VM profiler (#14833)

* Crude VM profiler

* Added --profileVM flag, refactoring

* fixed FileLine hash

* Use TLineInfo instead of own FileLine, updated formatting

* Refactoring, moved PStackFrame to vmdefs for cleaner data structure

* Moved vmprofiler to separate file

* Simplified TLineInfo hash, use toFileLineCol for output

* Hash

* Moved profile data into Config, dump only once at end of run

* Changed profile output header to show '#instr' instead of 'count'

* Do not accumulate instrcount for non-top frames

Co-authored-by: Ico Doornekamp <git@zevv.nl>

8 files changed, 86 insertions, 15 deletions

diff --git a/compiler/commands.nim b/compiler/commands.nim
index 95df45ebe..cbf93238f 100644
--- a/compiler/commands.nim
+++ b/compiler/commands.nim
@@ -884,6 +884,8 @@ proc processSwitch*(switch, arg: string, pass: TCmdLinePass, info: TLineInfo;
       localError(conf, info, "unknown Nim version; currently supported values are: {1.0}")
   of "benchmarkvm":
     processOnOffSwitchG(conf, {optBenchmarkVM}, arg, pass, info)
+  of "profilevm":
+    processOnOffSwitchG(conf, {optProfileVM}, arg, pass, info)
   of "sinkinference":
     processOnOffSwitch(conf, {optSinkInference}, arg, pass, info)
   of "panics":
diff --git a/compiler/lineinfos.nim b/compiler/lineinfos.nim
index 378e06c72..c9821ac9f 100644
--- a/compiler/lineinfos.nim
+++ b/compiler/lineinfos.nim
@@ -10,7 +10,7 @@
 ## This module contains the ``TMsgKind`` enum as well as the
 ## ``TLineInfo`` object.
 
-import ropes, tables, pathutils
+import ropes, tables, pathutils, hashes
 
 const
   explanationsBaseUrl* = "https://nim-lang.github.io/Nim"
@@ -271,6 +271,9 @@ type
 
 proc `==`*(a, b: FileIndex): bool {.borrow.}
 
+proc hash*(i: TLineInfo): Hash =
+  hash (i.line.int, i.col.int, i.fileIndex.int)
+
 proc raiseRecoverableError*(msg: string) {.noinline.} =
   raise newException(ERecoverableError, msg)
 
diff --git a/compiler/main.nim b/compiler/main.nim
index 25a42300f..256ec14cd 100644
--- a/compiler/main.nim
+++ b/compiler/main.nim
@@ -19,7 +19,7 @@ import
   cgen, json, nversion,
   platform, nimconf, passaux, depends, vm, idgen,
   modules,
-  modulegraphs, tables, rod, lineinfos, pathutils
+  modulegraphs, tables, rod, lineinfos, pathutils, vmprofiler
 
 when not defined(leanCompiler):
   import jsgen, docgen, docgen2
@@ -404,6 +404,8 @@ proc mainCommand*(graph: ModuleGraph) =
     else:
       output = $conf.absOutFile
     if optListFullPaths notin conf.globalOptions: output = output.AbsoluteFile.extractFilename
+    if optProfileVM in conf.globalOptions:
+      echo conf.dump(conf.vmProfileData)
     rawMessage(conf, hintSuccessX, [
       "loc", loc,
       "sec", sec,
diff --git a/compiler/options.nim b/compiler/options.nim
index 247f35419..80881d903 100644
--- a/compiler/options.nim
+++ b/compiler/options.nim
@@ -9,7 +9,7 @@
 
 import
   os, strutils, strtabs, sets, lineinfos, platform,
-  prefixmatches, pathutils, nimpaths
+  prefixmatches, pathutils, nimpaths, tables
 
 from terminal import isatty
 from times import utc, fromUnix, local, getTime, format, DateTime
@@ -95,6 +95,7 @@ type                          # please make sure we have under 32 options
     optPanics                 # turn panics (sysFatal) into a process termination
     optNimV1Emulation         # emulate Nim v1.0
     optSourcemap
+    optProfileVM              # enable VM profiler
 
   TGlobalOptions* = set[TGlobalOption]
 
@@ -217,6 +218,13 @@ type
     version*: int
   Suggestions* = seq[Suggest]
 
+  ProfileInfo* = object
+    time*: float
+    count*: int
+
+  ProfileData* = ref object
+    data*: TableRef[TLineInfo, ProfileInfo]
+
   ConfigRef* = ref object ## every global configuration
                           ## fields marked with '*' are subject to
                           ## the incremental compilation mechanisms
@@ -314,6 +322,7 @@ type
     structuredErrorHook*: proc (config: ConfigRef; info: TLineInfo; msg: string;
                                 severity: Severity) {.closure, gcsafe.}
     cppCustomNamespace*: string
+    vmProfileData*: ProfileData
 
 proc assignIfDefault*[T](result: var T, val: T, def = default(T)) =
   ## if `result` was already assigned to a value (that wasn't `def`), this is a noop.
@@ -390,6 +399,9 @@ template newPackageCache*(): untyped =
                  else:
                    modeCaseSensitive)
 
+proc newProfileData(): ProfileData =
+  ProfileData(data: newTable[TLineInfo, ProfileInfo]())
+
 proc newConfigRef*(): ConfigRef =
   result = ConfigRef(
     selectedGC: gcRefc,
@@ -442,6 +454,7 @@ proc newConfigRef*(): ConfigRef =
     arguments: "",
     suggestMaxResults: 10_000,
     maxLoopIterationsVM: 10_000_000,
+    vmProfileData: newProfileData(),
   )
   setTargetFromSystem(result.target)
   # enable colors by default on terminals
diff --git a/compiler/vm.nim b/compiler/vm.nim
index 5d8d21bb9..1edcace82 100644
--- a/compiler/vm.nim
+++ b/compiler/vm.nim
@@ -16,7 +16,7 @@ import
   strutils, msgs, vmdef, vmgen, nimsets, types, passes,
   parser, vmdeps, idents, trees, renderer, options, transf, parseutils,
   vmmarshal, gorgeimpl, lineinfos, tables, btrees, macrocacheimpl,
-  modulegraphs, sighashes, int128
+  modulegraphs, sighashes, int128, vmprofiler
 
 from semfold import leValueConv, ordinalValToString
 from evaltempl import evalTemplate
@@ -27,17 +27,6 @@ const
 when hasFFI:
   import evalffi
 
-type
-  PStackFrame* = ref TStackFrame
-  TStackFrame* = object
-    prc: PSym                 # current prc; proc that is evaluated
-    slots: seq[TFullReg]      # parameters passed to the proc + locals;
-                              # parameters come first
-    next: PStackFrame         # for stacking
-    comesFrom: int
-    safePoints: seq[int]      # used for exception handling
-                              # XXX 'break' should perform cleanup actions
-                              # What does the C backend do for it?
 
 proc stackTraceAux(c: PCtx; x: PStackFrame; pc: int; recursionLimit=100) =
   if x != nil:
@@ -552,6 +541,8 @@ proc rawExecute(c: PCtx, start: int, tos: PStackFrame): TFullReg =
         "ra", regDescr("ra", ra), "rb", regDescr("rb", instr.regB),
         "rc", regDescr("rc", instr.regC)]
 
+    c.profiler.enter(c, tos)
+
     case instr.opcode
     of opcEof: return regs[ra]
     of opcRet:
@@ -2077,6 +2068,8 @@ proc rawExecute(c: PCtx, start: int, tos: PStackFrame): TFullReg =
         if regs[ra].node.strVal.isNil: regs[ra].node.strVal = newStringOfCap(1000)
       storeAny(regs[ra].node.strVal, typ, regs[rb].regToNode, c.config)
 
+    c.profiler.leave(c)
+
     inc pc
 
 proc execute(c: PCtx, start: int): PNode =
diff --git a/compiler/vmdef.nim b/compiler/vmdef.nim
index 7b51c626d..9228ce5eb 100644
--- a/compiler/vmdef.nim
+++ b/compiler/vmdef.nim
@@ -261,6 +261,21 @@ type
     config*: ConfigRef
     graph*: ModuleGraph
     oldErrorCount*: int
+    profiler*: Profiler
+
+  PStackFrame* = ref TStackFrame
+  TStackFrame* = object
+    prc*: PSym                 # current prc; proc that is evaluated
+    slots*: seq[TFullReg]      # parameters passed to the proc + locals;
+                              # parameters come first
+    next*: PStackFrame         # for stacking
+    comesFrom*: int
+    safePoints*: seq[int]      # used for exception handling
+                              # XXX 'break' should perform cleanup actions
+                              # What does the C backend do for it?
+  Profiler* = object
+    tEnter*: float
+    tos*: PStackFrame
 
   TPosition* = distinct int
 
diff --git a/compiler/vmprofiler.nim b/compiler/vmprofiler.nim
new file mode 100644
index 000000000..57a0430b4
--- /dev/null
+++ b/compiler/vmprofiler.nim
@@ -0,0 +1,42 @@
+
+import
+  options, vmdef, times, lineinfos, strutils, tables,
+  msgs
+  
+proc enter*(prof: var Profiler, c: PCtx, tos: PStackFrame) {.inline.} =
+  if optProfileVM in c.config.globalOptions:
+    prof.tEnter = cpuTime()
+    prof.tos = tos
+
+proc leave*(prof: var Profiler, c: PCtx) {.inline.} =
+  if optProfileVM in c.config.globalOptions:
+    let tLeave = cpuTime()
+    var tos = prof.tos
+    var data = c.config.vmProfileData.data
+    while tos != nil:
+      if tos.prc != nil:
+        let li = tos.prc.info
+        if li notin data:
+          data[li] = ProfileInfo()
+        data[li].time += tLeave - prof.tEnter
+        if tos == prof.tos:
+          inc data[li].count
+      tos = tos.next
+
+proc dump*(conf: ConfigRef, pd: ProfileData): string =
+  var data = pd.data
+  echo "\nprof:     µs    #instr  location"
+  for i in 0..<32:
+    var tMax: float
+    var infoMax: ProfileInfo
+    var flMax: TLineInfo
+    for fl, info in data:
+      if info.time > infoMax.time:
+        infoMax = info
+        flMax = fl
+    if infoMax.count == 0:
+      break
+    result.add  "  " & align($int(infoMax.time * 1e6), 10) &
+                       align($int(infoMax.count), 10) & "  " &
+                       conf.toFileLineCol(flMax) & "\n"
+    data.del flMax
diff --git a/doc/advopt.txt b/doc/advopt.txt
index f5b8c9ec9..547005485 100644
--- a/doc/advopt.txt
+++ b/doc/advopt.txt
@@ -150,5 +150,6 @@ Advanced options:
                             works better with `--stackTrace:on`
                             see also https://nim-lang.github.io/Nim/estp.html
   --benchmarkVM:on|off      enable benchmarking of VM code with cpuTime()
+  --profileVM:on|off        enable compile time VM profiler
   --sinkInference:on|off    en-/disable sink parameter inference (default: on)
   --panics:on|off           turn panics into process terminations (default: off)