profiler documentation

doc/estp.txt

@@ -0,0 +1,180 @@
+============================================
+  Embedded Stack Trace Profiler User Guide
+============================================
+
+:Author: Andreas Rumpf
+:Version: |nimrodversion|
+
+
+Nimrod comes with a platform independent profiler -
+the `Embedded Stack Trace Profiler`:idx: (`ESTP`:idx:). The profiler 
+is *embedded* into your executable. To activate the profiler you need to do: 
+
+* compile your program with the ``--profiler:on --stackTrace:on`` command 
+  line options
+* import the ``nimprof`` module
+* run your program as usual.
+
+You can in fact look at ``nimprof``'s source code to see how to implement 
+your own profiler.
+
+The setting ``--profiler:on`` defines the conditional symbol ``profiler``.
+
+After your program has finished the profiler will create a 
+file ``profile_resultsX.txt``(where ``X`` is a previously unused number) 
+containing the profiling results.
+
+Since the profiler works by examining stack traces, it's essential that
+the option ``--stackTrace:on`` is active! Unfortunately this means that a 
+profiling build is much slower than a release build.
+
+
+Example results file
+====================
+
+The results file lists stack traces ordered by significance. 
+
+The following example file has been generated by profiling the Nimrod compiler
+itself: It shows that in total 4.1% of the runtime has been spent 
+in ``crcFromRope`` or its children.
+
+In general the stack traces show you immediately where the problem is because
+the trace acts like an explanation; in traditional profilers you can only find
+expensive leaf functions easily but the *reason* why they are invoked 
+often remains mysterious.
+
+::
+  total executions of each stack trace:
+  Entry: 0/3391 Calls: 84/4160 = 2.0% [sum: 84; 84/4160 = 2.0%]
+    newCrcFromRopeAux
+    crcFromRope
+    writeRopeIfNotEqual
+    shouldRecompile
+    writeModule
+    myClose
+    closePasses
+    processModule
+    CompileModule
+    CompileProject
+    CommandCompileToC
+    MainCommand
+    HandleCmdLine
+    nimrod
+  Entry: 1/3391 Calls: 46/4160 = 1.1% [sum: 130; 130/4160 = 3.1%]
+    updateCrc32
+    newCrcFromRopeAux
+    crcFromRope
+    writeRopeIfNotEqual
+    shouldRecompile
+    writeModule
+    myClose
+    closePasses
+    processModule
+    CompileModule
+    CompileProject
+    CommandCompileToC
+    MainCommand
+    HandleCmdLine
+    nimrod
+  Entry: 2/3391 Calls: 41/4160 = 0.99% [sum: 171; 171/4160 = 4.1%]
+    updateCrc32
+    updateCrc32
+    newCrcFromRopeAux
+    crcFromRope
+    writeRopeIfNotEqual
+    shouldRecompile
+    writeModule
+    myClose
+    closePasses
+    processModule
+    CompileModule
+    CompileProject
+    CommandCompileToC
+    MainCommand
+    HandleCmdLine
+    nimrod
+  Entry: 3/3391 Calls: 41/4160 = 0.99% [sum: 212; 212/4160 = 5.1%]
+    crcFromFile
+    writeRopeIfNotEqual
+    shouldRecompile
+    writeModule
+    myClose
+    closePasses
+    processModule
+    CompileModule
+    CompileProject
+    CommandCompileToC
+    MainCommand
+    HandleCmdLine
+    nimrod
+  Entry: 4/3391 Calls: 41/4160 = 0.99% [sum: 253; 253/4160 = 6.1%]
+    updateCrc32
+    crcFromFile
+    writeRopeIfNotEqual
+    shouldRecompile
+    writeModule
+    myClose
+    closePasses
+    processModule
+    CompileModule
+    CompileProject
+    CommandCompileToC
+    MainCommand
+    HandleCmdLine
+    nimrod
+  Entry: 5/3391 Calls: 32/4160 = 0.77% [sum: 285; 285/4160 = 6.9%]
+    pop
+    newCrcFromRopeAux
+    crcFromRope
+    writeRopeIfNotEqual
+    shouldRecompile
+    writeModule
+    myClose
+    closePasses
+    processModule
+    CompileModule
+    CompileProject
+    CommandCompileToC
+    MainCommand
+    HandleCmdLine
+    nimrod
+  Entry: 6/3391 Calls: 17/4160 = 0.41% [sum: 302; 302/4160 = 7.3%]
+    doOperation
+    forAllChildrenAux
+    pop
+    newCrcFromRopeAux
+    crcFromRope
+    writeRopeIfNotEqual
+    shouldRecompile
+    writeModule
+    myClose
+    closePasses
+    processModule
+    CompileModule
+    CompileProject
+    CommandCompileToC
+    MainCommand
+    HandleCmdLine
+    ...
+    nimrod
+  Entry: 7/3391 Calls: 14/4160 = 0.34% [sum: 316; 316/4160 = 7.6%]
+    Contains
+    isAccessible
+    interiorAllocatedPtr
+    gcMark
+    markStackAndRegisters
+    collectCTBody
+    collectCT
+    rawNewObj
+    newObj
+    newNode
+    copyTree
+    matchesAux
+    matches
+    resolveOverloads
+    semOverloadedCall
+    semOverloadedCallAnalyseEffects
+    ...
+    CommandCompileToC
+    MainCommand
+    HandleCmdLine

