Perf: end-of-test-case log replay + single end-of-run DB commit cause long tail latency on constrained hosts (e.g. Raspberry Pi)

Summary

When ENABLE_REALTIME_PYTHON_TEST_LOGS=False (the default), the last step of a python_testing test case ("Show test logs") replays the entire SDK stdout log file line-by-line with an artificial pacing delay, and the whole run's log/state is committed to the DB in a single operation at the very end of the run. On resource-constrained hosts (e.g. Raspberry Pi), with large log volumes this adds tens of seconds to minutes of wall-clock time even though actual test execution is fast. There's a matching set of smaller issues on the CLI side that compound the perceived lag when attached to a run with test-run-execution.

Root cause

backend/test_collections/matter/sdk_tests/support/python_testing/models/test_case.py:69-71:

LOG_BATCH_SIZE = 50      # Number of log lines to send per batch
LOG_BATCH_DELAY = 0.01   # Delay in seconds between batches (10ms)

display_batch_logs() (test_case.py:597-642, invoked from cleanup() when real-time logging is disabled) iterates the test case's output file and sleeps 10ms every 50 lines purely to yield to the event loop. For a real-world 673,988-line / 41MB output file, that's 13,480 batches × 10ms ≈ 135 seconds of pure asyncio.sleep, before any other work is counted. The same pacing constants are reused in _log_remaining_content() (test_case.py:578-584).

(Verified this is not caused by cross-test-case log accumulation: the SDK runner truncates the output file — open(EXECUTION_LOG_OUTPUT, "w", ...) in test_harness_client.py:204 — fresh for every test case.)

Compounding factors

1. Per-line log entry construction is not off-loaded. backend/app/test_engine/test_log_handler.py:106-109 registers the test_run_log sink without enqueue=True, unlike the other two sinks in backend/app/log.py:117,127. Every replayed line does synchronous Pydantic model construction inline on the run's coroutine.

2. The entire run's log/state is committed to the DB exactly once, at the end of the run. backend/app/test_engine/test_db_observer.py:53-57 (apply_updates) has a single caller: backend/app/test_engine/test_runner.py:184, after await self.test_run.run() returns. This means a run's full log column (a single JSON list, backend/app/models/test_run_execution.py:76-82) is JSON-encoded and written in one large UPDATE at the very end, rather than incrementally.

3. CLI: stream_sink is missing the enqueue=True its own comment claims. cli/th_cli/test_run/logging.py:78-79:

   # Add sink with enqueue=True to prevent re-entrancy and catch=True to suppress errors
   logger.add(stream_sink, format="{message}", catch=True)
   

   enqueue=True is documented but not actually passed, so stream_sink runs synchronously on the event loop per record. This also leaves open a real re-entrancy path: cli/th_cli/test_run/logs_http_server.py:163-164 logs from the SSE-server thread every 100 entries sent, which re-enters stream_sink → the same SSE queue.

4. CLI: the yield interval never fires for the backend's actual batch size. cli/th_cli/test_run/websocket.py:98,447-456:

   LOG_RECORD_YIELD_INTERVAL = 200
   ...
   if (i + 1) % LOG_RECORD_YIELD_INTERVAL == 0:
       await asyncio.sleep(0)
   

   The backend sends LOG_BATCH_SIZE = 50 records per websocket message, so (i+1) % 200 never hits for steady-state batches — the yield only helps for the rare oversized end-of-run flush message it wasn't primarily written for.

Suggested fixes

• Replace the fixed LOG_BATCH_DELAY = 0.01 pacing with a much larger batch size and a bare asyncio.sleep(0) yield (test_case.py:69-71, 597-642, 578-584).
• Add enqueue=True to the test_run_log sink in test_log_handler.py:106-109, matching the pattern already used in log.py:117,127.
• Give TestDBObserver an incremental flush loop (mirroring TestLogHandler's existing LOG_PROCESSING_INTERVAL periodic task) instead of relying solely on the single end-of-run apply_updates() call in test_runner.py:184, so the final commit isn't the entire run's log/state at once.
• Pass enqueue=True to logger.add(stream_sink, ...) in cli/th_cli/test_run/logging.py:79 to match its own comment and remove the SSE-thread re-entrancy path through logs_http_server.py:163-164.
• Lower LOG_RECORD_YIELD_INTERVAL (or yield once per received message instead of per N records) in cli/th_cli/test_run/websocket.py:98,447-456 so it actually yields during steady-state batches sized at the backend's LOG_BATCH_SIZE.

Environment / reproduction notes

Observed on a Raspberry Pi running a python_testing test run via the CLI (test-run-execution). Test steps complete quickly; the final "Show test logs" step (and/or the CLI's tail after the run reaches a terminal state) visibly stalls for a long time relative to actual execution time. Reproducible with any test case producing a large SDK log file (hundreds of thousands of lines).