IC: break down processTopLevel, and refute the obvious frontend win

The frontend's loading is 3.55s of Atlas's 9.2s and had no breakdown
finer than "TopLevel 1459ms". Now it does — `tTopReplay`, `tTopLogOps`,
`tTopOffers`, `tTopStmts` and a counter for the records the loader
skips:

    TopLevel 1459ms = Offers 569 + ExportBranch 312 + LogOps 137
                      + the bare cursor walk ~371 + Replay/Stmts ~11

That immediately suggests a target, and it is a trap. 80% of every
module header the loader walks is tooling-only records — `sig`, one per
signature-symbol occurrence, plus `expansion`/`modulesrc` — which it
skips on sight and which exist only for `idetools`: 3.36M of 4.19M nodes
on Atlas. Grouping them under one tag, or moving them past the
`(implementation)` marker where the loop stops, is an easy change and
buys nothing.

Probed before building any of it, by emitting none of them at all:

    nodes walked  4.19M -> 0.85M      .s.bif    44.7MB -> 44.0MB
    TopLevel      1459ms -> 1406ms    frontend  9.29s  -> 9.18s

Walking 3.3M records costs 53ms. `skip` on a `TagLit` is a jump, not a
scan — about 16ns a node — so the count was never the cost. A format
change for 0.5% would have been a bad trade discovered late.

What is left is the per-process re-load itself: 180 `nim m` each parsing
~20 modules' interfaces out of 44.7MB of `.s.bif`, with no dominant item
because there is no single item. It is the amortisation problem batching
already solved for the backend (`loadDepClosure` 10.2s -> 1.3s), and the
frontend is where it has not been solved.

Behind `-d:icBNodeProf`. ic 42/42, `koch boot -d:release` equal
executables.
This commit is contained in:
araq
2026-08-31 20:30:36 +02:00
parent c6f70374bc
commit 39b2f1830f
3 changed files with 79 additions and 14 deletions

View File

