From f97de5c5e80364271ccda8978e42ffb3de98a589 Mon Sep 17 00:00:00 2001 From: Alcides Fonseca Date: Wed, 3 Apr 2024 18:30:45 +0100 Subject: [PATCH] Added timing logs and flag --- aeon/__main__.py | 147 +++++++++++++++++++++------------------ aeon/logger/logger.py | 6 +- aeon/utils/time_utils.py | 22 +++++- 3 files changed, 104 insertions(+), 71 deletions(-) diff --git a/aeon/__main__.py b/aeon/__main__.py index a8e4e86c..83e322d2 100644 --- a/aeon/__main__.py +++ b/aeon/__main__.py @@ -1,7 +1,6 @@ from __future__ import annotations import sys -import time import argparse @@ -22,6 +21,7 @@ from aeon.synthesis_grammar.synthesizer import synthesize, parse_config from aeon.typechecking.typeinfer import check_type_errors from aeon.utils.ctx_helpers import build_context +from aeon.utils.time_utils import RecordTime def parse_arguments(): @@ -40,16 +40,27 @@ def parse_arguments(): "--log", nargs="+", default="", - help="""set log level: \nTRACE \nDEBUG \nINFO \nWARNINGS \nTYPECHECKER \nSYNTH_TYPE \nCONSTRAINT \nSYNTHESIZER - \nERROR \nCRITICAL""", + help= + """set log level: \nTRACE \nDEBUG \nINFO \nWARNINGS \nTYPECHECKER \nSYNTH_TYPE \nCONSTRAINT \nSYNTHESIZER + \nERROR \nCRITICAL\n TIME""", ) - parser.add_argument("-f", "--logfile", action="store_true", help="export log file") + parser.add_argument("-f", + "--logfile", + action="store_true", + help="export log file") - parser.add_argument("-csv", "--csv-synth", action="store_true", help="export synthesis csv file") + parser.add_argument("-csv", + "--csv-synth", + action="store_true", + help="export synthesis csv file") - parser.add_argument("-gp", "--gp-config", help="path to the GP configuration file") + parser.add_argument("-gp", + "--gp-config", + help="path to the GP configuration file") - parser.add_argument("-csec", "--config-section", help="section name in the GP configuration file") + parser.add_argument("-csec", + "--config-section", + help="section name in the GP configuration file") parser.add_argument( "-d", @@ -57,6 +68,13 @@ def parse_arguments(): action="store_true", help="Show debug information", ) + + parser.add_argument( + "-t", + "--timings", + action="store_true", + help="Show timing information", + ) return parser.parse_args() @@ -66,12 +84,12 @@ def read_file(filename: str) -> str: def log_type_errors(errors: list[Exception | str]): - logger.log("TYPECHECKER", "-------------------------------") - logger.log("TYPECHECKER", "+ Type Checking Error +") + print("TYPECHECKER", "-------------------------------") + print("TYPECHECKER", "+ Type Checking Error +") for error in errors: - logger.log("TYPECHECKER", "-------------------------------") - logger.log("TYPECHECKER", error) - logger.log("TYPECHECKER", "-------------------------------") + print("TYPECHECKER", "-------------------------------") + print("TYPECHECKER", error) + print("TYPECHECKER", "-------------------------------") if __name__ == "__main__": @@ -80,71 +98,66 @@ def log_type_errors(errors: list[Exception | str]): export_log(args.log, args.logfile, args.filename) if args.debug: logger.add(sys.stderr) + if args.timings: + logger.add(sys.stderr, level="TIME") aeon_code = read_file(args.filename) if args.core: - typing_ctx = build_context(typing_vars) - evaluation_ctx = EvaluationContext(evaluation_vars) - core_ast = parse_term(aeon_code) - metadata: Metadata = {} + with RecordTime("ParseCore"): + typing_ctx = build_context(typing_vars) + evaluation_ctx = EvaluationContext(evaluation_vars) + core_ast = parse_term(aeon_code) + metadata: Metadata = {} else: - start = time.time() - prog: Program = parse_program(aeon_code) - end = time.time() - logger.info(f"Parsing time: {end - start}") - start = time.time() - ( - core_ast, - typing_ctx, - evaluation_ctx, - metadata, - ) = desugar(prog) - end = time.time() - logger.info(f"Desugaring time: {end - start} seconds") - logger.info(core_ast) - start = time.time() - core_ast_anf = ensure_anf(core_ast) - print(core_ast_anf) - end = time.time() - logger.info(f"ANF conversion time: {end - start} seconds") - - start = time.time() - type_errors = check_type_errors(typing_ctx, core_ast_anf, top) - end = time.time() - logger.info(f"Type checking time: {end - start} seconds") + with RecordTime("ParseSugar"): + prog: Program = parse_program(aeon_code) + + with RecordTime("DeSugar"): + ( + core_ast, + typing_ctx, + evaluation_ctx, + metadata, + ) = desugar(prog) + + logger.debug(core_ast) + + with RecordTime("ANF conversion"): + core_ast_anf = ensure_anf(core_ast) + logger.debug(core_ast) + + with RecordTime("TypeChecking"): + type_errors = check_type_errors(typing_ctx, core_ast_anf, top) if type_errors: log_type_errors(type_errors) sys.exit(1) - start = time.time() - incomplete_functions: list[tuple[str, list[str]]] = incomplete_functions_and_holes(typing_ctx, core_ast_anf) - end = time.time() - logger.info(f"Incomplete Functions identification time: {end - start} seconds") + with RecordTime("DetectSynthesis"): + incomplete_functions: list[tuple[ + str, list[str]]] = incomplete_functions_and_holes( + typing_ctx, core_ast_anf) if incomplete_functions: filename = args.filename if args.csv_synth else None - start = time.time() - synth_config = ( - parse_config(args.gp_config, args.config_section) if args.gp_config and args.config_section else None - ) - end = time.time() - logger.info(f"Config parsing time: {end - start} seconds") - - synthesis_result = synthesize( - typing_ctx, - evaluation_ctx, - core_ast_anf, - incomplete_functions, - metadata, - filename, - synth_config, - ) - print(f"Best solution:{synthesis_result}") - # print() - # pretty_print_term(ensure_anf(synthesis_result, 200)) + with RecordTime("ParseConfig"): + synth_config = (parse_config(args.gp_config, args.config_section) + if args.gp_config and args.config_section else + None) + + with RecordTime("Synthesis"): + synthesis_result = synthesize( + typing_ctx, + evaluation_ctx, + core_ast_anf, + incomplete_functions, + metadata, + filename, + synth_config, + ) + print(f"{synthesis_result}") + # print() + # pretty_print_term(ensure_anf(synthesis_result, 200)) sys.exit(1) - start = time.time() - eval(core_ast, evaluation_ctx) - end = time.time() - logger.info(f"Evaluation time: {end - start} seconds") + with RecordTime("Evaluation"): + eval(core_ast, evaluation_ctx) diff --git a/aeon/logger/logger.py b/aeon/logger/logger.py index 65c9a2d7..497c225c 100644 --- a/aeon/logger/logger.py +++ b/aeon/logger/logger.py @@ -7,6 +7,7 @@ def levels_filter(levels): + def filter(record): return record["level"].name in levels @@ -18,6 +19,7 @@ def setup_logger(): logger.level("SYNTH_TYPE", no=36, color="") logger.level("CONSTRAINT", no=37, color="") logger.level("SYNTHESIZER", no=38, color="") + logger.level("TIME", no=39, color="") # Setup the logger logger.remove() @@ -25,7 +27,9 @@ def setup_logger(): return logger -def export_log(logs: list, export_file: bool = False, logfile_name: str | None = None): +def export_log(logs: list, + export_file: bool = False, + logfile_name: str | None = None): if export_file: logfile = f"logs/{logfile_name}_{datetime.datetime.now()}.log" return logger.add(logfile, filter=levels_filter(logs)) diff --git a/aeon/utils/time_utils.py b/aeon/utils/time_utils.py index 3f3236be..05b718a3 100644 --- a/aeon/utils/time_utils.py +++ b/aeon/utils/time_utils.py @@ -2,9 +2,13 @@ from functools import wraps from time import process_time +from time import perf_counter + +from loguru import logger def measure(func): + @wraps(func) def _time_it(*args, **kwargs): start = int(round(process_time() * 1000)) @@ -14,8 +18,20 @@ def _time_it(*args, **kwargs): end_ = int(round(process_time() * 1000)) - start if end_ > 1: end_s = end_ if end_ > 0 else 0 - print( - f"Total execution time {func.__name__}: {end_s} ms", - ) + print(f"Total execution time {func.__name__}: {end_s} ms", ) return _time_it + + +class RecordTime: + + def __init__(self, name: str): + self.name = name + + def __enter__(self): + self.start = perf_counter() + return self + + def __exit__(self, type, value, traceback): + self.time = perf_counter() - self.start + logger.log("TIME", f"[{self.name}] Time: {self.time:.3f} seconds")