feat(test-logging,test-consume): add ms-precision lifecycle logging to consume enginex

packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/base.py

@@ -1,5 +1,7 @@
 """Common pytest fixtures for the Hive simulators."""
 
+import logging
+import time
 from pathlib import Path
 from typing import Dict, Generator, Literal
 
@@ -19,6 +21,8 @@
 from ..consume import FixturesSource
 from .helpers.rejected_blocks import BlockRejectionTracker
 
+logger = logging.getLogger(__name__)
+
 
 @pytest.fixture(scope="function")
 def eth_rpc(client: Client) -> Generator[EthRPC, None, None]:
@@ -87,7 +91,12 @@ def __getitem__(self, key: Path) -> Fixtures:
         """
         assert key.is_file(), f"Expected a file path, got '{key}'"
         if key not in self._fixtures:
+            start = time.perf_counter()
             self._fixtures[key] = Fixtures.model_validate_json(key.read_text())
+            logger.info(
+                f"⏱ phase=fixture_load file={key.name} "
+                f"ms={(time.perf_counter() - start) * 1000:.1f}"
+            )
         return self._fixtures[key]
 
 

packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/enginex/conftest.py

@@ -10,6 +10,7 @@
 import io
 import json
 import logging
+import time
 from typing import TYPE_CHECKING, Generator, cast
 
 import pytest
@@ -98,6 +99,53 @@ def sort_key(item: pytest.Item) -> tuple[int, str]:
     logger.info("Sorted tests by pre-alloc group (largest first)")
 
 
+class _GroupDispatchTracker:
+    """
+    Per-worker (per-process) tracker of the idle time between test protocols.
+
+    The gap between the end of one test's run protocol and the start of the
+    next test's protocol is time the xdist worker spends waiting for the
+    controller (dispatch latency) at group boundaries. Small gaps may
+    instead be ordinary inter-protocol overhead (e.g. report submission):
+    the gap only equals dispatch latency when the worker's local item
+    queue is empty.
+    """
+
+    last_group: str | None = None
+    last_protocol_end: float | None = None
+
+
+def _xdist_group_name(item: pytest.Item) -> str | None:
+    """Return the xdist_group marker name of an item, if any."""
+    for marker in item.iter_markers("xdist_group"):
+        if "name" in marker.kwargs:
+            return marker.kwargs["name"]
+    return None
+
+
+@pytest.hookimpl(hookwrapper=True, tryfirst=True)
+def pytest_runtest_protocol(
+    item: pytest.Item, nextitem: pytest.Item | None
+) -> Generator[None, None, None]:
+    """Log a group-start marker with dispatch idle time at group boundaries."""
+    del nextitem
+
+    group = _xdist_group_name(item)
+    if group is not None and group != _GroupDispatchTracker.last_group:
+        if _GroupDispatchTracker.last_protocol_end is not None:
+            idle_ms = (
+                time.perf_counter() - _GroupDispatchTracker.last_protocol_end
+            ) * 1000
+            logger.info(
+                f"⏱ phase=group_start group={group} idle_ms={idle_ms:.1f}"
+            )
+        else:
+            logger.info(f"⏱ phase=group_start group={group}")
+        _GroupDispatchTracker.last_group = group
+    yield
+    _GroupDispatchTracker.last_protocol_end = time.perf_counter()
+
+
 @pytest.fixture(scope="session", autouse=True)
 def _configure_client_manager(
     multi_test_client_manager: "MultiTestClientManager",
@@ -169,16 +217,22 @@ def client(
         logger.info(f"♻️  Reusing client for group {group_identifier}")
     else:
         # Start new client; calculate genesis
+        serialize_start = time.perf_counter()
         genesis_bytes = json.dumps(client_genesis).encode("utf-8")
         buffered_genesis = io.BufferedReader(
             cast(io.RawIOBase, io.BytesIO(genesis_bytes))
         )
+        logger.info(
+            f"⏱ phase=genesis_serialize group={group_identifier} "
+            f"ms={(time.perf_counter() - serialize_start) * 1000:.1f}"
+        )
 
         logger.info(
             f"🚀 Starting client ({client_type.name}) "
             f"for group {group_identifier}"
         )
 
+        start_requested = time.perf_counter()
         with total_timing_data.time("Start client"):
             resolved_client = multi_test_hive_test.start_client(
                 client_type=client_type,
@@ -192,6 +246,13 @@ def client(
             "information."
         )
 
+        # The hive start-client API only returns once the client answers
+        # its liveness check, so this duration spans container creation,
+        # client boot and the check-live wait.
+        logger.info(
+            f"⏱ phase=client_start group={group_identifier} "
+            f"ms={(time.perf_counter() - start_requested) * 1000:.1f}"
+        )
         logger.info(
             f"Client ({client_type.name}) ready for group {group_identifier}"
         )

packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/multi_test_client.py

@@ -1,6 +1,7 @@
 """Pytest fixtures for multi-test client architecture."""
 
 import logging
+import time
 from typing import Generator
 
 import pytest
@@ -89,7 +90,12 @@ def mark_test_completed(self, group_identifier: str, test_id: str) -> None:
                     logger.info(
                         f"🛑 Stopping client for group {group_identifier}"
                     )
+                    start = time.perf_counter()
                     client.stop()
+                    logger.info(
+                        f"⏱ phase=client_stop group={group_identifier} "
+                        f"ms={(time.perf_counter() - start) * 1000:.1f}"
+                    )
                 except Exception as e:
                     logger.error(
                         "Error stopping client for group "
@@ -188,10 +194,14 @@ def pre_alloc_group(
 
     # Load and cache
     logger.debug(f"Loading pre-alloc group from {pre_alloc_path}")
+    start = time.perf_counter()
     pre_alloc_group_obj = PreAllocGroup.from_file(pre_alloc_path)
 
     pre_alloc_group_cache[pre_hash] = pre_alloc_group_obj
-    logger.info(f"Loaded pre-alloc group for {pre_hash}")
+    logger.info(
+        f"⏱ phase=pre_alloc_load group={pre_hash} "
+        f"ms={(time.perf_counter() - start) * 1000:.1f}"
+    )
 
     return pre_alloc_group_obj
 
@@ -214,12 +224,17 @@ def client_genesis(
     if pre_hash in client_genesis_cache:
         return client_genesis_cache[pre_hash]
 
+    start = time.perf_counter()
     genesis = to_json(pre_alloc_group.genesis)
     alloc = to_json(pre_alloc_group.pre)
     # NOTE: nethermind requires account keys without '0x' prefix
     genesis["alloc"] = {k.replace("0x", ""): v for k, v in alloc.items()}
 
     client_genesis_cache[pre_hash] = genesis
+    logger.info(
+        f"⏱ phase=genesis_prep group={pre_hash} "
+        f"ms={(time.perf_counter() - start) * 1000:.1f}"
+    )
     return genesis
 
 

packages/testing/src/execution_testing/logging/logger.py

@@ -86,15 +86,15 @@ def get_logger(name: str) -> EESTLogger:
 
 class UTCFormatter(logging.Formatter):
     """
-    Log formatter that formats UTC timestamps without milliseconds.
+    Log formatter that formats UTC timestamps with millisecond precision.
     """
 
     def formatTime(self, record: LogRecord, datefmt: str | None = None) -> str:  # noqa: D102,N802
         # camelcase required
         del datefmt
 
         dt = datetime.fromtimestamp(record.created, tz=timezone.utc)
-        return dt.strftime("%Y-%m-%d %H:%M:%S")
+        return f"{dt.strftime('%Y-%m-%d %H:%M:%S')}.{int(record.msecs):03d}"
 
     def format(self, record: LogRecord) -> str:
         """Format with relative pathname from current working directory."""

packages/testing/src/execution_testing/logging/tests/test_logging.py

@@ -98,14 +98,15 @@ def test_utc_formatter(self) -> None:
             {
                 "msg": "Test message",
                 "created": 1609459200.0,  # 2021-01-01 00:00:00 UTC
+                "msecs": 123.0,
             }
         )
 
         formatted = formatter.format(record)
 
         # logs contain
-        #       timestamp
-        assert "2021-01-01 00:00:00" in formatted
+        #       timestamp with millisecond precision
+        assert "2021-01-01 00:00:00.123" in formatted
         #       message
         assert "Test message" in formatted