Skip to content

{Misc} Fix timer for __main__.py #13844

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
jiasli merged 3 commits into from
Jun 8, 2020
Merged

{Misc} Fix timer for __main__.py #13844

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
458e85f
Fix timer
jiasli Jun 5, 2020
23d3ab5
Merge branch 'dev' into fix-timer
jiasli Jun 8, 2020
a3c2c90
Comply to E402
jiasli Jun 8, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
30 changes: 15 additions & 15 deletions src/azure-cli/azure/cli/__main__.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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:])

Expand All @@ -47,27 +50,24 @@ def cli_main(cli, args):
else:
telemetry.set_success()

elapsed_time = timeit.default_timer() - start_time

sys.exit(exit_code)

except KeyboardInterrupt:
telemetry.set_user_fault('keyboard interrupt')
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)",
Copy link
Member Author

@jiasli jiasli Jun 8, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not sure if this running time info should be moved to logger.debug. I am open to this.

invoke_finish_time - start_time,
init_finish_time - start_time,
invoke_finish_time - init_finish_time)
except NameError:
pass