mirror of
https://github.com/nim-lang/Nim.git
synced 2026-09-02 20:03:45 +00:00
3f014bbd37
The frontend was the one phase with no timers inside it — 180 processes
and 9.9s of Atlas's cold build, entirely opaque. `tStage` around
`commandCheck` and `tWriteNif` around `writeNifModule` close that, and
with the loading slots ast2nif already had, a `nim m` process is now
fully accounted:
startup (exec+runtime+config) 0.17 s 2%
loading imported `.s.bif` 4.57 s 46%
writing this module's `.s.bif` 1.84 s 18%
sem + parse 3.41 s 34%
Two thirds of the frontend is artifact I/O, not compilation. That is the
per-module model's structural cost: 180 processes each rebuild their
imports' interfaces from nothing.
One part of it is not structural at all. `interfHidden` accounts for
1.05s of the loading: 1.70M hidden-symbol stubs against 0.29M exported
ones, built by every `nim m` for every module it imports. The table is
reached ONLY through `modulegraphs.interfSelect` with `optImportHidden`,
and that flag is set in exactly one place — an `import x {.all.}`. The
backend already skips building it for this reason; the frontend cannot
skip it unconditionally, but it does not have to build it eagerly either.
Measured with a probe rather than estimated: skipping it takes
`InterfTables` 1161ms -> 80ms, the frontend 9.98s -> 8.93s, and the whole
Atlas build 22.19s -> 20.47s wall.
Not taking it in this commit. The correct form is lazy population on
first `interfSelect(true)` — deciding up front cannot work, because a
macro-generated `{.all.}` import is invisible syntactically and guessing
wrong loses symbols silently. `loaderCtx` is the hook (the module index
survives in the DecodeContext), but this is symbol visibility, and it
deserves its own pass rather than the tail of a long one.
`bnode.nim` carries the numbers and the design note. All behind
`-d:icBNodeProf`. ic 41/41, `koch boot -d:release` equal executables.
107 lines
4.4 KiB
Nim
107 lines
4.4 KiB
Nim
#
|
|
#
|
|
# 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, pIfaceExported, pIfaceHidden, pIfaceModules,
|
|
pTopNodes, pExportSyms, pPeekKind, pPeekFallback, pPeekLoaded
|
|
TimeSlot* = enum
|
|
tLoadClosure, tModuleId, tBifLoad, tPosIndex, tTopLevel, tInterfTables,
|
|
tTransform, tHandOff, tGenBody, tAnalyses,
|
|
tSym, tTyp, tInfo, tOrigin, tExportBranch, tResolveSym, tEnumFields,
|
|
# Coarse phases, added to find where a backend process spends the time
|
|
# that none of the slots above account for. `tStage` is the whole stage
|
|
# body, so `Process - tStage` is everything before it: exec, the Nim
|
|
# runtime, config replay, `registerNifSuffix`/graph setup.
|
|
tStage,
|
|
tLowerOwned, tLowerHooks, tLowerWrite,
|
|
tCgGen, tCgInit, tCgFinish, tCgWrite,
|
|
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
|
|
|
|
let procStart = getMonoTime()
|
|
## Set when this module initialises, i.e. essentially at process start, so
|
|
## the dump can report total process wall time and the startup share can be
|
|
## derived as `Process - Stage`.
|
|
|
|
var profStageName* = "frontend"
|
|
## Which invocation this is: the backend stage name, or "frontend" for a
|
|
## `nim m` process, which arms the profiler through ast2nif but never enters
|
|
## a backend stage. Without it the `Process - Stage` startup figure is
|
|
## meaningless — 204 frontend processes' whole runtime lands in it.
|
|
|
|
var profCounts: array[ProfSlot, int]
|
|
var profNanos: array[TimeSlot, int64]
|
|
var profStart: array[TimeSlot, MonoTime]
|
|
var profArmed = false
|
|
|
|
proc profDump() =
|
|
var line = "BNODEPROF stage=" & profStageName
|
|
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)
|
|
line.add " Processms=" & $((getMonoTime() - procStart).inNanoseconds 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
|