Log exec times of each stage of the ui test

uitests/uitests/environment.py

@@ -51,7 +51,7 @@ def f_restore_context(*args, **kwargs):
 
     return deco_context
 
-
+@uitests.tools.trace
 @uitests.tools.retry((TimeoutError, WebDriverException), tries=5, delay=5)
 @uitests.tools.log_exceptions()
 def before_all(context):
@@ -61,10 +61,12 @@ def before_all(context):
     _start_and_clear(context, options)
 
 
+@uitests.tools.trace
 def after_all(context):
     _exit(context)
 
 
+@uitests.tools.trace
 def before_feature(context, feature):
     for scenario in feature.scenarios:
         # If we're working on a scenario, then don't retry.
@@ -86,6 +88,7 @@ def before_feature(context, feature):
             patch_scenario_with_autoretry(scenario, max_attempts=2)
 
 
+@uitests.tools.trace
 @uitests.tools.retry((PermissionError, FileNotFoundError), tries=2)
 @uitests.tools.log_exceptions()
 @restore_context()
@@ -141,6 +144,7 @@ def before_scenario(context, scenario):
     _dismiss_one_time_messages(context, retry_count=2)
 
 
+@uitests.tools.trace
 @uitests.tools.log_exceptions()
 @restore_context()
 def after_scenario(context, scenario):
@@ -195,12 +199,14 @@ def after_scenario(context, scenario):
     os.makedirs(context.options.logfiles_dir, exist_ok=True)
 
 
+@uitests.tools.trace
 @uitests.tools.log_exceptions()
 @restore_context()
 def before_step(context, step):
     logging.info("Before step")
 
 
+@uitests.tools.trace
 @uitests.tools.log_exceptions()
 @restore_context()
 def after_step(context, step):
@@ -253,12 +259,14 @@ def after_step(context, step):
             pass
 
 
+@uitests.tools.trace
 @restore_context()
 def _exit(context):
     uitests.vscode.application.exit(context)
     uitests.vscode.application.CONTEXT["driver"] = None
 
 
+@uitests.tools.trace
 def _start_and_clear(context, options):
     # Clear VS Code folders (do not let VSC save state).
     # During tests, this can be done as a step `When I load VSC for the first time`.
@@ -287,6 +295,7 @@ def _start_and_clear(context, options):
         raise
 
 
+@uitests.tools.trace
 def _dismiss_one_time_messages(context, retry_count=100, retry_interval=0.1):
     # Dismiss one time VSC messages.
     # Dismiss one time extension messages.

uitests/uitests/tools.py

@@ -83,6 +83,21 @@ def wrapper(*args, **kwargs):
     return deco_log_exceptions
 
 
+def trace(f):
+    """Decorator to just log before and after execution of a function."""
+    @wraps(f)
+    def wrapper(*args, **kwargs):
+        start_time = time.time()
+        try:
+            logging.info(f"Before {f.__name__}")
+            return f(*args, **kwargs)
+        finally:
+            elapsed_time = time.time() - start_time
+            elapsed_time = time.strftime("%H:%M:%S", time.gmtime(elapsed_time))
+            logging.info(f"After {f.__name__} ({elapsed_time})")
+    return wrapper
+
+
 def run_command(command, *, cwd=None, silent=False, progress_message=None, env=None):
     """Run the specified command in a subprocess shell with the following options:
     - Pipe output from subprocess into current console.