[v2] Add more granular metrics to benchmarking framework: plugin-load time, static imports time, client creation time.

awscli/botocore/session.py

@@ -866,6 +866,7 @@ def create_client(
         :return: A botocore client instance
 
         """
+        self.emit('before-create-client')
         default_client_config = self.get_default_client_config()
         # If a config is provided and a default config is set, then
         # use the config resulting from merging the two.
@@ -960,6 +961,7 @@ def create_client(
         monitor = self._get_internal_component('monitor')
         if monitor is not None:
             monitor.register(client.meta.events)
+        self.emit('after-create-client')
         return client
 
     def _resolve_region_name(self, region_name, config):

awscli/clidriver.py

@@ -111,13 +111,13 @@ def main():
         return AWSCLIEntryPoint().main(sys.argv[1:])
 
 
-def create_clidriver(args=None):
+def create_clidriver(args=None, event_hooks=None):
     debug = None
     if args is not None:
         parser = FirstPassGlobalArgParser()
         args, _ = parser.parse_known_args(args)
         debug = args.debug
-    session = botocore.session.Session()
+    session = botocore.session.Session(event_hooks=event_hooks)
     _set_user_agent_for_session(session)
     load_plugins(
         session.full_config.get('plugins', {}),

awscli/plugin.py

@@ -45,7 +45,9 @@ def load_plugins(plugin_mapping, event_hooks=None, include_builtins=True):
     if event_hooks is None:
         event_hooks = HierarchicalEmitter()
     if include_builtins:
+        event_hooks.emit('before-load-plugins')
         _load_plugins(BUILTIN_PLUGINS, event_hooks)
+        event_hooks.emit('after-load-plugins')
     plugin_path = plugin_mapping.pop(CLI_LEGACY_PLUGIN_PATH, None)
     if plugin_path is not None:
         _add_plugin_path_to_sys_path(plugin_path)

scripts/performance/benchmark_utils.py

@@ -7,7 +7,6 @@
 
 import psutil
 
-from awscli.clidriver import AWSCLIEntryPoint, create_clidriver
 from scripts.performance import BaseBenchmarkSuite
 from scripts.performance.simple_stubbed_tests import (
     JSONStubbedBenchmarkSuite,
@@ -169,6 +168,21 @@ def _finalize_processed_data_for_file(self, samples, worker_results):
                 worker_results['first_client_invocation_time']
                 - worker_results['start_time'],
             ),
+            'plugins.load.time': Metric(
+                'Total time spent loading all built-in plugins.',
+                'Seconds',
+                worker_results['load_plugins_time'],
+            ),
+            'imports.static.time': Metric(
+                'Total time spent on static Python imports.',
+                'Seconds',
+                worker_results['static_imports_time'],
+            ),
+            'client.creation.time': Metric(
+                'Total time spent creating a botocore client.',
+                'Seconds',
+                worker_results['create-client-time'],
+            ),
         }
         # reset data state
         self._samples.clear()
@@ -264,21 +278,72 @@ def _run_command_with_metric_hooks(self, cmd, out_file):
         Runs a CLI command and logs CLI-specific metrics to a file.
         """
         first_client_invocation_time = None
+        create_client_start_time = None
+        create_client_end_time = None
+        plugin_import_start_time = None
+        plugin_import_end_time = None
         start_time = time.time()
-        driver = create_clidriver()
-        event_emitter = driver.session.get_component('event_emitter')
+
+        before_imports = start_time
+        # We import from awscli lazily to ensure import time is measured in
+        # total runtime.
+        from awscli.botocore.hooks import HierarchicalEmitter
+        from awscli.clidriver import AWSCLIEntryPoint, create_clidriver
+        after_imports = time.time()
 
         def _log_invocation_time(params, request_signer, model, **kwargs):
             nonlocal first_client_invocation_time
             if first_client_invocation_time is None:
                 first_client_invocation_time = time.time()
 
-        event_emitter.register_last(
+        def _log_create_client_start(**kwargs):
+            nonlocal create_client_start_time
+            if create_client_start_time is None:
+                create_client_start_time = time.time()
+
+        def _log_create_client_end(**kwargs):
+            nonlocal create_client_end_time
+            if create_client_end_time is None:
+                create_client_end_time = time.time()
+
+        def _log_import_plugins_start(**kwargs):
+            nonlocal plugin_import_start_time
+            if plugin_import_start_time is None:
+                plugin_import_start_time = time.time()
+
+        def _log_import_plugins_end(**kwargs):
+            nonlocal plugin_import_end_time
+            if plugin_import_end_time is None:
+                plugin_import_end_time = time.time()
+
+        event_hooks = HierarchicalEmitter()
+        event_hooks.register_last(
             'before-call',
             _log_invocation_time,
             'benchmarks.log-invocation-time',
         )
+        event_hooks.register_last(
+            'before-create-client',
+            _log_create_client_start,
+            'benchmarks.log-before-create-client',
+        )
+        event_hooks.register_last(
+            'after-create-client',
+            _log_create_client_end,
+            'benchmarks.log-after-create-client',
+        )
+        event_hooks.register_last(
+            'before-load-plugins',
+            _log_import_plugins_start,
+            'benchmarks.log-before-load-plugins',
+        )
+        event_hooks.register_last(
+            'after-load-plugins',
+            _log_import_plugins_end,
+            'benchmarks.log-after-load-plugins',
+        )
 
+        driver = create_clidriver(event_hooks=event_hooks)
         rc = AWSCLIEntryPoint(driver).main(cmd)
         end_time = time.time()
 
@@ -291,6 +356,15 @@ def _log_invocation_time(params, request_signer, model, **kwargs):
                         'start_time': start_time,
                         'end_time': end_time,
                         'first_client_invocation_time': first_client_invocation_time,
+                        'load_plugins_time': (
+                            plugin_import_end_time - plugin_import_start_time
+                        ),
+                        'static_imports_time': (
+                            after_imports - before_imports
+                        ),
+                        'create-client-time': (
+                            create_client_end_time - create_client_start_time
+                        )
                     }
                 )
             )
@@ -333,20 +407,16 @@ def _run_isolated_benchmark(
                         os.dup2(err.fileno(), sys.stderr.fileno())
                     else:
                         with open(
-                            os.path.abspath(
-                                os.path.join(
-                                    args.debug_dir,
-                                    f'{benchmark["name"]}-{iteration}.txt',
-                                )
+                            os.path.join(
+                                args.debug_dir,
+                                f'{benchmark["name"]}-{iteration}.txt',
                             ),
                             'w',
                         ) as f:
                             with open(
-                                os.path.abspath(
-                                    os.path.join(
-                                        args.debug_dir,
-                                        f'{benchmark["name"]}-{iteration}-err.txt',
-                                    )
+                                os.path.join(
+                                    args.debug_dir,
+                                    f'{benchmark["name"]}-{iteration}-err.txt',
                                 ),
                                 'w',
                             ) as f_err: