Add a perf profiling mode to the benchmark workflow - #12952
Conversation
dotTrace cannot see past a P/Invoke: everything below the boundary collapses into a single `[Native or optimized code]` node, routinely the third-largest entry in a snapshot with no breakdown at all. RocksDB, the allocator, memory zeroing and GC all land in there together. Add a `perf` input that records a host-side Linux perf profile alongside the run. perf walks one stack across the managed/native boundary, naming managed frames from the runtime's perf map and native frames from the container's shared objects, so that time is attributed per callee. The profile ships as folded stacks next to the existing dotTrace artifacts. perf runs on the host, so no image change is needed; expb sets the perf-map environment on the client container. scripts/perf-report.sh reads the folded output with the same shape as dottrace-report.sh - top/total/native/compare - reporting shares of the profile so two runs of different length stay comparable.
Reading the first captured profile surfaced two defects. The managed-frame pattern assumed `Namespace.Method`, but the runtime's perf map emits `<ret> [Assembly] Type::Method(args)`, so `native` listed managed frames as unmanaged. And `head` closing the pipe under `pipefail` made every report exit 141; awk now applies the row limit itself. Correct the documented caveats to what the run actually showed: kernel frames do resolve, the capture spans every thread of the process including RocksDB's compaction pool, and symbolization is partial rather than complete.
|
Claude finished @kamilchodola's task in 5m 39s —— View job Review: perf profiling mode for the benchmark workflowReviewed the full diff against
VerdictThe design is sound and the workflow wiring is correct. Everything I found is in The feature itself is well-motivated: dotTrace's What I checked and found clean
Findings
Two notes rather than findingsMerge order. No test for the reader. AGENTS.md asks for a regression test with every bug fix, and the second commit fixed two real defects (the managed-frame pattern, and Verification limitsI read the script closely but could not execute it — the review sandbox denied writing fixtures and running Recommendation: fix #1 before merge (it can silently produce wrong A/B deltas, which is the tool's main job). The rest are fine as follow-ups or as acknowledged-and-deferred. |
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
The eth_call benchmarks launch nodes through start-node.sh rather than expb, so they need their own perf hook. Same three requirements as the expb sidecar: the perf-map environment on the client, the host PID from docker top, and folding before teardown while /proc/<pid>/root still resolves the container's shared objects. perf-fold.awk keeps the shell path free of a Python dependency; it was verified to produce byte-identical output to the expb folder on the same fixture. Only the primary node is profiled - the reference client is left alone.
benaadams
left a comment
benaadams
left a comment
There was a problem hiding this comment.
Local review: unique findings not already covered by the existing inline discussions.
The sweep step keeps its own env block and never carried DOTTRACE, so attaching PERF beside the existing DOTTRACE entries reached the single-node path and the log scan but not run-rpc-sweep.sh: the corpus sweep started its nodes with perf disabled and produced no profile.
|
@claude re-review |
|
Claude finished @kamilchodola's task in 8m 16s —— View job Re-review: perf profiling modeReviewed the delta since my last pass (
VerdictEvery finding from the previous round is fixed, several of them properly rather than minimally. The new work — the recorder-identity guard, the fail-closed collectors, the Prior findings — all resolved
benaadams' four also land: perf env scoped after dotTrace's Two things I checked closely and found correct: the Findings
On #1 — this is the only thing I'd hold the merge for, and it's mechanical. On #3 — this is the one worth a design thought rather than a patch. The premise of the feature is that perf attributes both sides of the P/Invoke boundary. If the managed side silently drops out — perf resolving Not findings
Verification limitsI read the scripts closely but could not execute the new test suite — Recommendation: fix #1 before merge. #2 and #3 are worth an answer — even "the runner user is root" and "acknowledged, follow-up" would settle both — and the Lows are fine as follow-ups. |
|
@claude re-review |
|
Claude finished @kamilchodola's task in 7m 44s —— View job Re-review: perf profiling modeReviewed the delta since the last pass (
VerdictThe three findings I'd have held the merge for are all properly fixed. No Critical or High. One Medium (documentation) and four Lows, none of which touch client code or benchmark timings. Prior findings — resolved
Things I checked closely this round and found correct: Findings
Not findings
Verification limitsI read every changed file but could not execute anything: Also unchanged from last round: the rpc-bench perf path has still not been run end-to-end. The only linked verification, 32536259998, is expb, whose capture lives in expb rather than in this diff. Everything in Recommendation: #1 is a small patch and worth doing here. #2–#6 are fine as follow-ups; nothing blocks merge on correctness. |
| self[frames[m]] += count | ||
| totalSamples += count | ||
| } END { | ||
| for (f in self) printf "%s\t%d\t%.4f\n", f, self[f], self[f] * 100 / totalSamples |
There was a problem hiding this comment.
Low — every reporting subcommand aborts with an awk "division by zero" when no line carries a positive count.
totalSamples only accumulates the trailing integer, so a folded file whose counts are all 0 — or one truncated mid-write so the last field isn't a number — leaves it at 0, and this END divides by it. gawk and mawk both treat that as a fatal error, so the user gets a raw interpreter message rather than the clean require_file-style diagnostic that exists two functions down. total_time's END (L56) and, transitively, compare have the same shape.
The suite already builds exactly the fixture that trips it — zero.folded = .NET;Frame 0 in test_report_and_validator_reject_profiles_without_positive_samples — but only feeds it to the validator, never to top.
A guard in both END blocks costs one line:
| for (f in self) printf "%s\t%d\t%.4f\n", f, self[f], self[f] * 100 / totalSamples | |
| if (totalSamples == 0) { print "error: profile has no positive sample counts" > "/dev/stderr"; exit 1 } | |
| for (f in self) printf "%s\t%d\t%.4f\n", f, self[f], self[f] * 100 / totalSamples |
| leaf = frames[frame_count] | ||
| total += count | ||
| if (leaf ~ /\[[A-Za-z0-9_.-]+\][[:space:]].*::/) { | ||
| managed += count |
There was a problem hiding this comment.
Low — the managed-frame pattern is now duplicated, with nothing pinning the two copies together.
This is the good fix for last round's #3 — the gate now proves symbolization worked, and printing the split gives the reader the number AGENTS.md tells them to check first. One maintenance snag: the frame-format regex \[[A-Za-z0-9_.-]+\][[:space:]].*:: now exists twice, here and as NATIVE_FILTER in scripts/perf-report.sh:25.
That exact pattern is the one that was already wrong once (commit 3288549 fixed it against a real profile) and was widened a second time last round for generic instantiations. The next correction has to land in two files, and the tests cover each copy separately — test_native_view_excludes_generic_managed_frames and test_folded_profile_validator_requires_managed_samples_and_reports_leaf_split would both keep passing if only one were updated, and the failure mode is silent: a hard-failing gate that classifies a whole profile as unmanaged.
Cheapest fix that keeps the two honest is a test asserting the literals are identical — grep the pattern out of each file and assertEqual. A shared perf-frames.awk include would be cleaner but is more churn than the duplication warrants.
| line = $0 | ||
| dso = "" | ||
| if (match(line, /\([^)]*\)[[:space:]]*$/)) { | ||
| dso = substr(line, RSTART + 1, RLENGTH - 2) |
There was a problem hiding this comment.
Low — trailing whitespace on a frame line leaves a stray ) inside the DSO name.
The match pattern is \([^)]*\)[[:space:]]*$, so RLENGTH covers the parentheses plus any trailing whitespace, but RLENGTH - 2 assumes it covers only (…). With one trailing space the extracted text is libcoreclr.so) — the following sub(/[[:space:]]*$/, "", dso) strips the space but not the paren that shifted into the window, and the label renders as [unknown] (libcoreclr.so)).
Cosmetic in the common case, but it splits counts: the same DSO sampled on lines with and without trailing whitespace becomes two distinct [unknown] (…) frames, so a share that should read as one library is reported as two. Stripping first makes the arithmetic exact:
| dso = substr(line, RSTART + 1, RLENGTH - 2) | |
| sub(/[[:space:]]+$/, "", line) | |
| if (match(line, /\([^)]*\)$/)) { | |
| dso = substr(line, RSTART + 1, RLENGTH - 2) |
(and the sub(/[[:space:]]*$/, "", dso) two lines below becomes redundant.)
| <(self_time "$1" | LC_ALL=C sort -t$'\t' -k1,1) \ | ||
| <(self_time "$2" | LC_ALL=C sort -t$'\t' -k1,1) \ | ||
| | awk -F'\t' -v a="$(basename "$1")" -v b="$(basename "$2")" -v n="$n" ' | ||
| { delta = $3 - $2; printf "%s\t%.4f\t%.4f\t%.4f\n", $1, $2, $3, delta }' \ |
There was a problem hiding this comment.
Low — a and b are computed and passed into awk but never used, so the compare table never says which file is A.
Both -v a="$(basename "$1")" and -v b="$(basename "$2")" are bound on L109 and referenced nowhere; the header on L122 prints bare A % / B %. Every other subcommand puts the profile name in its title (… — $(basename "$1")), so compare is the one view where the output alone cannot tell you which direction a + delta points — which matters most here, since that sign is the whole answer.
Either use them or drop them:
| { delta = $3 - $2; printf "%s\t%.4f\t%.4f\t%.4f\n", $1, $2, $3, delta }' \ | |
| { delta = $3 - $2; printf "%s\t%.4f\t%.4f\t%.4f\n", $1, $2, $3, delta }' \ |
with the second awk taking -v a=… -v b=… and printing printf "\n Largest self-time shifts, %s -> %s (percentage points of profile)\n\n", a, b.
| self.assertEqual(commands[0], "stat --event cycles:u -- true") | ||
| self.assertIn("record --event cycles:u --freq 99 --call-graph fp --pid 4321", commands[1]) | ||
| self.assertIn( | ||
| ' perf record --event cycles:u --freq "$frequency" --call-graph fp --pid "$node_pid" \\\n' |
There was a problem hiding this comment.
Low — this assertion pins four lines of lib.sh byte-for-byte, including the line breaks and continuations.
The intent is right and worth keeping: prove perf record is not wrapped in sudo/as_root, because a wrapper would make $! the wrapper's PID and quietly break the identity tracking that the rest of this teardown depends on. But asserting the literal source text means any reflow — joining the continuations, reordering --freq before --event, reindenting — reds the job with no behavioral change, and the same assertion would pass if someone inserted sudo elsewhere in the function.
A narrower check on the same function body expresses the invariant directly and survives formatting:
recorder = re.search(r"(?ms)^start_perf_recorder\(\) \{.*?^\}", RPC_LIB.read_text(encoding="utf-8"))["0"]
self.assertRegex(recorder, r"(?m)^\s*perf record\b") # launched directly
self.assertNotRegex(recorder, r"\b(sudo|as_root)\b") # no wrapper between perf and $!
self.assertIn("PERF_RECORDER_PID=$!", recorder)The two behavioural halves of this test (the recorded argv, and the preflight running before any record) are the valuable part and need no change.
|
@claude re-review |
|
Claude finished @kamilchodola's task in 5m 31s —— View job Re-review: perf profiling modeReviewed the delta since the last pass (
VerdictThe delta is documentation-only and it closes last round's Medium. No Critical, High, or Medium. Four Lows, all new this round; nothing touches client code or benchmark timings. Prior finding — resolved
I checked each claim in the new section against the code rather than taking it on trust, and all seven hold: Findings
On #1 — the only one I'd fix while in here. It fails in the most expensive place: the fold is the last step after a full restore and benchmark run, and the dotTrace snapshot is precisely the fallback you want when perf symbolization didn't work. Reordering keeps the fail-closed behaviour (step still red) while the Still open from earlier rounds, unchanged and fine as follow-upsAll Low, all in the reader rather than the capture: the all-zero-count Not findings
Verification limitsStatic reading only — Unchanged from the last two rounds: the rpc-bench perf path still has no linked end-to-end run. The only verification run, 32536259998, is expb, whose capture lives in expb rather than in this diff. Everything in Recommendation: #1 is a small reorder and worth doing here; #2-#4 are fine as follow-ups. Nothing blocks merge on correctness. Note I can't push the workflow half of #1/#2 myself — GitHub App permissions exclude |
| if [[ "${PERF}" == "true" ]]; then | ||
| mapfile -t folded_profiles < <(find "${profiling_dirs[@]}" -type f -name 'perf.folded' -newer "${MARKER}" 2>/dev/null) | ||
| valid_folded_profiles=() | ||
| for folded_profile in "${folded_profiles[@]}"; do | ||
| if bash scripts/validate-folded-profile.sh "${folded_profile}"; then | ||
| valid_folded_profiles+=("${folded_profile}") | ||
| else | ||
| echo "::warning::Ignoring invalid perf.folded profile: ${folded_profile}" | ||
| fi | ||
| done | ||
| if [[ "${#valid_folded_profiles[@]}" -eq 0 ]]; then | ||
| echo "::error::perf was requested but no perf.folded profile with a positive sample count was produced." | ||
| exit 1 | ||
| fi | ||
| echo "Validated positive-sample perf.folded profile(s):" | ||
| printf ' %s\n' "${valid_folded_profiles[@]}" | ||
| fi | ||
|
|
||
| zip -9r "${archive}" "${profiling_dirs[@]}" -x '*/perf.data' |
There was a problem hiding this comment.
Low — on a dottrace=true perf=true run, an invalid fold discards the valid dotTrace snapshot too.
The perf gate exit 1s at L1294 before the zip at L1300, and the whole capture lives in one archive. So a combined run that produces a perfectly good .dtp (and .nettrace) but a perf.folded the validator rejects — no managed leaf samples, a truncated perf.data after a SIGKILLed recorder — throws the dotTrace half away as well. The Upload profiling artifact step then finds nothing and, with if-no-files-found: ignore (L1309), no-ops silently.
That's the expensive direction to fail in: the fold is the last thing that happens, after a full snapshot restore and benchmark run, and the dotTrace data is exactly what you'd fall back to when perf symbolization didn't work.
Zipping first keeps the fail-closed behaviour (the step still exits non-zero, the job still goes red) while the always() upload preserves what was actually captured:
| if [[ "${PERF}" == "true" ]]; then | |
| mapfile -t folded_profiles < <(find "${profiling_dirs[@]}" -type f -name 'perf.folded' -newer "${MARKER}" 2>/dev/null) | |
| valid_folded_profiles=() | |
| for folded_profile in "${folded_profiles[@]}"; do | |
| if bash scripts/validate-folded-profile.sh "${folded_profile}"; then | |
| valid_folded_profiles+=("${folded_profile}") | |
| else | |
| echo "::warning::Ignoring invalid perf.folded profile: ${folded_profile}" | |
| fi | |
| done | |
| if [[ "${#valid_folded_profiles[@]}" -eq 0 ]]; then | |
| echo "::error::perf was requested but no perf.folded profile with a positive sample count was produced." | |
| exit 1 | |
| fi | |
| echo "Validated positive-sample perf.folded profile(s):" | |
| printf ' %s\n' "${valid_folded_profiles[@]}" | |
| fi | |
| zip -9r "${archive}" "${profiling_dirs[@]}" -x '*/perf.data' | |
| if [[ "${PERF}" == "true" ]]; then | |
| mapfile -t folded_profiles < <(find "${profiling_dirs[@]}" -type f -name 'perf.folded' -newer "${MARKER}" 2>/dev/null) | |
| valid_folded_profiles=() | |
| for folded_profile in "${folded_profiles[@]}"; do | |
| if bash scripts/validate-folded-profile.sh "${folded_profile}"; then | |
| valid_folded_profiles+=("${folded_profile}") | |
| else | |
| echo "::warning::Ignoring invalid perf.folded profile: ${folded_profile}" | |
| fi | |
| done | |
| fi | |
| zip -9r "${archive}" "${profiling_dirs[@]}" -x '*/perf.data' | |
| # Fail after archiving: a bad fold must not discard a valid dotTrace snapshot | |
| # collected in the same run. | |
| if [[ "${PERF}" == "true" ]]; then | |
| if [[ "${#valid_folded_profiles[@]}" -eq 0 ]]; then | |
| echo "::error::perf was requested but no perf.folded profile with a positive sample count was produced." | |
| exit 1 | |
| fi | |
| echo "Validated positive-sample perf.folded profile(s):" | |
| printf ' %s\n' "${valid_folded_profiles[@]}" | |
| fi |
Applies to the benchmark-multi copy at L2482-2497 as well. (Note I can't push workflow edits myself — GitHub App permissions exclude .github/workflows.)
| echo "dottrace requires client=nethermind (dotTrace is .NET-specific)." | ||
| exit 1 | ||
| fi | ||
| if [[ "${perf}" == "true" && "${benchmark_tool}" == "jsonbench-sweep" ]]; then |
There was a problem hiding this comment.
Low — perf gets a resolve-time guard for the tool but not for the client, unlike dottrace.
Four lines above, dottrace refuses a non-Nethermind client at resolve time (L295-298). perf has the same restriction — start-node.sh:65 dies with "perf profiling is wired for CLIENT=nethermind (it needs the runtime perf map)", and the input description says "(nethermind only)" — but the check lives in the node script, which runs after the runner has been picked, the image pulled and the DB snapshot restored.
That's inconsistent with the direction the rest of this round went: require_perf_access was deliberately hoisted into a preflight step ahead of Ensure Docker is installed so a misconfigured runner fails in seconds. The client check is the same class of precondition and is one line here:
| if [[ "${perf}" == "true" && "${benchmark_tool}" == "jsonbench-sweep" ]]; then | |
| if [[ "${perf}" == "true" && "${benchmark_tool}" == "jsonbench-sweep" ]]; then | |
| echo "::error::perf=true is not supported with benchmark_tool=jsonbench-sweep. Use a single-node benchmark tool; sweep capture needs per-cell profile isolation." | |
| exit 1 | |
| fi | |
| if [[ "${perf}" == "true" && "${client}" != "nethermind" ]]; then | |
| echo "::error::perf=true requires client=nethermind (managed frames come from the runtime's perf map)." | |
| exit 1 | |
| fi |
(start-node.sh's check is still worth keeping as the direct-invocation guard.)
| perf_fail=1 | ||
| fi | ||
| fi | ||
| wait "$PERF_PID" 2>/dev/null || true |
There was a problem hiding this comment.
Low — this wait can never wait: the recorder is not a child of this shell.
perf record is backgrounded in start-node.sh; its PID travels here through node.env. By the time stop-node.sh runs, its parent has exited and the recorder has been reparented, so wait "$PERF_PID" returns immediately with "pid N is not a child of this shell" — swallowed by || true. It's a no-op on every path, including the one it looks like it protects (SIGINT sent, perf still writing out perf.data).
What actually guarantees the flush is the poll at L47-56, which breaks only once kill -0 fails — i.e. after the recorder has fully exited. That's correct, so this is dead code rather than a bug. The reason to remove it is that it reads as the flush guarantee, and the next person tuning the timeout may trim the loop believing wait backs it up.
| wait "$PERF_PID" 2>/dev/null || true | |
| # No `wait` here: the recorder was started by start-node.sh, so it is not a child | |
| # of this shell. The identity-checked poll above is what confirms it exited. |
| - **`jq`, `curl`, `git`**, **`python3` + `pip`** (flood; json-bench also renders | ||
| its benchmark config via `python3` + PyYAML), and the **.NET SDK** (only if | ||
| `/opt/dottrace` is not already installed by previous expb dotTrace runs). | ||
| - **Host `perf` and a root runner process** when using `perf: true`; `perf` must |
There was a problem hiding this comment.
Low — the new prerequisite is filed under an arm64-only heading, but perf runs on both boxes.
This section opens "The reproducible-benchmarks-arm self-hosted runner must provide:" (L517), while perf: true is available for arch=amd64 too — and amd64 is the default. As written, a reader provisioning the amd64 box has no reason to think the root requirement applies to them, which is the one prerequisite that turns a dispatch into an immediate die rather than a degraded run.
Cheapest fix is to say so in the bullet:
| - **Host `perf` and a root runner process** when using `perf: true`; `perf` must | |
| - **Host `perf` and a root runner process** on *either* runner when using | |
| `perf: true`; `perf` must be able to sample `cycles:u` (see | |
| [Linux perf flow](#linux-perf-flow)). |
Two smaller doc notes while you're in this file:
- The
Filestable (L539) still describesstop-node.shas "Graceful stop → collect logs + dotTrace → verify snapshot unchanged → tear down". It now also stops the recorder and folds the profile — and does so before the graceful stop, which is the non-obvious part worth a word. - The new section doesn't mention that a
comparisonrun profiles only the primary node (the reference instance is started withPERF: "false",run-rpc-benchmarks.yml:777). Anyone expecting two profiles from an A/B dispatch will look for the second one.
3 participants
Problem
dotTrace cannot see past a P/Invoke. Everything below the boundary collapses into a single
[Native or optimized code]node with no breakdown — on a recent snapshot that node was the third-largest entry in the whole profile (166s of own time, above every individual Nethermind frame). RocksDB, the allocator, memory zeroing, the JIT and the GC all land in there together, indistinguishable.Change
A
perfworkflow input that records a host-side Linux perf profile alongside the run, plusscripts/perf-report.shto read the result. perf walks one stack across the managed/native boundary — managed frames from the runtime's perf map, native frames from the container's shared objects — so that time is attributed per callee.No image change is needed: perf runs on the host and expb sets the perf-map environment on the client container (companion PR: execution-payloads-benchmarks#27).
perfis independent ofdottrace. Enabling both samples the process twice, which perturbs timings, so perf runs are for attribution and A/B numbers should come from dottrace-only or unprofiled runs. The Reporter XML job stays gated ondottracealone; only artifact collection was widened.Verification
Run 32536259998 on the arm64 runner with
perf=trueanddottrace=sampling— which also exercises the hardest path, perf locating the client PID underneath the dotTrace launcher. Artifact carriedperf.data(5.3MB, 14,344 samples),perf.folded(41MB) and the dotTrace.dtpand.nettracetogether.Symbolization on that profile:
[unknown]The residual is almost entirely the stripped
libcoreclr.soandlibrocksdb.soshipped in the image. So perf narrows dotTrace's opaque node to a named library plus a resolved majority; it does not eliminate it.What the profile actually attributes, split by thread — the capture covers every thread of the process, so this split matters before drawing conclusions:
Two readings that were invisible in dotTrace: 38% of process CPU was RocksDB background compaction, roughly half of it snappy, and secp256k1 recovery was ~11% of runtime-thread CPU. (Short 20-payload run, so the
libclrjitshare is inflated by startup JIT and none of this is a steady-state claim.)scripts/perf-report.shwas exercised on that profile and on synthetic fixtures across all four subcommands:top,total(inclusive time, verified summing correctly across shared prefixes),native,compare(recovers injected shifts exactly).Reading real data also caught two defects in the reader, fixed in the second commit: the managed-frame pattern assumed
Namespace.Methodwhere the perf map emits<ret> [Assembly] Type::Method(args), andheadunderpipefailmade every report exit 141.