Commit: ac9a306
Version: 3.4dev-20260817_072105
Mediabot’s test suite has been reliable for a long time.
It has also become large enough that a full run now takes about fifteen minutes.
So before trying to parallelise anything, MB650 adds something much safer:
measurement.
The test runner can now profile every test file and show where the time actually goes.
No reordering.
No skipped tests.
No hidden concurrency.
No “make it faster and hope”.
Just a map.
--profileThe normal test runner now accepts:
perl t/test_commands.pl --profile
and an optional report size:
perl t/test_commands.pl --profile --profile-top 30
The profiler records, per test file:
elapsed time
execution mode
assertion count
failure contribution
and sorts the result from slowest to fastest.
Example:
Slowest test files (top 30 of 715)
------------------------------------------------------------------------------
# seconds mode asserts file
------------------------------------------------------------------------------
1 66.348 runner 41 541_mb319_trivia_async_fetch.t
2 65.193 runner 39 612_mb394_trivia_rate_limit_retry.t
3 61.019 runner 28 613_mb395_trivia_process_watch_diagnostics.t
4 46.335 runner 26 614_mb396_trivia_stage_protocol_deadline.t
...
------------------------------------------------------------------------------
Profiled 715 test file(s); cumulative case time 902.362s
A leading ! marks a file that contributed at least one failed assertion.
The final profiled run completed successfully:
PASSED : 13229/13229
RC=0
Timing:
715 test files
902.362 s cumulative case time
903 s wall clock
So profiling itself adds essentially no meaningful wall-clock distortion to the full run.
The four slowest files are all Trivia-related:
541_mb319_trivia_async_fetch.t 66.348 s
612_mb394_trivia_rate_limit_retry.t 65.193 s
613_mb395_trivia_process_watch_diagnostics.t 61.019 s
614_mb396_trivia_stage_protocol_deadline.t 46.335 s
Together:
238.895 seconds
That is approximately:
26.5% of the entire test-suite runtime
in only four files.
That is exactly why profiling came before parallelisation.
The suite is not uniformly slow.
A small number of lifecycle-heavy tests dominate the runtime.
The 30 slowest files account for approximately:
572.249 seconds
or:
63.4% of the full 902.362 seconds
This means optimisation can be targeted.
We do not need to throw 715 test files into a parallel executor and create a new class of race conditions merely to save time.
The first full profiled run failed:
FAILED : 5/13225
All five failures came from:
397_mb161_reminder_starvation_and_first_occurrence.t
The test itself was fine.
The profiler had imported:
use Time::HiRes qw(time);
into the shared runner namespace.
Because many test files are loaded into that same namespace, their normal integer time() suddenly became high-resolution floating-point time.
A reminder tag that previously looked like:
[at:1786967727]
could now become:
[at:1786967727.25777]
while the reminder parser expected:
[at:(\d+)]
The tag stopped matching and five reminder assertions failed.
The fix was to stop exporting time():
use Time::HiRes ();
and call it explicitly only inside the profiler:
Time::HiRes::time()
After that correction:
397_mb161 + profiler regression
PASSED : 40/40
focused runner regression
PASSED : 98/98
full profiled suite
PASSED : 13229/13229
The profiler now measures the tests without changing their runtime namespace semantics.
MB650 does not parallelise the suite.
It does not:
fork multiple test files
change ordering
skip slow tests
shorten timeouts
mock additional behaviour
change production code
The whole point is to gather enough evidence to make the next performance decision safely.
The slowest tests naturally fall into groups that deserve different treatment.
Examples from the top 30 include:
Trivia async fetch
Trivia rate-limit retry
Trivia process-watch diagnostics
Trivia stage protocol deadline
Partyline reverse DNS
Define async deterministic
Version-check async nonblocking
AI chunk pacing
These are prime candidates for examining shared subprocess lifecycle behaviour.
karmahist
seen
lookup DB safety
poll operations
notes
helpers DB balance
level lookup DB safety
These should remain conservative until isolation guarantees are explicit.
test runner contract isolation
dispatch dead handlers
help internal commands
These are different again: their time comes from loading or exercising a large amount of code, not necessarily from external waiting.
The important conclusion is that one optimisation strategy will not fit every test.
The roadmap explicitly called for classifying tests before considering parallel execution:
PURE
FILESYSTEM
PROCESS
DB
NETWORK
That remains the right approach.
Tests involving:
temporary files
processes
signals
ports
shared databases
PID state
timeouts
global Perl namespaces
cannot safely be assumed independent.
MB650 gives us the numbers needed to make that classification intelligently.
A new test protects the profiler itself:
t/cases/832_mb650_test_suite_profiler.t
It covers the profile CLI/report contract and now also guards against re-exporting high-resolution time() into the test namespace.
The existing runner regression tests were also exercised throughout the round.
ac9a306
⏱️ Give the Test Suite a Marauder's Map for Its Slowest Paths
Version:
3.4dev-20260817_072105
Committed scope:
CHANGELOG.md
README.md
VERSION
t/test_commands.pl
t/cases/832_mb650_test_suite_profiler.t
The owl has reached GitHub.
And now, for the first time, we know exactly where those fifteen minutes go.
You must be logged in to reply.