@@ -4182,11 +4182,13 @@ proc processTopLevel(c: var DecodeContext; cur: var Cursor; flags: set[LoadFlag]
case topTagAt(cur)
of ttReplay:
# Always load replay actions (macro cache operations)
icProfStart(tTopReplay)
cur.into:
while cur.hasMore:
let replayNode = loadNode(c, cur, suffix, localSyms)
if replayNode != nil:
result.topLevel.sons.add replayNode
icProfStop(tTopReplay)
of ttUnusedId:
# backend id seed — consumed eagerly by `moduleId`/`readUnusedId`; just
# skip past it here so the rest of the header still loads.
@@ -4197,18 +4199,42 @@ proc processTopLevel(c: var DecodeContext; cur: var Cursor; flags: set[LoadFlag]
result.moduleFlags = int32 intVal(cur)
skip cur
while cur.hasMore: skip cur
of ttRepConverter: loadLogOp(c, result.logOps, cur, ConverterEntry, attachedTrace, module)
of ttRepDestroy: loadLogOp(c, result.logOps, cur, HookEntry, attachedDestructor, module)
of ttRepWasMoved: loadLogOp(c, result.logOps, cur, HookEntry, attachedWasMoved, module)
of ttRepCopy: loadLogOp(c, result.logOps, cur, HookEntry, attachedAsgn, module)
of ttRepSink: loadLogOp(c, result.logOps, cur, HookEntry, attachedSink, module)
of ttRepDup: loadLogOp(c, result.logOps, cur, HookEntry, attachedDup, module)
of ttRepTrace: loadLogOp(c, result.logOps, cur, HookEntry, attachedTrace, module)
of ttRepDeepCopy: loadLogOp(c, result.logOps, cur, HookEntry, attachedDeepCopy, module)
of ttRepEnumToStr: loadLogOp(c, result.logOps, cur, EnumToStrEntry, attachedTrace, module)
of ttRepMethod: loadLogOp(c, result.logOps, cur, MethodEntry, attachedTrace, module)
of ttRepPureEnum: loadLogOp(c, result.logOps, cur, PureEnumEntry, attachedTrace, module)
of ttRepCppMember: loadLogOp(c, result.logOps, cur, CppMemberEntry, attachedTrace, module)
of ttRepConverter:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, ConverterEntry, attachedTrace, module)
of ttRepDestroy:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, HookEntry, attachedDestructor, module)
of ttRepWasMoved:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, HookEntry, attachedWasMoved, module)
of ttRepCopy:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, HookEntry, attachedAsgn, module)
of ttRepSink:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, HookEntry, attachedSink, module)
of ttRepDup:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, HookEntry, attachedDup, module)
of ttRepTrace:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, HookEntry, attachedTrace, module)
of ttRepDeepCopy:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, HookEntry, attachedDeepCopy, module)
of ttRepEnumToStr:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, EnumToStrEntry, attachedTrace, module)
of ttRepMethod:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, MethodEntry, attachedTrace, module)
of ttRepPureEnum:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, PureEnumEntry, attachedTrace, module)
of ttRepCppMember:
timed tTopLogOps:
loadLogOp(c, result.logOps, cur, CppMemberEntry, attachedTrace, module)
of ttExport:
if SkipInterfaceTables in flags:
# Same reason the interface tables are skipped: `interf` is a scratch
@@ -4261,6 +4287,7 @@ proc processTopLevel(c: var DecodeContext; cur: var Cursor; flags: set[LoadFlag]
var cts: seq[PType] = @[]
var idx = 0
var ok = true
icProfStart(tTopOffers)
cur.into:
while cur.hasMore:
if cur.kind == Symbol:
@@ -4278,12 +4305,14 @@ proc processTopLevel(c: var DecodeContext; cur: var Cursor; flags: set[LoadFlag]
else: skip cur
if ok and genSym != nil and instSym != nil:
result.genericOffers.add (genSym, instSym, cts, paramsCount)
icProfStop(tTopOffers)
of ttTOffer:
# (toffer "<genericBodySym>" "<instType>") — intern the two full names,
# resolve, FULLY load the instance (so `searchInstTypes` can match its
# params). Best-effort: a failure to resolve drops the offer.
var genName, instName = ""
var idx = 0
icProfStart(tTopOffers)
cur.into:
while cur.hasMore:
if cur.kind == StrLit:
@@ -4298,15 +4327,19 @@ proc processTopLevel(c: var DecodeContext; cur: var Cursor; flags: set[LoadFlag]
if genSym != nil and inst != nil:
loadType(c, inst)
result.typeOffers.add (genSym, inst)
icProfStop(tTopOffers)
of ttModuleSrc:
prof pTopToolingSkip
# self-identification record for the standalone include-graph scanner;
# not needed by the loader, just skip past it.
skip cur
of ttExpansion:
prof pTopToolingSkip
# template/macro expansion usage record for tooling (`idetools` scans it
# as a `Symbol` use); the loader itself needs nothing from it.
skip cur
of ttSig:
prof pTopToolingSkip
# signature-symbol occurrence record for tooling (`idetools` scans it as a
# `Symbol` use); the loader itself needs nothing from it.
skip cur
@@ -4319,9 +4352,11 @@ proc processTopLevel(c: var DecodeContext; cur: var Cursor; flags: set[LoadFlag]
# `{.push/pop.}` around it) must reach the `cg` stage's genPragma/genEmit,
# else e.g. a `#include` is dropped and the generated C won't compile.
# writeToplevelNode routes these into this header section.
icProfStart(tTopStmts)
let stmtNode = loadNode(c, cur, suffix, localSyms)
if stmtNode != nil:
result.topLevel.sons.add stmtNode
icProfStop(tTopStmts)
of ttOther:
if LoadFullAst in flags:
let stmtNode = loadNode(c, cur, suffix, localSyms)

View File

@@ -164,6 +164,33 @@
## grow `g.ifaces`, which would leave a `var` alias into it dangling).
## `tests/ic/timporthidden.nim` is what says all of this still holds.
##
## THE FRONTEND'S LOADING, after the `interfHidden` fix above, is 3.55s of
## Atlas's 9.2s frontend and it is NOT concentrated anywhere:
##
## BifLoad 695ms PosIndex 519ms ModuleId 841ms InterfTables 80ms
## TopLevel 1459ms = Offers 569 + ExportBranch 312 + LogOps 137
## + the bare cursor walk ~371 + Replay/Stmts ~11
##
## Two candidates inside it were probed and only one paid:
##
## * hidden interface stubs — 1.05s, taken (see above).
## * the tooling-only header records (`sig`, one per signature-symbol
## occurrence, plus `expansion`/`modulesrc`). These are 80% of every header
## the loader walks: 3.36M of 4.19M nodes on Atlas, skipped immediately,
## existing only for `idetools`. Grouping or relocating them looks like an
## obvious win and IS NOT ONE. Emitting none of them at all: nodes walked
## 4.19M -> 0.85M, `.s.bif` 44.7MB -> 44.0MB, `TopLevel` 1459ms -> 1406ms,
## the frontend 9.29s -> 9.18s. Walking 3.3M records costs 53ms, because
## `skip` on a `TagLit` is a jump, not a scan — about 16ns a node. Measured
## with a probe before anything was built, which is the only reason no
## format change was made for 0.5%.
##
## What is left is the per-process re-load itself: 180 `nim m` processes each
## parsing ~20 modules' interfaces out of 44.7MB of `.s.bif`. No single item
## dominates because there is no single item — it is the same amortisation
## problem batching solved for the backend (`loadDepClosure` 10.2s -> 1.3s), and
## the frontend is where it has not been solved yet.
##
## THE C COMPILER is the largest CPU item of a cold Atlas build and the smallest
## wall lever, which is worth writing down so nobody spends a week on it. gcc is
## 12.2s of CPU against a whole-program build's 10.2s — but `callCCompiler`

View File

@@ -32,7 +32,8 @@ when defined(icBNodeProf):
pKind, pTagKindHit, pTagKindMiss, pAstChildren, pSkip, pSon, pLen,
pLastSon, pIterYield, pSym, pTyp, pTypTagLit, pOrigin, pNilType,
pGenBodyCalls, pInfo, pIfaceExported, pIfaceHidden, pIfaceModules,
pTopNodes, pExportSyms, pPeekKind, pPeekFallback, pPeekLoaded
pTopNodes, pExportSyms, pPeekKind, pPeekFallback, pPeekLoaded,
pTopToolingSkip
TimeSlot* = enum
tLoadClosure, tModuleId, tBifLoad, tPosIndex, tTopLevel, tInterfTables,
tTransform, tHandOff, tGenBody, tAnalyses,
@@ -47,7 +48,9 @@ when defined(icBNodeProf):
tMergeStage, tEmitRender, tLinkStage,
# `nim m` (the frontend): the sem pass as a whole, and writing the module's
# `.s.bif`. `Stage - WriteNif - <the loading slots>` is then sem proper.
tWriteNif
tWriteNif,
# `processTopLevel`'s branches: which part of a module HEADER costs what.
tTopReplay, tTopLogOps, tTopOffers, tTopStmts
let procStart = getMonoTime()
## Set when this module initialises, i.e. essentially at process start, so