From 39b2f1830f989421f588ea2e6ca5da8313718178 Mon Sep 17 00:00:00 2001 From: araq Date: Mon, 31 Aug 2026 20:30:36 +0200 Subject: [PATCH] IC: break down `processTopLevel`, and refute the obvious frontend win MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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. --- compiler/ast2nif.nim | 59 +++++++++++++++++++++++++++++++++++--------- compiler/bnode.nim | 27 ++++++++++++++++++++ compiler/icprof.nim | 7 ++++-- 3 files changed, 79 insertions(+), 14 deletions(-) diff --git a/compiler/ast2nif.nim b/compiler/ast2nif.nim index 869bfed12a..832d9de3b7 100644 --- a/compiler/ast2nif.nim +++ b/compiler/ast2nif.nim @@ -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 "" "") — 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) diff --git a/compiler/bnode.nim b/compiler/bnode.nim index 3c5ffb1298..3a3c310817 100644 --- a/compiler/bnode.nim +++ b/compiler/bnode.nim @@ -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` diff --git a/compiler/icprof.nim b/compiler/icprof.nim index 2410de2cbf..ff05b3e823 100644 --- a/compiler/icprof.nim +++ b/compiler/icprof.nim @@ -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 - ` 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