From dbaed3d38aaa91ab5cee33fa654ba1eeb847ceb0 Mon Sep 17 00:00:00 2001 From: araq Date: Sun, 30 Aug 2026 23:09:32 +0200 Subject: [PATCH] IC: measure the whole backend, and record where its time actually is MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The profiling added with the cursor path was local to `bnode`, so it could only answer questions about the cursor path. Moved to `compiler/icprof.nim` — no compiler imports, so any stage can use it without a cycle — and extended to the stage boundaries: the closure load and its three phases, `transformBody`, `handOffBody`, `genProcBody`. The budget that produces, on a cold `--ic:on` build of a 68-module target (10.1s wall, summed over 177 backend processes): loadDepClosure 3306ms of which moduleId 1285ms processTopLevel 1516ms interface tbls 1323ms genProcBody 333ms handOffBody 60ms transformBody 28ms This is worth having written down because it reprices the migration this branch is doing. Reading a routine body off a cursor rather than a tree is finished and costs nothing — `genProcBody` is the same either way. But FINISHING the job, reading a `.t.bif` body directly and never materialising the `PNode`, can only win back `handOffBody` + `transformBody`: under 1% of the build. The 41% is in getting the closure's INTERFACE into memory, which no amount of body-reading touches. The remaining blockers in `bnode`'s header — `TLoc.lode` above all, 72 call sites and hard, because a symbol's `loc.lode` outlives the body it was built in and `lode == nil` is a sentinel — are worth exactly that under 1% until something else changes. Said so in the header, replacing the older 0.20s/0.16s figures, since that paragraph is the map read first. The obvious lever on the real cost was tried and is not taken: `{SkipInterfaceTables}` for dep-of-a-dep loads in `loadDepClosure` builds and runs correctly but returns ~200ms, because most of that phase is the target and system modules rather than the transitive ones. Not worth a name that silently fails to resolve, so the flag stays restricted to `loadTransitiveHooks`. Verified: both configurations build; `tests/ic` 40/40; the instrumentation changes no codegen — 67/67 `.c` identical, cursor still identical to `PNode`. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01FMyRHByv7hhaQJ4Pa1bHbE --- compiler/ast2nif.nim | 7 ++++ compiler/bnode.nim | 91 ++++++++++++++--------------------------- compiler/cgen.nim | 2 + compiler/icprof.nim | 82 +++++++++++++++++++++++++++++++++++++ compiler/nifbackend.nim | 13 +++++- 5 files changed, 132 insertions(+), 63 deletions(-) create mode 100644 compiler/icprof.nim diff --git a/compiler/ast2nif.nim b/compiler/ast2nif.nim index f7f3df194e..86b02fc7eb 100644 --- a/compiler/ast2nif.nim +++ b/compiler/ast2nif.nim @@ -34,6 +34,7 @@ import "../dist/nimony/src/models" / nifindex_tags import typekeys import icnifcore import ic / [enum2nif] +import icprof const SysModuleSuffix* = "@sys" const BackendLocalMarker* = "@bk" @@ -4120,7 +4121,9 @@ proc registerModuleSelfSym*(c: var DecodeContext; suffix: string; m: PSym) = proc loadNifModule*(c: var DecodeContext; suffix: ModuleSuffix; interf, interfHidden: var TStrTable; flags: set[LoadFlag] = {}): PrecompiledModule = # Ensure module index is loaded - moduleId returns the FileIndex for this suffix + icProfStart(tModuleId) let module = moduleId(c, string(suffix), flags) + icProfStop(tModuleId) # Load the module AST (or just replay actions if loadFullAst is false). # processTopLevel also collects export instructions. Step 2 phase 2: read the @@ -4130,7 +4133,9 @@ proc loadNifModule*(c: var DecodeContext; suffix: ModuleSuffix; interf, interfHi if cur.kind == TagLit and tagIs(cur, toNifTag(nkStmtList)): inc cur # enter (stmts (past the tag head, onto the flags dot) skip cur # flags dot (processTopLevel skips the type dot itself) + icProfStart(tTopLevel) result = processTopLevel(c, cur, flags, interf, string(suffix), module.int) + icProfStop(tTopLevel) else: result = PrecompiledModule(topLevel: newNode(nkStmtList)) @@ -4138,7 +4143,9 @@ proc loadNifModule*(c: var DecodeContext; suffix: ModuleSuffix; interf, interfHi # Symbols are created as stubs (Partial state) and will be loaded lazily via loadSym # Use exports collected by processTopLevel if SkipInterfaceTables notin flags: + icProfStart(tInterfTables) populateInterfaceTablesFromIndex(c, module, interf, interfHidden, string(suffix)) + icProfStop(tInterfTables) proc loadNifModule*(c: var DecodeContext; f: FileIndex; interf, interfHidden: var TStrTable; flags: set[LoadFlag] = {}): PrecompiledModule = diff --git a/compiler/bnode.nim b/compiler/bnode.nim index 9fcec4d799..16fdd4e9cf 100644 --- a/compiler/bnode.nim +++ b/compiler/bnode.nim @@ -10,10 +10,32 @@ ## `BNode` — the backend's node type, and the seam for running codegen off a ## `.bif` `Cursor` instead of a deserialized `PNode` tree. ## -## Building those trees is the bulk of the `lower` and `cg` stages: their cost -## tracks the size of the dependency CLOSURE a stage loads, not the module it -## compiles (measured: a 370-byte module costs 0.20s/0.16s in lower/cg, the main -## module 3.40s/3.16s, and the two are ~85% of the serial backend critical path). +## A stage's cost tracks the size of the dependency CLOSURE it loads, not the +## module it compiles. That is why this seam exists — but WHERE the closure's +## cost sits has since been measured, and it is not where the seam can reach. +## On a cold `--ic:on` build of a 68-module target (10.1s wall, `-d:icBNodeProf`, +## `-d:icNoParallel`), summed over all 177 backend processes: +## +## loadDepClosure 3306ms of which moduleId 1285ms +## processTopLevel 1516ms +## interface tbls 1323ms +## genProcBody 333ms +## handOffBody 60ms <- the bridge encode +## transformBody 28ms +## +## So reading a routine body off a cursor instead of a tree is DONE and free — +## `genProcBody` costs the same either way (see "WHAT IT COSTS" below) — but +## finishing the job, i.e. reading a `.t.bif` body directly and never +## materialising the `PNode`, can only win back the `handOffBody` + +## `transformBody` line: under 1% of the build. The 41% is in getting the +## closure's INTERFACE into memory, which no amount of body-reading touches. +## (Skipping the interface tables for dep-of-a-dep loads was tried as the +## obvious lever and returns ~200ms, not enough to justify a name that silently +## fails to resolve; see `SkipInterfaceTables`, which stays restricted to +## `loadTransitiveHooks`.) +## +## Anyone about to spend a week on the remaining blockers below — `TLoc.lode` +## above all — should weigh them against that budget first. ## ## With `-d:newIcBackend` `BNode` is a `distinct Cursor`; without it a plain ## `PNode`, which is what every build does today. Codegen migrates to the @@ -243,63 +265,10 @@ import ast, lineinfos, idents -# ---- opt-in profiling (-d:icBNodeProf) -------------------------------------- -# Counts and coarse phase timings; the accessors are far too small to time -# individually. Each backend process appends one line to $NIM_IC_BNODE_PROF (or -# stderr) at exit, so a parallel build still produces attributable output. -when defined(icBNodeProf): - import std / [envvars, exitprocs, syncio, monotimes] - from std / times import inNanoseconds - - type - ProfSlot* = enum - pKind, pTagKindHit, pTagKindMiss, pAstChildren, pSkip, pSon, pLen, - pLastSon, pIterYield, pSym, pTyp, pTypTagLit, pOrigin, pNilType, - pGenBodyCalls, pInfo - TimeSlot* = enum tHandOff, tGenBody, tAnalyses, tSym, tTyp, tInfo, tOrigin - - var profCounts: array[ProfSlot, int] - var profNanos: array[TimeSlot, int64] - var profStart: array[TimeSlot, MonoTime] - var profArmed = false - - proc profDump() = - var line = "BNODEPROF" - for s in ProfSlot: line.add " " & ($s)[1..^1] & "=" & $profCounts[s] - for s in TimeSlot: line.add " " & ($s)[1..^1] & "ms=" & $(profNanos[s] div 1_000_000) - let f = getEnv("NIM_IC_BNODE_PROF") - if f.len > 0: - let h = open(f, fmAppend) - h.writeLine line - h.close() - else: - stderr.writeLine line - - template armProf() = - if not profArmed: - profArmed = true - addExitProc profDump - - template prof*(s: ProfSlot; n = 1) = - armProf() - inc profCounts[s], n - template icProfStart*(s: TimeSlot) = - armProf() - profStart[s] = getMonoTime() - template icProfStop*(s: TimeSlot) = - profNanos[s] += (getMonoTime() - profStart[s]).inNanoseconds - - template timed*(s: TimeSlot; body: untyped) = - ## Leaf-accessor timing. NOT re-entrant: `typ` reaches `sym`, so read those - ## two as overlapping rather than additive. - let t0 = getMonoTime() - body - profNanos[s] += (getMonoTime() - t0).inNanoseconds -else: - template prof*(s: untyped; n = 1) = discard - template icProfStart*(s: untyped) = discard - template icProfStop*(s: untyped) = discard - template timed*(s: untyped; body: untyped) = body +# Re-exported so `cgen`, which includes the `ccg*` files, gets the +# instrumentation along with the seam. +import icprof +export icprof when defined(newIcBackend): when defined(nimPreviewSlimSystem): diff --git a/compiler/cgen.nim b/compiler/cgen.nim index 5a7c97974b..5dd5075d8b 100644 --- a/compiler/cgen.nim +++ b/compiler/cgen.nim @@ -2092,9 +2092,11 @@ proc genProcLvl3*(m: BModule, prc: PSym) = when defined(newIcBackend): grindBNode(m, p, prc) let wasLoaded = m.config.cmd == cmdNifC and prc.transformedBody != nil + icProfStart(tTransform) var procBody = transformBody(m.g.graph, m.idgen, prc, {}) if sfInjectDestructors in prc.flags and not wasLoaded: procBody = injectDestructorCalls(m.g.graph, m.idgen, prc, procBody) + icProfStop(tTransform) # THE HANDOFF (`transf.handOffBody`). Rewriting is done for this body — # transformed, and destructor-injected when this process did the injecting — # so from here the reading side works off a cursor. diff --git a/compiler/icprof.nim b/compiler/icprof.nim new file mode 100644 index 0000000000..5edfaf102c --- /dev/null +++ b/compiler/icprof.nim @@ -0,0 +1,82 @@ +# +# +# The Nim Compiler +# (c) Copyright 2026 Andreas Rumpf +# +# See the file "copying.txt", included in this +# distribution, for details about the copyright. +# + +## Opt-in instrumentation for the IC backend, enabled with `-d:icBNodeProf`. +## Off, every template below is `discard` and nothing is linked in. +## +## It lives in its own module with NO compiler imports so that any stage can +## use it without creating a cycle — `bnode` needs it for the accessors, +## `nifbackend` for the stage phases, `cgen` for what happens per routine. +## +## Each backend process appends ONE line to `$NIM_IC_BNODE_PROF` at exit (or to +## stderr when that is unset), because a `--ic:on` build fans out a process per +## module per stage and interleaved writes would tear. Use `-d:icNoParallel` +## when the numbers need to be attributable to a particular module. +## +## Counts are for volume, timings for cost, and the two answer different +## questions: the accessors turned out to be 700k calls worth 8ms, while `info` +## was 259k calls worth 1.36s. Neither number alone would have found that. + +when defined(icBNodeProf): + import std / [envvars, exitprocs, syncio, monotimes] + from std / times import inNanoseconds + + type + ProfSlot* = enum + pKind, pTagKindHit, pTagKindMiss, pAstChildren, pSkip, pSon, pLen, + pLastSon, pIterYield, pSym, pTyp, pTypTagLit, pOrigin, pNilType, + pGenBodyCalls, pInfo + TimeSlot* = enum + tLoadClosure, tModuleId, tTopLevel, tInterfTables, + tTransform, tHandOff, tGenBody, tAnalyses, + tSym, tTyp, tInfo, tOrigin + + var profCounts: array[ProfSlot, int] + var profNanos: array[TimeSlot, int64] + var profStart: array[TimeSlot, MonoTime] + var profArmed = false + + proc profDump() = + var line = "BNODEPROF" + for s in ProfSlot: line.add " " & ($s)[1..^1] & "=" & $profCounts[s] + for s in TimeSlot: line.add " " & ($s)[1..^1] & "ms=" & $(profNanos[s] div 1_000_000) + let f = getEnv("NIM_IC_BNODE_PROF") + if f.len > 0: + let h = open(f, fmAppend) + h.writeLine line + h.close() + else: + stderr.writeLine line + + template armProf() = + if not profArmed: + profArmed = true + addExitProc profDump + + template prof*(s: ProfSlot; n = 1) = + armProf() + inc profCounts[s], n + template icProfStart*(s: TimeSlot) = + armProf() + profStart[s] = getMonoTime() + template icProfStop*(s: TimeSlot) = + profNanos[s] += (getMonoTime() - profStart[s]).inNanoseconds + + template timed*(s: TimeSlot; body: untyped) = + ## Leaf timing. NOT re-entrant, and the phase slots are not disjoint — + ## `tTransform` contains body materialization, `tTyp` reaches `tSym`. Read + ## them as nested, not additive. + let t0 = getMonoTime() + body + profNanos[s] += (getMonoTime() - t0).inNanoseconds +else: + template prof*(s: untyped; n = 1) = discard + template icProfStart*(s: untyped) = discard + template icProfStop*(s: untyped) = discard + template timed*(s: untyped; body: untyped) = body diff --git a/compiler/nifbackend.nim b/compiler/nifbackend.nim index 53c0f62abb..8c14f9e971 100644 --- a/compiler/nifbackend.nim +++ b/compiler/nifbackend.nim @@ -28,6 +28,7 @@ import ast, options, lineinfos, modulegraphs, cgendata, cgen, from cgmeth import generateIfMethodDispatchers from transf import transformBody from injectdestructors import injectDestructorCalls +import icprof import ic / replayer proc systemNifSuffix(conf: ConfigRef): string = @@ -387,7 +388,11 @@ proc generateLowerStage(g: ModuleGraph; mainFileIdx: FileIndex) = return target = findTargetModule(g, modules, precompSys, g.config.icBackendModule) else: - (modules, precompSys, target) = loadDepClosure(g, g.config.icBackendModule) + (modules, precompSys, target) = block: + icProfStart(tLoadClosure) + let r = loadDepClosure(g, g.config.icBackendModule) + icProfStop(tLoadClosure) + r if target.module == nil: rawMessage(g.config, errGenerated, "per-module lowering: module not found for suffix: " & g.config.icBackendModule) @@ -538,7 +543,11 @@ proc generateCgStage(g: ModuleGraph; mainFileIdx: FileIndex) = else: # No whole-program load, hence no whole-program DCE: the target emits its # full demanded closure and the merge stage drops what is globally dead. - (modules, precompSys, target) = loadDepClosure(g, g.config.icBackendModule) + (modules, precompSys, target) = block: + icProfStart(tLoadClosure) + let r = loadDepClosure(g, g.config.icBackendModule) + icProfStop(tLoadClosure) + r if target.module == nil: rawMessage(g.config, errGenerated, "per-module codegen: module not found for suffix: " & g.config.icBackendModule)