Where capture time goes
Stubbing record_line in stages, running tests/unit/assert/basic_test.sh
against --coverage-paths src (Bash 3.2 arm64, 5718 recorded lines):
| cumulative | stage cost |
|---|
| no coverage | 566 ms | |
trap fires, record_line stubbed | 1318 ms | 752 ms — dispatch floor |
| + tracked-file lookup | 2019 ms | 701 ms |
| + path normalize and lookup | 2886 ms | 867 ms |
| + the two appends | 3591 ms | 705 ms |
Three roughly equal thirds, and the dispatch floor is not removable without
changing engine.
Two fixes worth taking
The appends reopen the file per line.>>"$file" opens, writes and closes
for every record, twice per line (data plus test-hits): about 11,400 opens for
this run, 705 ms, roughly 62 µs each. Holding a descriptor open for the process
(exec 9>>"$file" — a fixed fd, since {fd}>> is Bash 4.1+) and writing to it
turns each record into one write.
Care needed: the descriptor belongs to a process, so a subshell inherits it and
that is fine, but _resolve_output_files picks a different target under
--parallel, so the fd has to be (re)opened when the resolved target changes,
and closed in cleanup.
Two lookups per line where one would do. The tracked decision and the
normalized path are separate namespaces, so every line pays the
${file//[^a-zA-Z0-9]/_} key rebuild twice. Storing "<decision> <normalized>"
under one key halves it — worth ~300 ms of the 1568 ms those two stages cost.
Caveat from earlier today
Micro-benchmarks of record_line have mispredicted the in-situ result twice
(the memo in #1102 promised 5x and delivered 4%). Both of these should be
measured end to end before they are believed, and dropped if they do not show.
Where capture time goes
Stubbing
record_linein stages, runningtests/unit/assert/basic_test.shagainst
--coverage-paths src(Bash 3.2 arm64, 5718 recorded lines):record_linestubbedThree roughly equal thirds, and the dispatch floor is not removable without
changing engine.
Two fixes worth taking
The appends reopen the file per line.
>>"$file"opens, writes and closesfor every record, twice per line (data plus test-hits): about 11,400 opens for
this run, 705 ms, roughly 62 µs each. Holding a descriptor open for the process
(
exec 9>>"$file"— a fixed fd, since{fd}>>is Bash 4.1+) and writing to itturns each record into one
write.Care needed: the descriptor belongs to a process, so a subshell inherits it and
that is fine, but
_resolve_output_filespicks a different target under--parallel, so the fd has to be (re)opened when the resolved target changes,and closed in
cleanup.Two lookups per line where one would do. The tracked decision and the
normalized path are separate namespaces, so every line pays the
${file//[^a-zA-Z0-9]/_}key rebuild twice. Storing"<decision> <normalized>"under one key halves it — worth ~300 ms of the 1568 ms those two stages cost.
Caveat from earlier today
Micro-benchmarks of
record_linehave mispredicted the in-situ result twice(the memo in #1102 promised 5x and delivered 4%). Both of these should be
measured end to end before they are believed, and dropped if they do not show.