Log exec times of each stage of the ui test (microsoft#6430)

* Add logging to see perf times of tests * Run all tests * Revert

Author: DonJayamanne

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.