Azure CLI is slow to start on first instantiation #31541
Description
Describe the bug
It looks like when the Azure CLI starts for the first time on Linux based Github Actions runners (could be the case elsewhere too?). It loads all command modules by default, which can take considerable time on a system that hasn't done it before.
While this is only on the version command, this impacts other commands such as az login, and az acr login which can substantially slow down CI pipelines in Github Actions (and other CI platforms likely too?).
Is it possible to make the Discovered command modules: / Loading command modules: logic either just-in-time and/or configurable which modules to load, as a means of speeding up startup?
I can see references to BLOCKED_MODS in the source code already, but that's a hardcoded list at the moment.
Curious, is this Loading command modules: done into RAM or cached to disk? If its cached to disk, this might be solveable using https://github.com/actions/cache to cache the loaded state and restore it...
Related command
az version --debug (same duration outcomes without --debug, it just hangs for a while before outputting)
Errors
First run, commands executed:
date
az version --debug
date
This allows seeing the elapsed time between start and end clearly.
Output:
Thu May 22 20:36:56 UTC 2025
DEBUG: cli.knack.cli: Command arguments: ['version', '--debug']
DEBUG: cli.knack.cli: __init__ debug log:
Cannot enable color.
DEBUG: cli.knack.cli: Event: Cli.PreExecute []
DEBUG: cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x[7](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:8)fc7f169f7e0>, <function OutputProducer.on_global_arguments at 0x7fc7f13f67a0>, <function CLIQuery.on_global_arguments at 0x7fc7f143bce0>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
DEBUG: cli.azure.cli.core: Command index version or cloud profile is invalid or doesn't match the current command.
DEBUG: cli.azure.cli.core: Command index has been invalidated.
DEBUG: cli.azure.cli.core: No module found from index for '['version', '--debug']'
DEBUG: cli.azure.cli.core: Loading all modules and extensions
DEBUG: cli.azure.cli.core: Discovered command modules: ['acr', 'acs', 'advisor', 'ams', 'apim', 'appconfig', 'appservice', 'aro', 'backup', 'batch', 'batchai', 'billing', 'botservice', 'cdn', 'cloud', 'cognitiveservices', 'compute_recommender', 'computefleet', 'config', 'configure', 'consumption', 'container', 'containerapp', 'cosmosdb', 'databoxedge', 'dls', 'dms', 'eventgrid', 'eventhubs', 'extension', 'feedback', 'find', 'hdinsight', 'identity', 'interactive', 'iot', 'keyvault', 'lab', 'managedservices', 'maps', 'marketplaceordering', 'monitor', 'mysql', 'netappfiles', 'network', 'policyinsights', 'privatedns', 'profile', 'rdbms', 'redis', 'relay', 'resource', 'role', 'search', 'security', 'servicebus', 'serviceconnector', 'servicefabric', 'signalr', 'sql', 'sqlvm', 'storage', 'synapse', 'util', 'vm']
DEBUG: cli.azure.cli.core: Loading command modules:
DEBUG: cli.azure.cli.core: Name Load Time Groups Commands
DEBUG: cli.azure.cli.core: acr 1.009 36 149
DEBUG: cli.azure.cli.core: acs 0.341 15 79
DEBUG: cli.azure.cli.core: advisor 0.026 3 6
DEBUG: cli.azure.cli.core: ams 0.034 22 100
DEBUG: cli.azure.cli.core: apim 0.055 14 69
DEBUG: cli.azure.cli.core: appconfig 0.041 9 47
DEBUG: cli.azure.cli.core: appservice 0.540 [8](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:9)0 277
DEBUG: cli.azure.cli.core: aro 0.15[9](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:10) 1 10
DEBUG: cli.azure.cli.core: backup 0.028 16 60
DEBUG: cli.azure.cli.core: batch 0.295 32 96
DEBUG: cli.azure.cli.core: batchai 0.027 [10](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:11) 30
DEBUG: cli.azure.cli.core: billing 0.182 20 53
DEBUG: cli.azure.cli.core: botservice 0.058 12 42
DEBUG: cli.azure.cli.core: cdn 1.557 8 50
DEBUG: cli.azure.cli.core: cloud 0.028 1 7
DEBUG: cli.azure.cli.core: cognitiveservices 0.018 10 33
DEBUG: cli.azure.cli.core: compute_recommender 0.028 1 1
DEBUG: cli.azure.cli.core: computefleet 0.103 1 1
DEBUG: cli.azure.cli.core: config 0.063 2 7
DEBUG: cli.azure.cli.core: configure 0.034 2 5
DEBUG: cli.azure.cli.core: consumption 0.340 8 9
DEBUG: cli.azure.cli.core: container 0.[11](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:12)8 2 17
DEBUG: cli.azure.cli.core: containerapp 1.594 37 123
DEBUG: cli.azure.cli.core: cosmosdb 0.081 58 200
DEBUG: cli.azure.cli.core: databoxedge 0.104 5 28
DEBUG: cli.azure.cli.core: dls 0.016 6 36
DEBUG: cli.azure.cli.core: dms 0.015 3 22
DEBUG: cli.azure.cli.core: eventgrid 0.049 25 96
DEBUG: cli.azure.cli.core: eventhubs 0.216 13 20
DEBUG: cli.azure.cli.core: extension 0.014 1 7
DEBUG: cli.azure.cli.core: feedback 0.001 1 2
DEBUG: cli.azure.cli.core: find 0.015 1 1
DEBUG: cli.azure.cli.core: hdinsight 0.085 9 42
DEBUG: cli.azure.cli.core: identity 0.015 2 11
DEBUG: cli.azure.cli.core: interactive 0.015 1 1
DEBUG: cli.azure.cli.core: iot 1.496 19 82
DEBUG: cli.azure.cli.core: keyvault 0.058 20 113
DEBUG: cli.azure.cli.core: lab 0.490 9 30
DEBUG: cli.azure.cli.core: managedservices 0.074 3 8
DEBUG: cli.azure.cli.core: maps 0.026 5 13
DEBUG: cli.azure.cli.core: marketplaceordering 0.028 1 2
DEBUG: cli.azure.cli.core: monitor 7.248 18 61
DEBUG: cli.azure.cli.core: mysql 0.978 16 56
DEBUG: cli.azure.cli.core: netappfiles 0.448 8 17
DEBUG: cli.azure.cli.core: network 1.846 104 345
DEBUG: cli.azure.cli.core: policyinsights 0.[12](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:13)5 9 17
DEBUG: cli.azure.cli.core: privatedns 0.156 14 60
DEBUG: cli.azure.cli.core: profile 0.014 2 8
DEBUG: cli.azure.cli.core: rdbms 0.943 53 223
DEBUG: cli.azure.cli.core: redis 0.048 7 38
DEBUG: cli.azure.cli.core: relay 0.545 7 8
DEBUG: cli.azure.cli.core: resource 0.103 52 232
DEBUG: cli.azure.cli.core: role 0.015 17 62
DEBUG: cli.azure.cli.core: search 0.060 7 19
DEBUG: cli.azure.cli.core: security 0.[13](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:14)9 47 98
DEBUG: cli.azure.cli.core: servicebus 0.200 13 17
DEBUG: cli.azure.cli.core: serviceconnector 0.178 20 323
DEBUG: cli.azure.cli.core: servicefabric 0.155 27 80
DEBUG: cli.azure.cli.core: signalr 0.015 10 42
DEBUG: cli.azure.cli.core: sql 0.121 56 215
DEBUG: cli.azure.cli.core: sqlvm 0.430 4 20
DEBUG: cli.azure.cli.core: storage 0.255 60 275
DEBUG: cli.azure.cli.core: synapse 0.097 54 246
DEBUG: cli.azure.cli.core: util 0.0[14](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:15) 3 7
DEBUG: cli.azure.cli.core: vm 1.631 59 217
DEBUG: cli.azure.cli.core: Total (65) 25.238 1191 4671
DEBUG: cli.azure.cli.core: Loading extensions:
DEBUG: cli.azure.cli.core: Name Load Time Groups Commands Directory
DEBUG: cli.azure.cli.core: azure-devops 0.667 60 192 /opt/az/azcliextensions/azure-devops
DEBUG: cli.azure.cli.core: Total (1) 0.667 60 192
DEBUG: cli.azure.cli.core: Loaded 1237 groups, 4863 commands.
DEBUG: cli.azure.cli.core: Updated command index in 0.003 seconds.
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7fc7f05a0360>]
DEBUG: cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to '/home/runner/.azure/commands/2025-05-22.20-37-29.version.2021.log'.
INFO: az_command_data_logger: command args: version --debug
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>.add_subscription_parameter at 0x7fc7f01a39c0>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_arguments at 0x7fc7f01a3a60>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x7fc7f01a3ba0>, <function register_upcoming_breaking_change_info.<locals>.update_breaking_change_info at 0x7fc7f01a3c40>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreParseArgs [<function _documentdb_deprecate at 0x7fc7eea22660>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x7fc7f13f6840>, <function CLIQuery.handle_query_parameter at 0x7fc7f143bd80>, <function register_ids_argument.<locals>.parse_ids_arguments at 0x7fc7f01a3b00>, <function DevCommandsLoader.post_parse_args at 0x7fc7ea5771a0>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnTransformResult [<function _resource_group_transform at 0x7fc7f05f85e0>, <function _x509_from_base64_to_hex_transform at 0x7fc7f05f8680>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnFilterResult []
DEBUG: cli.knack.cli: Event: Cli.SuccessfulExecute []
DEBUG: cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x7fc7f05a05e0>]
INFO: az_command_data_logger: exit code: 0
INFO: cli.__main__: Command ran in 31.046 seconds (init: 4.449, invoke: 26.597)
DEBUG: cli.azure.cli.core._profile: Failed to load installationId from AzureRmSurvey.json. [Errno 2] No such file or directory: '/home/runner/.azure/AzureRmContextSettings.json'
INFO: telemetry.main: Begin splitting cli events and extra events, total events: 1
INFO: telemetry.client: Accumulated 0 events. Flush the clients.
INFO: telemetry.main: Finish splitting cli events and extra events, cli events: 1
INFO: telemetry.save: Save telemetry record of length 3674 in cache file under /home/runner/.azure/telemetry/[20](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:21)250522203729357
INFO: telemetry.main: Begin creating telemetry upload process.
INFO: telemetry.process: Creating upload process: "/opt/az/bin/python3 /opt/az/lib/python3.12/site-packages/azure/cli/telemetry/__init__.py /home/runner/.azure /home/runner/.azure/telemetry/202505[22](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:2:23)203729357"
INFO: telemetry.process: Return from creating process 2052
INFO: telemetry.main: Finish creating telemetry upload process.
{
"azure-cli": "2.72.0",
"azure-cli-core": "2.72.0",
"azure-cli-telemetry": "1.1.0",
"extensions": {
"azure-devops": "1.0.1"
}
}
Thu May 22 20:37:29 UTC
Second execution, second step in the same job (so same Github Actions runner VM under the hood):
Thu May 22 20:37:29 UTC 2025
DEBUG: cli.knack.cli: Command arguments: ['version', '--debug']
DEBUG: cli.knack.cli: __init__ debug log:
Cannot enable color.
DEBUG: cli.knack.cli: Event: Cli.PreExecute []
DEBUG: cli.knack.cli: Event: CommandParser.OnGlobalArgumentsCreate [<function CLILogging.on_global_arguments at 0x[7](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:3:8)f59321db7e0>, <function OutputProducer.on_global_arguments at 0x7f5931f367a0>, <function CLIQuery.on_global_arguments at 0x7f5931f7bce0>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableCreate []
DEBUG: cli.azure.cli.core: Modules found from index for 'version': ['azure.cli.command_modules.util']
DEBUG: cli.azure.cli.core: Loading command modules:
DEBUG: cli.azure.cli.core: Name Load Time Groups Commands
DEBUG: cli.azure.cli.core: util 0.002 3 7
DEBUG: cli.azure.cli.core: Total (1) 0.002 3 7
DEBUG: cli.azure.cli.core: These extensions are not installed and will be skipped: ['azext_ai_examples', 'azext_next']
DEBUG: cli.azure.cli.core: Loading extensions:
DEBUG: cli.azure.cli.core: Name Load Time Groups Commands Directory
DEBUG: cli.azure.cli.core: Total (0) 0.000 0 0
DEBUG: cli.azure.cli.core: Loaded 3 groups, 7 commands.
DEBUG: cli.azure.cli.core: Found a match in the command table.
DEBUG: cli.azure.cli.core: Raw command : version
DEBUG: cli.azure.cli.core: Command table: version
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreCommandTableTruncate [<function AzCliLogging.init_command_file_logging at 0x7f59310f[8](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:3:9)360>]
DEBUG: cli.azure.cli.core.azlogging: metadata file logging enabled - writing logs to '/home/runner/.azure/commands/2025-05-22.20-37-2[9](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:3:10).version.2059.log'.
INFO: az_command_data_logger: command args: version --debug
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreArgumentLoad [<function register_global_subscription_argument.<locals>.add_subscription_parameter at 0x7f5931150860>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostArgumentLoad []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostCommandTableCreate [<function register_ids_argument.<locals>.add_ids_arguments at 0x7f5931153060>, <function register_cache_arguments.<locals>.add_cache_arguments at 0x7f59311531a0>, <function register_upcoming_breaking_change_info.<locals>.update_breaking_change_info at 0x7f5931153240>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnCommandTableLoaded []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPreParseArgs []
DEBUG: cli.knack.cli: Event: CommandInvoker.OnPostParseArgs [<function OutputProducer.handle_output_argument at 0x7f5931f36840>, <function CLIQuery.handle_query_parameter at 0x7f5931f7bd80>, <function register_ids_argument.<locals>.parse_ids_arguments at 0x7f5931153[10](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:3:11)0>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnTransformResult [<function _resource_group_transform at 0x7f593[11](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:3:12)505e0>, <function _x509_from_base64_to_hex_transform at 0x7f5931150680>]
DEBUG: cli.knack.cli: Event: CommandInvoker.OnFilterResult []
DEBUG: cli.knack.cli: Event: Cli.SuccessfulExecute []
DEBUG: cli.knack.cli: Event: Cli.PostExecute [<function AzCliLogging.deinit_cmd_metadata_logging at 0x7f59310f85e0>]
INFO: az_command_data_logger: exit code: 0
INFO: cli.__main__: Command ran in 0.[12](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:3:13)9 seconds (init: 0.119, invoke: 0.011)
INFO: telemetry.main: Begin splitting cli events and extra events, total events: 1
INFO: telemetry.client: Accumulated 0 events. Flush the clients.
INFO: telemetry.main: Finish splitting cli events and extra events, cli events: 1
INFO: telemetry.save: Save telemetry record of length 3673 in cache file under /home/runner/.azure/telemetry/20250522203729898
INFO: telemetry.main: Begin creating telemetry upload process.
INFO: telemetry.process: Creating upload process: "/opt/az/bin/python3 /opt/az/lib/python3.12/site-packages/azure/cli/telemetry/__init__.py /home/runner/.azure /home/runner/.azure/telemetry/[20](https://github.com/REDACTED/test-actions-runner-vnet/actions/runs/REDACTED/job/REDACTED#step:3:21)250522203729898"
INFO: telemetry.process: Return from creating process 2077
INFO: telemetry.main: Finish creating telemetry upload process.
{
"azure-cli": "2.72.0",
"azure-cli-core": "2.72.0",
"azure-cli-telemetry": "1.1.0",
"extensions": {
"azure-devops": "1.0.1"
}
}
Thu May 22 20:37:29 UTC 2025
Issue script & Debug output
date
az version --debug
date
Expected behavior
For az to start in under a second the first time its executed on a fresh VM/system/CI runner, at least to be able to perform login and/or acr login operations.
Intensive system resource operations can take longer of course if they exist...
Environment Summary
Run az --version
WARNING: You have 2 update(s) available. Consider updating your CLI installation with 'az upgrade'
azure-cli 2.72.0 *
core 2.72.0 *
telemetry 1.1.0
Extensions:
azure-devops 1.0.1
Dependencies:
msal 1.32.3
azure-mgmt-resource 23.1.1
Python location '/opt/az/bin/python3'
Config directory '/home/runner/.azure'
Extensions directory '/opt/az/azcliextensions'
Python (Linux) 3.12.8 (main, Apr 28 2025, 09:24:33) [GCC 13.3.0]
Legal docs and information: aka.ms/AzureCliLegal
Additional context
NOTE: I'm using Hosted Compute Networking in Github Actions, which does mean there's less "warm" VMs spooled up by Github, so runners tend to be spun up cold more often, and that makes this problem more visible. Github does not provide any control over that warm pool size, but that's unrelated to the root cause here - trying to get az calls to run fast from a "cold" started VM.
A related issue Azure/login#527 which is what prompted me to raise this separately