Performance of V2 Pytest runner, showing that the requirements PEX causes ~75% of the performance cost.

contextutil_results.txt

./pants --no-v1 --v2 test tests/python/pants_test/util:contextutil

time elapsed for pex download: 0.01029515266418457
time elapsed for getting closure: 0.04847383499145508
time elapsed for requirements pex: 8.583088159561157
time elapsed for sources: 0.009785652160644531
time elapsed for __init__: 0.01706719398498535
time elapsed for merging files: 0.0031499862670898438
time elapsed for pytest: 2.261147975921631
total elapsed time: 10.933007955551147

strutil_results.txt

$ ./pants --no-v1 --v2 test tests/python/pants_test/util:strutil

time elapsed for pex download: 0.014779329299926758
time elapsed for getting closure: 0.03091573715209961
time elapsed for requirements pex: 7.257895231246948
time elapsed for sources: 0.007035732269287109
time elapsed for __init__: 0.01335000991821289
time elapsed for merging files: 0.004971027374267578
time elapsed for pytest: 1.993941068649292
total elapsed time: 9.322888135910034

timing.diff

diff --git a/src/python/pants/backend/python/rules/python_test_runner.py b/src/python/pants/backend/python/rules/python_test_runner.py
index e043e22bc..3a2d9c300 100644
--- a/src/python/pants/backend/python/rules/python_test_runner.py
+++ b/src/python/pants/backend/python/rules/python_test_runner.py
@@ -6,6 +6,7 @@ from __future__ import absolute_import, division, print_function, unicode_litera
 
 import sys
 from builtins import str
+from time import time
 
 from future.utils import text_type
 
@@ -47,12 +48,16 @@ def parse_interpreter_constraints(python_setup, python_target_adaptors):
 @rule(TestResult, [PythonTestsAdaptor, PyTest, PythonSetup, SourceRootConfig, PexBuildEnvironment, SubprocessEncodingEnvironment])
 def run_python_test(test_target, pytest, python_setup, source_root_config, pex_build_environment, subprocess_encoding_environment):
   """Runs pytest for one target."""
+  time_start = time()
 
   # TODO: Inject versions and digests here through some option, rather than hard-coding it.
   url = 'https://github.com/pantsbuild/pex/releases/download/v1.6.6/pex'
   digest = Digest('61bb79384db0da8c844678440bd368bcbfac17bbdb865721ad3f9cb0ab29b629', 1826945)
   pex_snapshot = yield Get(Snapshot, UrlToFetch(url, digest))
 
+  time_after_pex_download = time()
+  print(f"time elapsed for pex download: {time_after_pex_download - time_start}")
+
   # TODO(7726): replace this with a proper API to get the `closure` for a
   # TransitiveHydratedTarget.
   transitive_hydrated_targets = yield Get(
@@ -60,6 +65,9 @@ def run_python_test(test_target, pytest, python_setup, source_root_config, pex_b
   )
   all_targets = [t.adaptor for t in transitive_hydrated_targets.closure]
 
+  time_after_closure = time()
+  print(f"time elapsed for getting closure: {time_after_closure - time_after_pex_download}")
+
   # Produce a pex containing pytest and all transitive 3rdparty requirements.
   all_target_requirements = []
   for maybe_python_req_lib in all_targets:
@@ -106,6 +114,9 @@ def run_python_test(test_target, pytest, python_setup, source_root_config, pex_b
   requirements_pex_response = yield Get(
     ExecuteProcessResult, ExecuteProcessRequest, requirements_pex_request)
 
+  time_after_requirements_pex = time()
+  print(f"time elapsed for requirements pex: {time_after_requirements_pex - time_after_closure}")
+
   source_roots = source_root_config.get_source_roots()
 
   # Gather sources and adjust for the source root.
@@ -134,8 +145,14 @@ def run_python_test(test_target, pytest, python_setup, source_root_config, pex_b
     Digest, DirectoriesToMerge(directories=tuple(all_sources_digests)),
   )
 
+  time_after_sources = time()
+  print(f"time elapsed for sources: {time_after_sources - time_after_requirements_pex}")
+
   inits_digest = yield Get(InjectedInitDigest, Digest, sources_digest)
 
+  time_after_init = time()
+  print(f"time elapsed for __init__: {time_after_init - time_after_sources}")
+
   all_input_digests = [
     sources_digest,
     inits_digest.directory_digest,
@@ -147,6 +164,9 @@ def run_python_test(test_target, pytest, python_setup, source_root_config, pex_b
     DirectoriesToMerge(directories=tuple(all_input_digests)),
   )
 
+  time_after_merge = time()
+  print(f"time elapsed for merging files: {time_after_merge - time_after_init}")
+
   pex_exe_env = {'PATH': interpreter_search_paths}
   # TODO(#6071): merge the two dicts via ** unpacking once we drop Py2.
   pex_exe_env.update(subprocess_encoding_environment.invocation_environment_dict)
@@ -161,6 +181,11 @@ def run_python_test(test_target, pytest, python_setup, source_root_config, pex_b
   result = yield Get(FallibleExecuteProcessResult, ExecuteProcessRequest, request)
   status = Status.SUCCESS if result.exit_code == 0 else Status.FAILURE
 
+  time_after_pytest = time()
+  print(f"time elapsed for pytest: {time_after_pytest - time_after_merge}")
+
+  print(f"total elapsed time: {time_after_pytest - time_start}")
+
   yield TestResult(
     status=status,
     stdout=result.stdout.decode('utf-8'),