doc/tools.txt

@@ -15,3 +15,6 @@ The standard distribution ships with the following tools:
 
 - | `endb <endb.html>`_
   | Nimrod's slow platform independent embedded debugger.
+
+- | `estp <estp.html>`_
+  | Nimrod's slow platform independent embedded stack trace profiler.

lib/pure/nimprof.nim

@@ -87,6 +87,9 @@ proc getTotal(x: ref TProfileEntry): int =
 proc cmpEntries(a, b: ref TProfileEntry): int =
   result = b.getTotal - a.getTotal
 
+proc `//`(a, b: int): string =
+  result = format("$1/$2 = $3%", a, b, formatFloat(a / b * 100.0, ffDefault, 2))
+
 proc writeProfile() {.noconv.} =
   stopProfiling()
   const filename = "profile_results"
@@ -110,8 +113,8 @@ proc writeProfile() {.noconv.} =
       if profileData[i] != nil and profileData[i].total > 1:
         inc sum, profileData[i].total
         writeln(f, "Entry: ", i, "/", entries, " Calls: ",
-          profileData[i].total, "/", totalCalls, " [sum: ", sum, "; ",
-          formatFloat(sum / totalCalls * 100.0, ffDefault, 2), "%]")
+          profileData[i].total // totalCalls, " [sum: ", sum, "; ",
+          sum // totalCalls, "]")
         for ii in 0..high(TStackTrace):
           let procname = profileData[i].st[ii]
           if isNil(procname): break

lib/system/profiler.nim

@@ -77,9 +77,6 @@ proc setProfilingInterval*(intervalInUs: int): TNanos =
 
 var t0: TTicks
 
-var usefulCall* = 0
-var uselessCall* = 0
-
 proc nimProfile() =
   ## This is invoked by the compiler in every loop and on every proc entry!
   dec gTicker
@@ -87,7 +84,6 @@ proc nimProfile() =
     gTicker = -1
     let t1 = getticks()
     if getticks() - t0 > interval:
-      inc usefulCall
       if not isNil(profilerHook):
         # disable recursive calls: XXX should use try..finally,
         # but that's too expensive!
@@ -96,8 +92,6 @@ proc nimProfile() =
         callProfilerHook(oldHook)
         profilerHook = oldHook
       t0 = getticks()
-    else:
-      inc uselessCall
     gTicker = SamplingInterval
 
 proc stopProfiling*() =

web/news.txt

@@ -133,6 +133,7 @@ Compiler Additions
 - The compiler now supports the ``dynlib`` pragma for variables.
 - The compiler now supports ``bycopy`` and ``byref`` pragmas that affect how
   objects/tuples are passed.
+- The embedded profiler became a stack trace profiler and has been documented.
 
 
 Language Additions

web/nimrod.ini

@@ -22,7 +22,7 @@ file: ticker
 
 [Documentation]
 doc: "endb;intern;apis;lib;manual;tut1;tut2;nimrodc;overview;filters;trmacros"
-doc: "tools;c2nim;niminst;nimgrep;gc"
+doc: "tools;c2nim;niminst;nimgrep;gc;estp"
 pdf: "manual;lib;tut1;tut2;nimrodc;c2nim;niminst;gc"
 srcdoc: "core/macros;pure/marshal;core/typeinfo;core/unsigned"
 srcdoc: "impure/graphics;impure/re;pure/sockets"
@@ -44,6 +44,7 @@ srcdoc: "pure/collections/intsets;pure/collections/queues;pure/encodings"
 srcdoc: "pure/events;pure/collections/sequtils;pure/irc;ecmas/dom;pure/cookies"
 srcdoc: "pure/ftpclient;pure/memfiles;pure/subexes;pure/collections/critbits"
 srcdoc: "pure/asyncio;pure/actors;core/locks;pure/oids;pure/endians;pure/uri"
+srcdoc: "pure/nimprof"
 
 webdoc: "wrappers/libcurl;pure/md5;wrappers/mysql;wrappers/iup"
 webdoc: "wrappers/sqlite3;wrappers/postgres;wrappers/tinyc"