Merge pull request #2571 from ralexstokes/add-timing-info-to-test-gen

add timing information to spec test generation

tests/core/pyspec/eth2spec/gen_helpers/gen_base/gen_runner.py

@@ -1,4 +1,5 @@
 import os
+import time
 import shutil
 import argparse
 from pathlib import Path
@@ -22,6 +23,9 @@ from .gen_typing import TestProvider
 context.is_pytest = False
 
 
+TIME_THRESHOLD_TO_PRINT = 1.0  # seconds
+
+
 def validate_output_dir(path_str):
     path = Path(path_str)
 
@@ -98,6 +102,7 @@ def run_generator(generator_name, test_providers: Iterable[TestProvider]):
 
     generated_test_count = 0
     skipped_test_count = 0
+    provider_start = time.time()
     for tprov in test_providers:
         # runs anything that we don't want to repeat for every test case.
         tprov.prepare()
@@ -122,6 +127,7 @@ def run_generator(generator_name, test_providers: Iterable[TestProvider]):
                     shutil.rmtree(case_dir)
 
             print(f'Generating test: {case_dir}')
+            test_start = time.time()
 
             written_part = False
 
@@ -179,9 +185,18 @@ def run_generator(generator_name, test_providers: Iterable[TestProvider]):
                     generated_test_count += 1
                     # Only remove `INCOMPLETE` tag file
                     os.remove(incomplete_tag_file)
+            test_end = time.time()
+            span = round(test_end - test_start, 2)
+            if span > TIME_THRESHOLD_TO_PRINT:
+                print(f'    - generated in {span} seconds')
+
+    provider_end = time.time()
+    span = round(provider_end - provider_start, 2)
 
     summary_message = f"completed generation of {generator_name} with {generated_test_count} tests"
     summary_message += f" ({skipped_test_count} skipped tests)"
+    if span > TIME_THRESHOLD_TO_PRINT:
+        summary_message += f" in {span} seconds"
     print(summary_message)