Merge pull request #62 from alcides/contextmanager_time

ContextManager to record time

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,23 +40,41 @@ 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",
         "--debug",
         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)

aeon/logger/logger.py

@@ -7,6 +7,7 @@
 
 
 def levels_filter(levels):
+
     def filter(record):
         return record["level"].name in levels
 
@@ -18,14 +19,17 @@ def setup_logger():
     logger.level("SYNTH_TYPE", no=36, color="<magenta>")
     logger.level("CONSTRAINT", no=37, color="<cyan>")
     logger.level("SYNTHESIZER", no=38, color="<red>")
+    logger.level("TIME", no=39, color="<green>")
 
     # Setup the logger
     logger.remove()
     # logger.add(sys.stderr, level="DEBUG")
     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))

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")