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)