From cbc0d8c5771fad7187b6ea6cf3e0c9ff39b0570e Mon Sep 17 00:00:00 2001 From: "Joshua D. Drake" Date: Sat, 8 Aug 2026 06:38:05 -0600 Subject: [PATCH] fix: a profile must not measure the assert build or its own fixture (#445) Two artifacts in bench/run_profile.sh, both found while profiling the load for #445, and both of the class the script already exists to prevent: output that looks like data. AN ASSERT BUILD IS NOT A SLOWER VERSION OF THE SAME PROFILE. --enable-cassert compiles in validation production never runs, and it does not distribute evenly. Profiled against the assert PG18 here, the largest single self-time entry of the ingest shape was verify_compact_attribute at 9.28%, a function that does not exist in a production build, with every other percentage diluted against it. A reader would reasonably have gone looking at tuple descriptor validation. That is the same category as an unopenable perf event, which this script already refuses on the grounds that profiling would report an empty profile as data, so it gets the same treatment: refuse, with PROFILE_ALLOW_CASSERT=1 to override, because an assert build is still worth profiling when it is the only one to hand and two assert builds compare fine with each other. The build is printed with the event and the unwind method, for the same reason those are. THE INGEST SHAPE PROFILED ITS OWN DATA GENERATOR. It was INSERT INTO pw SELECT g, md5(g::text) FROM generate_series(1,200000) g so md5_calc took 12.31% and pg_md5_hash 1.65%: about 14% of an "ingest" measurement was the fixture inventing strings inside the timed statement, inflating the denominator every write-path entry was measured against. The rows are now materialised into a heap table first, outside the profiled statement, which is also closer to what a load is: rows arriving from somewhere rather than computed per row by the insert. Proved by running it: the assert build now exits 1 with a FATAL naming the measured cost, PROFILE_ALLOW_CASSERT=1 lets it through and labels every percentage, and on a non-assert build md5_calc leaves the profile entirely. The numbers in #499 were taken through both artifacts, so its 33.9% and 14.6% are directionally right and quantitatively off. Co-Authored-By: Claude Opus 5 (1M context) --- bench/run_profile.sh | 46 +++++++++++++++++++++++++++++++++++++++++++- 1 file changed, 45 insertions(+), 1 deletion(-) diff --git a/bench/run_profile.sh b/bench/run_profile.sh index 55d2ed4..b3379bd 100755 --- a/bench/run_profile.sh +++ b/bench/run_profile.sh @@ -93,6 +93,34 @@ if ! perf stat -e "$PERF_EVENT" true >/dev/null 2>"$WORKDIR/evprobe.err"; then exit 1; } fi +# An assert build is not a slower version of the same profile, it is a different +# one. --enable-cassert compiles in validation that production never runs, and it +# does not distribute evenly: profiled against the assert PG18 here, the largest +# single self-time entry of the ingest shape was verify_compact_attribute at +# 9.28%, a function that does not exist in a production build, with every other +# percentage diluted against it. Someone reading that profile would reasonably +# have gone looking at tuple descriptor validation. +# +# This is the same category as an unopenable perf event above, and gets the same +# treatment: refuse, rather than emit a number that looks like data. The override +# exists because an assert build is still worth profiling when it is the only one +# to hand, and a comparison between two assert builds is valid. +CASSERT="$("$PG_CONFIG" --configure | grep -c 'enable-cassert' || true)" +if [ "${CASSERT:-0}" != "0" ]; then + if [ -n "${PROFILE_ALLOW_CASSERT:-}" ]; then + echo "-- WARNING: assert build (--enable-cassert). Percentages below include" + echo " validation a production build never runs, and are comparable only" + echo " against another assert build." + else + echo "FATAL: $("$PG_CONFIG" --bindir) is an --enable-cassert build." + echo " Assert-only validation would be profiled as if it were work:" + echo " measured at 9.28% self time for verify_compact_attribute alone." + echo " Use a non-assert build, or set PROFILE_ALLOW_CASSERT=1 to" + echo " profile anyway and have every percentage labelled as such." + exit 1 + fi +fi + CFLAGS="$("$PG_CONFIG" --cflags)" case "$CFLAGS" in *-fno-omit-frame-pointer*) UNWIND="fp"; UNWIND_WHY="frame pointers present" ;; @@ -299,8 +327,23 @@ for shape in $SHAPES; do project) profile_shape project "PERFORM id, k, v FROM p WHERE k BETWEEN 100 AND 140" ;; ingest) + # The source rows are materialised OUTSIDE the profiled statement. + # + # This shape used to be + # INSERT INTO pw SELECT g, md5(g::text) FROM generate_series(...) + # which put md5_calc at 12.31% and pg_md5_hash at 1.65% of the profile: + # about 14% of an "ingest" measurement was the fixture inventing its own + # strings, inside the timed statement, inflating the denominator every + # write-path entry was measured against. + # + # A heap source is also closer to what a load is: rows arriving from + # somewhere, rather than being computed per row by the insert itself. + sql_run "DROP TABLE IF EXISTS pw_src; + CREATE TABLE pw_src (id bigint, t text); + INSERT INTO pw_src SELECT g, md5(g::text) FROM generate_series(1,200000) g; + ANALYZE pw_src;" >/dev/null 2>&1 sql_run "CREATE TABLE pw (id bigint, t text) USING pgcolumnar;" >/dev/null 2>&1 - profile_shape ingest "INSERT INTO pw SELECT g, md5(g::text) FROM generate_series(1,200000) g" ;; + profile_shape ingest "INSERT INTO pw SELECT id, t FROM pw_src" ;; *) echo "FAIL: unknown shape '$shape'" echo " valid: decode filtered project ingest" @@ -310,6 +353,7 @@ for shape in $SHAPES; do done echo +echo "Build: $([ "${CASSERT:-0}" != "0" ] && echo "ASSERT (--enable-cassert)" || echo "non-assert")" echo "Event and unwind method are printed above and belong with any number taken" echo "from this run: a percentage is only comparable against another profile that" echo "sampled the same way."