Skip to content

Commit 64a58d6

Browse files
springfall2008CIclaude
authored
perf(tests): cut the unit test suite from 123s to 78s (#4966)
Profiling `--quick` by wrapping time.sleep/asyncio.sleep showed 38s of its 123s was spent literally asleep, and most of the rest of the hot spots were one avoidable cost: parsing multi-megabyte debug dumps with PyYAML's pure-Python parser. Production changes: - read_debug_yaml() now loads through libyaml's CLoader. It pairs the C parser with the very same (unsafe) Constructor yaml.unsafe_load uses, so the Python-object tags these dumps carry still load and the result is identical - verified equal on the committed cases - about 6x faster on a 5MB dump. Falls back to the pure-Python loader when PyYAML was not built with libyaml. This speeds up real --debug_file replays too, not just tests. - ComponentBase.wait_api_started() polls every 0.1s instead of every 1s. Components come up in milliseconds, so the old cadence spent nearly the whole wait asleep after the component was already live. The loop is now bounded by a monotonic deadline rather than by counting ticks, so `timeout` stays honest in seconds however often the flag is checked. Test changes - each of these waited on a real delay that no assertion depended on: - test_givtcp_component: _make_component() records the REST retry waits instead of taking them, mirroring test_givtcp_rest.py's _client. One test asserting a write never verifies was walking the whole 5 x 2s ladder. - test_alphaess_api: MockAlphaESS was inheriting initialize()'s real 2s api_delay, and the transport-failure test served the full retry backoff. - test_ohme / test_ge_cloud: skip the retry wait and the rate-limit pacing, as the neighbouring tests in those files already do. - test_chat: _fast_confirm_poll() shortens (not removes) await_confirmation's 0.2s poll for tests whose background thread answers immediately. Tooling: - --quick's help named three tests that are not marked slow while the four that are went unmentioned; it is now derived from TEST_REGISTRY so it cannot drift again. - Each test logs a wall-clock start/end stamp, so a run that stalls can be read straight from the log by its unmatched start stamp. debug_cases 22.56s -> 12.01s random 27.94s -> 22.44s givtcp_component 10.04s -> 0.03s web_if 3.37s -> 1.57s alphaess_api 7.05s -> 0.04s chat 3.50s -> 2.52s window_cache 7.47s -> 2.09s debug_yaml_scope 2.04s -> 0.19s ge_cloud 1.67s -> 1.04s ohme 1.01s -> 0.01s Sleeps left in place are the ones that are themselves the assertion - the tests proving the event loop is not blocked, and annual_job's real subprocesses. Co-authored-by: CI <ci@example.com> Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent 63b7b70 commit 64a58d6

9 files changed

Lines changed: 103 additions & 22 deletions

‎.cspell/custom-dictionary-workspace.txt‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -327,6 +327,7 @@ ladybugdb
327327
larr
328328
libbi
329329
libc
330+
libyaml
330331
LIFEPO
331332
linebreak
332333
linestyle

‎apps/predbat/component_base.py‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,13 @@
2424
import time
2525
import traceback
2626

27+
# Components typically come up in milliseconds, so the previous 1s poll spent nearly all of a
28+
# start-up wait asleep after the component was already live. Polling ten times a second makes
29+
# start-up feel immediate for no meaningful cost - one cheap flag check per tick. The wait is
30+
# bounded by a monotonic deadline rather than by counting ticks, so `timeout` stays honest in
31+
# seconds however often the flag is checked.
32+
API_START_POLL_SECONDS = 0.1
33+
2734

2835
class ComponentBase(ABC):
2936
"""
@@ -355,10 +362,9 @@ def wait_api_started(self, timeout=10 * 60):
355362
bool: True if component started successfully, False if timeout
356363
"""
357364
self.log(f"{self.__class__.__name__}: Waiting for API to start")
358-
count = 0
359-
while not self.api_started and count < timeout:
360-
time.sleep(1)
361-
count += 1
365+
deadline = time.monotonic() + timeout
366+
while not self.api_started and time.monotonic() < deadline:
367+
time.sleep(API_START_POLL_SECONDS)
362368
if not self.api_started:
363369
self.log(f"Warn: {self.__class__.__name__}: Failed to start")
364370
return False

‎apps/predbat/tests/test_alphaess_api.py‎

Lines changed: 11 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -12,7 +12,7 @@
1212
import hashlib
1313
import pytz
1414
from datetime import datetime
15-
from unittest.mock import MagicMock, patch
15+
from unittest.mock import AsyncMock, MagicMock, patch
1616
from alphaess import AlphaESSAPI
1717
from tests.test_infra import run_async as run_async_local, create_aiohttp_mock_response, create_aiohttp_mock_session
1818

@@ -32,12 +32,18 @@ def __init__(self, app_id="alphatestappid00000", app_secret="secret0000000000",
3232
self.state = {}
3333
self.published = {}
3434
self.external_state = {}
35+
# 0 rather than initialize()'s real 2s default: api_delay is a courtesy pause between
36+
# consecutive calls to AlphaESS's rate-limited cloud, and nothing here talks to the real
37+
# cloud - every request is a scripted mock. Left at 2 it was several real seconds of
38+
# dead wall-clock per test that reads more than one endpoint. A test that wants to
39+
# exercise the pacing can still set client.api_delay itself.
3540
self.initialize(
3641
app_id=app_id,
3742
app_secret=app_secret,
3843
inverter_sn=inverter_sn,
3944
automatic=automatic,
4045
control_enable=control_enable,
46+
api_delay=0,
4147
)
4248

4349
def log(self, message):
@@ -213,7 +219,10 @@ def test_alphaess_transport_failure_returns_minus_one():
213219
failed = False
214220
client = MockAlphaESS()
215221
session = create_aiohttp_mock_session(exception=Exception("connection reset"))
216-
with patch("alphaess.aiohttp.ClientSession", return_value=session):
222+
# _request backs off between its retries with asyncio.sleep(1 + attempt) - 3 real seconds
223+
# before it gives up. What is asserted here is the verdict it lands on, not the pacing it
224+
# keeps on the way there, so the wait is skipped.
225+
with patch("alphaess.aiohttp.ClientSession", return_value=session), patch("alphaess.asyncio.sleep", new_callable=AsyncMock):
217226
code, data = run_async_local(client._get("ess_list"))
218227
if code != -1:
219228
print(f"ERROR: transport failure code {code} should be -1")

‎apps/predbat/tests/test_chat.py‎

Lines changed: 30 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@
1414
"""
1515

1616
import asyncio
17+
import contextlib
1718
import json
1819
import os
1920
import shutil
@@ -1710,6 +1711,25 @@ def _write_call_response(entity_id="input_number.predbat_best_soc_keep", value="
17101711
return _tool_call_response("set_config", {"entity_id": entity_id, "value": value}, call_id="call_write")
17111712

17121713

1714+
@contextlib.contextmanager
1715+
def _fast_confirm_poll():
1716+
"""Shorten await_confirmation's poll interval for tests whose answer arrives at once.
1717+
1718+
await_confirmation re-checks the pending confirmation every CONFIRM_POLL_SECONDS (0.2s). That
1719+
is the right cadence against a person at a browser, but a test whose background thread answers
1720+
in microseconds still sits out a whole tick, and these tests assert that the answer is
1721+
honoured - not how often the waiter looks for it. Shortened rather than removed so the polling
1722+
loop is still genuinely exercised. Same trick test_write_confirmation_timeout uses on
1723+
CONFIRM_TIMEOUT_SECONDS.
1724+
"""
1725+
original = chat.CONFIRM_POLL_SECONDS
1726+
chat.CONFIRM_POLL_SECONDS = 0.002
1727+
try:
1728+
yield
1729+
finally:
1730+
chat.CONFIRM_POLL_SECONDS = original
1731+
1732+
17131733
def _confirm_soon(agent, approved):
17141734
"""Answer the next pending confirmation from a background thread, as a browser would."""
17151735

@@ -1738,7 +1758,8 @@ def test_write_confirmation_approved(my_predbat):
17381758
cid = asyncio.run(agent.store.create())
17391759

17401760
_confirm_soon(agent, True)
1741-
asyncio.run(agent.run_turn(cid, "raise best soc keep"))
1761+
with _fast_confirm_poll():
1762+
asyncio.run(agent.run_turn(cid, "raise best soc keep"))
17421763

17431764
kinds = [event["type"] for event in agent.events_since(0, cid)[0]]
17441765
for required in ("confirm", "confirm_result", "tool_start", "tool_end"):
@@ -1763,7 +1784,8 @@ def test_write_confirmation_rejected(my_predbat):
17631784
cid = asyncio.run(agent.store.create())
17641785

17651786
_confirm_soon(agent, False)
1766-
asyncio.run(agent.run_turn(cid, "raise best soc keep"))
1787+
with _fast_confirm_poll():
1788+
asyncio.run(agent.run_turn(cid, "raise best soc keep"))
17671789

17681790
results = [message for message in asyncio.run(agent.store.get_messages(cid)) if message["role"] == "tool"]
17691791
if not results or "declined" not in str(results[0].get("content")).lower():
@@ -1853,7 +1875,8 @@ def test_set_apps_config_confirmation_gate_and_card(my_predbat):
18531875
cid = asyncio.run(agent.store.create())
18541876

18551877
_confirm_soon(agent, False)
1856-
asyncio.run(agent.run_turn(cid, "change the HA url"))
1878+
with _fast_confirm_poll():
1879+
asyncio.run(agent.run_turn(cid, "change the HA url"))
18571880

18581881
events, _, _ = agent.events_since(0, cid)
18591882
kinds = [event["type"] for event in events]
@@ -1913,7 +1936,8 @@ def test_set_apps_config_approved_writes_apps_yaml(my_predbat):
19131936
cid = asyncio.run(agent.store.create())
19141937

19151938
_confirm_soon(agent, True)
1916-
asyncio.run(agent.run_turn(cid, "change num_inverters"))
1939+
with _fast_confirm_poll():
1940+
asyncio.run(agent.run_turn(cid, "change num_inverters"))
19171941

19181942
with open(os.path.join(temp_dir, "apps.yaml"), "r", encoding="utf-8") as handle:
19191943
written = handle.read()
@@ -3138,7 +3162,8 @@ async def press_stop():
31383162
approved = await agent.await_confirmation("call_x")
31393163
return approved, time.monotonic() - started
31403164

3141-
approved, elapsed = asyncio.run(drive())
3165+
with _fast_confirm_poll():
3166+
approved, elapsed = asyncio.run(drive())
31423167

31433168
if approved:
31443169
print("ERROR: a stopped confirmation was treated as approved")

‎apps/predbat/tests/test_ge_cloud.py‎

Lines changed: 9 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -3209,7 +3209,12 @@ async def mock_read_setting(serial, setting_id):
32093209

32103210
ge_cloud.async_read_inverter_setting = mock_read_setting
32113211

3212-
result = await ge_cloud.async_get_inverter_settings("test123")
3212+
# async_get_inverter_settings paces itself with a 0.2s sleep per setting so a large
3213+
# register list does not burst the GE Cloud rate limit. The reads here are local mocks
3214+
# with no rate limit to respect, so the pacing is skipped - as the retry/backoff tests
3215+
# in this file already do.
3216+
with patch("gecloud.asyncio.sleep", new_callable=AsyncMock):
3217+
result = await ge_cloud.async_get_inverter_settings("test123")
32133218

32143219
# Result structure: {sid: {"name": ..., "value": ..., "validation_rules": ..., "validation": ...}}
32153220
if 1 not in result or result[1]["value"] != "75":
@@ -3246,7 +3251,9 @@ async def mock_read_setting(serial, setting_id):
32463251

32473252
# Provide previous data - previous dict structure matches result structure
32483253
previous = {2: {"name": "charge_power", "value": "2500", "validation": {}, "validation_rules": {}}}
3249-
result = await ge_cloud.async_get_inverter_settings("test123", previous=previous)
3254+
# Local mocks, so skip the rate-limit pacing - see the success case above.
3255+
with patch("gecloud.asyncio.sleep", new_callable=AsyncMock):
3256+
result = await ge_cloud.async_get_inverter_settings("test123", previous=previous)
32503257

32513258
if result[1]["value"] != "75":
32523259
print("ERROR: Expected setting 1 value='75', got {}".format(result.get(1)))

‎apps/predbat/tests/test_givtcp_component.py‎

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -66,8 +66,23 @@ def _rest_data_blob(
6666

6767

6868
def _make_component(rest_urls="http://givtcp:6345", automatic=True):
69+
"""
70+
A GivTCPComponent whose REST clients count their retry waits rather than taking them.
71+
72+
GivTCPRest paces its retry ladders with InverterRestState.sleep(), a blocking time.sleep():
73+
2s between each of the five write-verification attempts, and 20s then 40s between read
74+
attempts. Those are the right delays against a real inverter that may still be booting, but
75+
in a test they are dead wall-clock - a single write that never verifies costs the whole
76+
5 x 2s ladder, which was most of this module's runtime.
77+
78+
Recorded into inverter.slept rather than discarded, so a test that does want to assert on the
79+
pacing still can. This mirrors test_givtcp_rest.py's own _client helper.
80+
"""
6981
base = MockBase()
7082
component = GivTCPComponent(base, rest_urls=rest_urls, automatic=automatic)
83+
for rest in component.rest:
84+
rest.inverter.slept = []
85+
rest.inverter.sleep = rest.inverter.slept.append
7186
return base, component
7287

7388

‎apps/predbat/tests/test_ohme.py‎

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1319,7 +1319,11 @@ async def mock_make_request_with_retry(method, url, data=None, skip_json=False):
13191319

13201320
client._make_request = mock_make_request_with_retry
13211321

1322-
run_async(client.async_get_charge_session())
1322+
# async_get_charge_session waits a real second between attempts to give the charger time to
1323+
# leave CALCULATING. What is under test is that it retries at all, not how long it pauses
1324+
# first, so the wait is skipped rather than served.
1325+
with patch("ohme.asyncio.sleep", new_callable=AsyncMock):
1326+
run_async(client.async_get_charge_session())
13231327

13241328
# Should have retried at least once
13251329
assert call_count[0] >= 2, f"Expected at least 2 calls, got {call_count[0]}"

‎apps/predbat/unit_test.py‎

Lines changed: 14 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -749,7 +749,10 @@ def main():
749749
parser.add_argument("--test", "-t", action="append", help="Run specific test(s) by name (can be used multiple times, use --list to see available tests)")
750750
parser.add_argument("--keyword", "-k", action="store", help="Run tests matching keyword pattern (e.g., -k carbon_ runs all carbon tests)")
751751
parser.add_argument("--list", "-l", action="store_true", help="List all available tests")
752-
parser.add_argument("--quick", "-q", action="store_true", help="Skip slow tests (optimise_levels, optimise_windows, debug_cases)")
752+
# Named from the registry rather than hard-coded: the previous literal list had drifted to
753+
# name three tests that are not marked slow at all, while the four that are went unmentioned.
754+
slow_test_names = ", ".join(name for name, _func, _desc, slow in TEST_REGISTRY if slow) or "none currently marked slow"
755+
parser.add_argument("--quick", "-q", action="store_true", help=f"Skip slow tests ({slow_test_names})")
753756
parser.add_argument("--plot", action="store_true", help="Display failure plots on screen (blocks until closed); the PNG is written either way")
754757
parser.add_argument("--random-generate", action="store_true", help="Generate random benchmark scenarios and write to a YAML file")
755758
parser.add_argument("--random-count", type=int, default=100, metavar="N", help="Number of random scenarios to generate (default: 100)")
@@ -867,26 +870,30 @@ def main():
867870
skipped_count += 1
868871
continue
869872

870-
# Show descriptive message for keyword/specific tests, simple for full suite
871-
print(f"**** Running: {name} - {desc} ****")
873+
# Show descriptive message for keyword/specific tests, simple for full suite.
874+
# The wall-clock stamps bracket each test so a run that stalls can be read straight
875+
# from the log: the elapsed figure below only appears once a test returns, so a test
876+
# still running (or one that hung) is identified by its unmatched start stamp.
877+
print(f"**** Running: {name} - {desc} (start {time.strftime('%H:%M:%S')}) ****")
872878

873879
start_time = time.time()
874880
test_failed = func(my_predbat)
875881
elapsed = time.time() - start_time
876882
total_time += elapsed
883+
end_stamp = time.strftime("%H:%M:%S")
877884

878885
if test_failed:
879886
if args.keyword or args.test:
880-
print(f"**** ERROR: Test {name} FAILED in {elapsed:.2f}s ****")
887+
print(f"**** ERROR: Test {name} FAILED in {elapsed:.2f}s (end {end_stamp}) ****")
881888
else:
882-
print(f"**** {name}: FAILED in {elapsed:.2f}s ****")
889+
print(f"**** {name}: FAILED in {elapsed:.2f}s (end {end_stamp}) ****")
883890
failed = True
884891
break
885892
else:
886893
if args.keyword or args.test:
887-
print(f"**** Test {name} PASSED in {elapsed:.2f}s ****")
894+
print(f"**** Test {name} PASSED in {elapsed:.2f}s (end {end_stamp}) ****")
888895
else:
889-
print(f"**** {name}: PASSED in {elapsed:.2f}s ****")
896+
print(f"**** {name}: PASSED in {elapsed:.2f}s (end {end_stamp}) ****")
890897

891898
# Report results
892899
if failed:

‎apps/predbat/userinterface.py‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,13 @@
3737
from config import APPS_SCHEMA, CONFIG_API_OVERRIDE
3838
from predbat import THIS_VERSION, THIS_VERSION_DISPLAY
3939

40+
# A debug dump is several megabytes of deeply nested YAML and PyYAML's pure-Python parser spends
41+
# most of a replay's wall-clock on it - about 6s for a 5MB dump. CLoader pairs libyaml's C parser
42+
# with the very same (unsafe) Constructor that yaml.unsafe_load uses, so the Python-object tags
43+
# these dumps carry still load and the result is identical, roughly 6x faster. PyYAML is not
44+
# always built with libyaml, so fall back to the pure-Python loader when the C one is absent.
45+
DEBUG_YAML_LOADER = getattr(yaml, "CLoader", yaml.UnsafeLoader)
46+
4047

4148
class DebugYamlDumper(yaml.Dumper):
4249
"""
@@ -765,7 +772,7 @@ def read_debug_yaml(self, filename):
765772
debug = {}
766773
if os.path.exists(filename):
767774
with open(filename, "r") as file:
768-
debug = yaml.unsafe_load(file)
775+
debug = yaml.load(file, Loader=DEBUG_YAML_LOADER)
769776
else:
770777
self.log("Warn: Debug file {} not found".format(filename))
771778
return

0 commit comments

Comments
 (0)