bench: a profiling harness, and make two harnesses executable - #499
Conversation
Adds bench/run_profile.sh: attaches perf to a running backend for four query shapes and reports where the time goes, so a micro-optimisation is aimed at a measured hot path. The shapes are the ones the benchmarks flagged, not an arbitrary set: an un-pushable text predicate (commandprompt#426), the filtered aggregate that gains nothing from parallel workers, a row-returning scan that never receives a parallel plan, and the write path that is 3.6x slower than heap on text (commandprompt#445). Measured on 8M rows, PG18.4, 6s windows: decode SB_MatchText 27.2% -- core's LIKE matcher, not our decode filtered bitunpack 21.0%, PgColumnarReadNextRow 16.9%, ExecInterpExpr 13.8% project bitunpack 19.2%, PgColumnarReadNextRow 18.0%, ExecInterpExpr 13.4% ingest encode_fsst_shared 33.9%, PgColumnarFsstBuildChunkTable 14.6%, pg_qsort 5.5%, fsst_count_add 3.3%, fsst_cand_cmp 1.8% So roughly 59% of ingestion is FSST symbol-table construction, which is a measured answer to why commandprompt#445 sees citus load the same data faster, and makes the case for commandprompt#472 (cache the keep/drop verdict) concrete rather than speculative. On the read side bitunpack is the top cost on both scan shapes while PgColumnarDecodeChunk itself is 4-7%, so the inner bit-unpacking loop is where decode time actually sits. WHY THE GUARDS ARE THE BULK OF THE SCRIPT Every one of them is a failure this harness actually produced while being written, and each produced output that looked like data: - The event is probed BEFORE the fixture is built. This VM exposes no hardware PMU, so perf's default precise event cannot be opened, perf writes a zero-sized file, and perf report renders an empty profile without complaint. An empty profile reads as "nothing is hot". - The unwind method is chosen from pg_config --cflags rather than assumed. The build has no -fno-omit-frame-pointer, so frame-pointer stacks are truncated; it does keep .debug_info, so DWARF resolves. Event and method are printed with the profile, because a percentage only compares against one sampled the same way. - perf's stderr is never redirected. Discarding it turned the PMU diagnosis above into an unexplained empty report. - The sample count is asserted before any percentage is read. - The backend is confirmed on-CPU before attaching, and confirmed to be running THIS shape via a marker unique to the shape and the run. - The pid is asserted to differ from the previous shape's. That last one exists because the first working version reported four clean, fully symbolized profiles that were all the SAME query. `kill` on the psql client does not stop the backend; the server keeps running its loop until it next writes to a client that is gone. The first shape's backend outlived its window and every later shape matched it on a generic '%LOOP%'. A LIKE matcher appeared in an INSERT profile, which is the only reason it was caught. The loops are now time-bounded and expire on their own, the backend is terminated server-side, and two shapes sharing a pid is a hard failure. Also sets the executable bit on run_bench_join.sh and run_bench_readstream.sh, which were committed 0644. Both fail with "Permission denied" when invoked the way the other harnesses are, which is how two of four were skipped in a full bench run. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01QRQYekvivA4RLDnndhanHK
jdatcmd
left a comment
There was a problem hiding this comment.
Good harness, and the findings are the kind that change what gets worked on: 59% of ingestion in FSST symbol-table construction sizes #472 and answers #445 with a measurement rather than a theory, and bitunpack dominating both scan shapes while PgColumnarDecodeChunk sits at 4 to 7% is genuinely not where I would have looked.
One change requested, and it is your own principle one level up.
The guards are real. I checked each against the script rather than the description
- perf event probed with
perf statbefore the fixture is built, with the fallback and aFATALif neither opens evprobe.errcaptures perf's stderr instead of discarding it- unwind method taken from
pg_config --cflags,dwarf,8192when frame pointers are absent, and both event and method printed with the profile - marker is
PROFILEMARK_${name}_$$, unique per shape and per invocation - backend confirmed
state = 'active'matching that marker andpsstateR* pid = PREV_PIDis a hard stop- the DO block carries its own
clock_timestamp()deadline, so a loop expires even if every cleanup fails pg_terminate_backendon the backend, waited on, before the clientkill- sample count asserted at 200 before any percentage is printed
The pid-collision story is worth the space you gave it. Four fully symbolized profiles of the same query, every guard passing, caught only because a LIKE matcher turned up in an INSERT profile, is exactly the shape this repository keeps producing.
cb_guards.sh is also 0644 and you correctly left it alone: it is sourced by run_clickbench.sh:126, never invoked. I checked because a sweep that fixed all three would have been wrong.
The requested change: a failed run still exits 0
FAIL: pid ... already profiled and both SKIP paths return from profile_shape without setting any state, and nothing after the loop inspects anything. So a run in which every shape failed on pid collision prints its FAIL lines, then:
== profile complete ==
and exits 0.
That is the defect this script is otherwise built to prevent, in the one place it does not look: the summary line says complete and the exit code says success, while the thing that was supposed to be measured was not. It is also #447 exactly, which you fixed, and which #455 then had to fix again one layer down when exit 2 collided with something else. The lesson recorded from that pair was two signals rather than one, because a single one cannot be made collision-proof, and here there is currently zero.
Concretely:
- a
FAILED=1flag set by the pid-collision branch and by the too-few-samples branch exit 1at the end when it is set, and a final line naming which shapes produced no usable profileunknown shape: $shapeshould set it too. A typo inPROFILE_SHAPEScurrently profiles nothing and exits 0, which is the same failure with an easier cause
Whether the too-few-samples SKIP should be fatal or merely non-zero is your call. It is a legitimate "raise PROFILE_SECS" condition rather than a defect, so I would accept it counting as not-success without being called FAIL.
Nothing else. bench/ is unregistered so there is no SUITES interaction, the mode changes are correct, and CI is green on all 11.
|
Re-reviewed at One addition from the second pass, and it is a clean bill rather than another request. I was suspicious of the sample-count parse, because Tested it rather than raising it as a worry. perf 7.0.12:
So the exit status is the only thing outstanding. |
Review catch, and it is this script's own principle in the one place the script did not apply it. Both SKIP paths and the pid-collision FAIL returned from profile_shape without recording anything, and nothing after the loop inspected anything. A run in which EVERY shape collided printed its FAIL lines, then "== profile complete ==", and exited 0: the summary claiming success while nothing had been measured. Two counters rather than one, which is the lesson from commandprompt#447 and commandprompt#455 -- a single status value cannot be made collision-proof, and commandprompt#455 had to fix commandprompt#447 again a layer down for exactly that reason. A defect and an underpowered run are different things and are now reported and exited differently: 0 every requested shape produced a usable profile 1 a shape FAILED: pid collision, no backend appeared, or a shape name that does not exist 2 nothing failed, but a shape produced too few samples to attribute The too-few-samples case is deliberately not called FAIL. It is a legitimate "raise PROFILE_SECS" condition rather than a defect, so it is counted as not-success and named, without being reported as a fault in the code under test. An unknown shape now fails too. It previously profiled nothing and exited 0, which is the same defect with an easier cause: a typo in PROFILE_SHAPES. Proved by removal, not asserted: PROFILE_SHAPES=bogus -> "== profile FAILED == no usable profile for: bogus" exit 1 PROFILE_SHAPES=decode -> "== profile complete ==" exit 0 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01QRQYekvivA4RLDnndhanHK
|
Fixed and pushed as You are right, and it is this script's own principle in the one place the script did not apply it. Every guard I wrote checks the measurement; none checked the report of the measurement. Two counters rather than one, per the #447 and #455 lesson that a single status value cannot be made collision-proof: I took your call on the too-few-samples case: not called FAIL. It is a legitimate "raise Proved by removal rather than asserted: Thanks for checking |
jdatcmd
left a comment
There was a problem hiding this comment.
481e491a addresses it, and the shape you chose is better than what I asked for.
I said whether the thin-sample case should be fatal was your call. Two counters with three exit codes is the right answer, and grounding it in #447 and #455 is exactly the reasoning that keeps it from being simplified away later:
0 every requested shape produced a usable profile
1 at least one shape FAILED (pid collision, or a shape name that does not exist)
2 no shape failed, but at least one produced too few samples to attribute
Three things I checked rather than assumed:
== profile complete ==is now reachable only when both lists are empty.- "no backend running the marker appeared" was upgraded from SKIP to FAIL. That is right and it is a change I did not ask for: a shape that was requested and did not run is a failure, not an abstention.
unknown shapesets the flag, so a typo inPROFILE_SHAPEScan no longer profile nothing and exit 0.
One observation, deliberately not a request
exit 2 is the code #455 moved away from, and for a reason that half-applies here: bash itself exits 2 on a syntax error, so "INCOMPLETE" and "this script no longer parses" are the same number. If this is ever wired into a make target or a cron that branches on the status, those two become indistinguishable.
I am not asking you to change it, because you have satisfied what #455 actually concluded: two signals rather than one. The == profile INCOMPLETE == marker is the second, and a broken script cannot print it. Recording the thought so that whoever automates this reads the marker rather than the number, and so the choice reads as considered.
Approving. Thanks for the profile itself, which is already changing what gets worked on: #472 landed on the strength of it (#502) and took about 2.5x out of the ingest path.
Adds
bench/run_profile.sh, so a micro-optimisation can be aimed at a measured hot path rather than a guessed one, and sets the executable bit on two harnesses that were committed without it.What it found on the first honest run
8M rows, PG 18.4, 6-second windows, serial:
decode(un-pushableLIKE, #426)SB_MatchText27.2% — core's matcher, not our decodefiltered(skippable range agg)bitunpack21.0%,PgColumnarReadNextRow16.9%,ExecInterpExpr13.8%project(row-returning scan)bitunpack19.2%,PgColumnarReadNextRow18.0%,ExecInterpExpr13.4%ingest(columnar write path, #445)encode_fsst_shared33.9%,PgColumnarFsstBuildChunkTable14.6%,pg_qsort5.5%,fsst_count_add3.3%,fsst_cand_cmp1.8%About 59% of ingestion is FSST symbol-table construction. That is a measured answer to #445, where citus loads the same data faster, and it turns #472 (cache the keep/drop verdict instead of re-deciding per row group) from a plausible idea into a sized one.
On the read side,
bitunpackis the largest single cost on both scan shapes whilePgColumnarDecodeChunkitself is only 4–7%, so the inner bit-unpacking loop is where decode time actually sits — not where I would have guessed.The guards are most of the script, and each one is a failure it produced
Every guard below exists because the harness did the thing it now prevents, and each failure produced output that looked like data:
perf reportrenders an empty profile without complaint. An empty profile reads as "nothing is hot" — after a 20M-row load.pg_config --cflags. The build has no-fno-omit-frame-pointer, so frame-pointer stacks truncate; it does keep.debug_info, so DWARF resolves. Both the event and the method print with the profile, since a percentage only compares against another sampled the same way.Why that last one exists
The first working version reported four clean, fully symbolized profiles that were all the same query.
killon the psql client does not stop the backend — the server keeps running its loop until it next writes to a client that is gone — so shape one's backend outlived its window and every later shape matched it on a generic'%LOOP%'.Every guard passed. A backend was running, it was
state=R, each profile had ~6,000 samples and a clean call tree. What caught it was aLIKEmatcher appearing in anINSERTprofile. That is luck, not a control, so it is now a control: the loops are time-bounded and expire on their own, the backend is terminated server-side, and two shapes sharing a pid is a hard failure that names why.The executable bits
run_bench_join.shandrun_bench_readstream.share committed0644. Invoked the way the other harnesses are they fail withPermission denied, which is how two of four were silently skipped in a full bench run. Mode-only change, no content.Not included
No
SUITESentry —bench/is not registered anywhere, so this cannot conflict with an in-flight suite change.