diff --git a/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/base.py b/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/base.py index 35edcedba81..23d6fbd5ad0 100644 --- a/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/base.py +++ b/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] diff --git a/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/enginex/conftest.py b/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/enginex/conftest.py index 78c57a4fb7e..f0275269e97 100644 --- a/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/enginex/conftest.py +++ b/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}" ) diff --git a/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/multi_test_client.py b/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/multi_test_client.py index 898c9273959..c28bb60e085 100644 --- a/packages/testing/src/execution_testing/cli/pytest_commands/plugins/consume/simulators/multi_test_client.py +++ b/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 diff --git a/packages/testing/src/execution_testing/logging/logger.py b/packages/testing/src/execution_testing/logging/logger.py index 61e745b166d..47f4ad715e2 100644 --- a/packages/testing/src/execution_testing/logging/logger.py +++ b/packages/testing/src/execution_testing/logging/logger.py @@ -86,7 +86,7 @@ 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 @@ -94,7 +94,7 @@ def formatTime(self, record: LogRecord, datefmt: str | None = None) -> str: # n 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.""" diff --git a/packages/testing/src/execution_testing/logging/tests/test_logging.py b/packages/testing/src/execution_testing/logging/tests/test_logging.py index 87fe76ac89c..1b9be2f0bc7 100644 --- a/packages/testing/src/execution_testing/logging/tests/test_logging.py +++ b/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