mirror of
https://github.com/nim-lang/Nim.git
synced 2026-09-01 19:33:42 +00:00
IC: measure the whole backend, and record where its time actually is
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 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FMyRHByv7hhaQJ4Pa1bHbE
This commit is contained in:
araq
@@ -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 =
|
||||
|
||||
@@ -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):
|
||||
|
||||
@@ -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.
|
||||
|
||||
82
compiler/icprof.nim
Normal file
82
compiler/icprof.nim
Normal file
@@ -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
|
||||
@@ -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)
|
||||
|
||||
Reference in New Issue
Block a user