diff --git a/src/azure-cli/azure/cli/__main__.py b/src/azure-cli/azure/cli/__main__.py index e6e6b34a2f4..1558a8266e9 100644 --- a/src/azure-cli/azure/cli/__main__.py +++ b/src/azure-cli/azure/cli/__main__.py @@ -4,16 +4,17 @@ # -------------------------------------------------------------------------------------------- import sys -import uuid import timeit +import uuid +import azure.cli.core.telemetry as telemetry +from azure.cli.core import get_default_cli from knack.completion import ARGCOMPLETE_ENV_NAME from knack.log import get_logger -from azure.cli.core import get_default_cli - -import azure.cli.core.telemetry as telemetry - +# Log the start time +# TODO: Disable E402 "Module level import not at top of file" so that imports can also be timed +start_time = timeit.default_timer() # A workaround for https://bugs.python.org/issue32502 (https://github.com/Azure/azure-cli/issues/5184) # If uuid1 raises ValueError, use uuid4 instead. @@ -34,9 +35,11 @@ def cli_main(cli, args): telemetry.set_application(az_cli, ARGCOMPLETE_ENV_NAME) +# Log the init finish time +init_finish_time = timeit.default_timer() + try: telemetry.start() - start_time = timeit.default_timer() exit_code = cli_main(az_cli, sys.argv[1:]) @@ -47,8 +50,6 @@ def cli_main(cli, args): else: telemetry.set_success() - elapsed_time = timeit.default_timer() - start_time - sys.exit(exit_code) except KeyboardInterrupt: @@ -56,18 +57,17 @@ def cli_main(cli, args): sys.exit(1) except SystemExit as ex: # some code directly call sys.exit, this is to make sure command metadata is logged exit_code = ex.code if ex.code is not None else 1 - - try: - elapsed_time = timeit.default_timer() - start_time - except NameError: - pass - raise ex finally: telemetry.conclude() try: - logger.info("command ran in %.3f seconds.", elapsed_time) + # Log the invoke finish time + invoke_finish_time = timeit.default_timer() + logger.info("Command ran in %.3f seconds (init: %.3f, invoke: %.3f)", + invoke_finish_time - start_time, + init_finish_time - start_time, + invoke_finish_time - init_finish_time) except NameError: pass