summary refs log tree commit diff stats
path: root/lib/pure/nimprof.nim
blob: 3598cdd3ad1db4c3b3f8b865ca60df95e238ccea (plain) (blame)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
pre { line-height: 125%; }
td.linenos .normal { color: inherit; background-color: transparent; padding-left: 5px; padding-right: 5px; }
span.linenos { color: inherit; background-color: transparent; padding-left: 5px; padding-right: 5px; }
td.linenos .special { color: #000000; background-color: #ffffc0; padding-left: 5px; padding-right: 5px; }
span.linenos.special { color: #000000; background-color: #ffffc0; padding-left: 5px; padding-right: 5px; }
.highlight .hll { background-color: #ffffcc }
.highlight .c { color: #888888 } /* Comment */
.highlight .err { color: #a61717; background-color: #e3d2d2 } /* Error */
.highlight .k { color: #008800; font-weight: bold } /* Keyword */
.highlight .ch { color: #888888 } /* Comment.Hashbang */
.highlight .cm { color: #888888 } /* Comment.Multiline */
.highlight .cp { color: #cc0000; font-weight: bold } /* Comment.Preproc */
.highlight .cpf { color: #888888 } /* Comment.PreprocFile */
.highlight .c1 { color: #888888 } /* Comment.Single */
.highlight .cs { color: #cc0000; font-weight: bold; background-color: #fff0f0 } /* Comment.Special */
.highlight .gd { color: #000000; background-color: #ffdddd } /* Generic.Deleted */
.highlight .ge { font-style: italic } /* Generic.Emph */
.highlight .ges { font-weight: bold; font-style: italic } /* Generic.EmphStrong */
.highlight .gr { color: #aa0000 } /* Generic.Error */
.highlight .gh { color: #333333 } /* Generic.Heading */
.highlight .gi { color: #000000; background-color: #ddffdd } /* Generic.Inserted */
.highlight .go { color: #888888 } /* Generic.Output */
.highlight .gp { color: #555555 } /* Generic.Prompt */
.highlight .gs { font-weight: bold } /* Generic.Strong */
.highlight .gu { color: #666666 } /* Generic.Subheading */
.highlight .gt { color: #aa0000 } /* Generic.Traceback */
.highlight .kc { color: #008800; font-weight: bold } /* Keyword.Constant */
.highlight .kd { color: #008800; font-weight: bold } /* Keyword.Declaration */
.highlight .kn { color: #008800; font-weight: bold } /* Keyword.Namespace */
.highlight .kp { color: #008800 } /* Keyword.Pseudo */
.highlight .kr { color: #008800; font-weight: bold } /* Keyword.Reserved */
.highlight .kt { color: #888888; font-weight: bold } /* Keyword.Type */
.highlight .m { color: #0000DD; font-weight: bold } /* Literal.Number */
.highlight .s { color: #dd2200; background-color: #fff0f0 } /* Literal.String */
.highlight .na { color: #336699 } /* Name.Attribute */
.highlight .nb { color: #003388 } /* Name.Builtin */
.highlight .nc { color: #bb0066; font-weight: bold } /* Name.Class */
.highlight .no { color: #003366; font-weight: bold } /* Name.Constant */
.highlight .nd { color: #555555 } /* Name.Decorator */
.highlight .ne { color: #bb0066; font-weight: bold } /* Name.Exception */
.highlight .nf { color: #0066bb; font-weight: bold } /* Name.Function */
.highlight .nl { color: #336699; font-style: italic } /* Name.Label */
.highlight .nn { color: #bb0066; font-weight: bold } /* Name.Namespace */
.highlight .py { color: #336699; font-weight: bold } /* Name.Property */
.highlight .nt { color: #bb0066; font-weight: bold } /* Name.Tag */
.highlight .nv { color: #336699 } /* Name.Variable */
.highlight .ow { color: #008800 } /* Operator.Word */
.highlight .w { color: #bbbbbb } /* Text.Whitespace */
.highlight .mb { color: #0000DD; font-weight: bold } /* Literal.Number.Bin */
.highlight .mf { color: #0000DD; font-weight: bold } /* Literal.Number.Float */
.highlight .mh { color: #0000DD; font-weight: bold } /* Literal.Number.Hex */
.highlight .mi { color: #0000DD; font-weight: bold } /* Literal.Number.Integer */
.highlight .mo { color: #0000DD; font-weight: bold } /* Literal.Number.Oct */
.highlight .sa { color: #dd2200; background-color: #fff0f0 } /* Literal.String.Affix */
.highlight .sb { color: #dd2200; background-color: #fff0f0 } /* Literal.String.Backtick */
.highlight .sc { color: #dd2200; background-color: #fff0f0 } /* Literal.String.Char */
.highlight .dl { color: #dd2200; background-color: #fff0f0 } /* Literal.String.Delimiter */
.highlight .sd { color: #dd2200; background-color: #fff0f0 } /* Literal.String.Doc */
.highlight .s2 { color: #dd2200; background-color: #fff0f0 } /* Literal.String.Double */
.highlight .se { color: #0044dd; background-color: #fff0f0 } /* Literal.String.Escape */
.highlight .sh { color: #dd2200; background-color: #fff0f0 } /* Literal.String.Heredoc */
.highlight .si { color: #3333bb; background-color: #fff0f0 } /* Literal.String.Interpol */
.highlight .sx { color: #22bb22; background-color: #f0fff0 } /* Literal.String.Other */
.highlight .sr { color: #008800; background-color: #fff0ff } /* Literal.String.Regex */
.highlight .s1
#
#
#            Nim's Runtime Library
#        (c) Copyright 2012 Andreas Rumpf
#
#    See the file "copying.txt", included in this
#    distribution, for details about the copyright.
#

## Profiling support for Nim. This is an embedded profiler that requires
## ``--profiler:on``. You only need to import this module to get a profiling
## report at program exit.

when not defined(profiler) and not defined(memProfiler):
  {.warning: "Profiling support is turned off!".}

# We don't want to profile the profiling code ...
{.push profiler: off.}

import hashes, algorithm, strutils, tables, sets

when not defined(memProfiler):
  include "system/timers"

const
  withThreads = compileOption("threads")
  tickCountCorrection = 50_000

when not declared(system.TStackTrace):
  type TStackTrace = array [0..20, cstring]

# We use a simple hash table of bounded size to keep track of the stack traces:
type
  TProfileEntry = object
    total: int
    st: TStackTrace
  TProfileData = array [0..64*1024-1, ptr TProfileEntry]

proc `==`(a, b: TStackTrace): bool =
  for i in 0 .. high(a):
    if a[i] != b[i]: return false
  result = true

# XXX extract this data structure; it is generally useful ;-)
# However a chain length of over 3000 is suspicious...
var
  profileData: TProfileData
  emptySlots = profileData.len * 3 div 2
  maxChainLen = 0
  totalCalls = 0

when not defined(memProfiler):
  var interval: TNanos = 5_000_000 - tickCountCorrection # 5ms

  proc setSamplingFrequency*(intervalInUs: int) =
    ## set this to change the sampling frequency. Default value is 5ms.
    ## Set it to 0 to disable time based profiling; it uses an imprecise
    ## instruction count measure instead then.
    if intervalInUs <= 0: interval = 0
    else: interval = intervalInUs * 1000 - tickCountCorrection

when withThreads:
  import locks
  var
    profilingLock: TLock

  initLock profilingLock

proc hookAux(st: TStackTrace, costs: int) =
  # this is quite performance sensitive!
  when withThreads: acquire profilingLock
  inc totalCalls
  var last = high(st)
  while last > 0 and isNil(st[last]): dec last
  var h = hash(pointer(st[last])) and high(profileData)

  # we use probing for maxChainLen entries and replace the encountered entry
  # with the minimal 'total' value:
  if emptySlots == 0:
    var minIdx = h
    var probes = maxChainLen
    while probes >= 0:
      if profileData[h].st == st:
        # wow, same entry found:
        inc profileData[h].total, costs
        return
      if profileData[minIdx].total < profileData[h].total:
        minIdx = h
      h = ((5 * h) + 1) and high(profileData)
      dec probes
    profileData[minIdx].total = costs
    profileData[minIdx].st = st
  else:
    var chain = 0
    while true:
      if profileData[h] == nil:
        profileData[h] = cast[ptr TProfileEntry](
                             allocShared0(sizeof(TProfileEntry)))
        profileData[h].total = costs
        profileData[h].st = st
        dec emptySlots
        break
      if profileData[h].st == st:
        # wow, same entry found:
        inc profileData[h].total, costs
        break
      h = ((5 * h) + 1) and high(profileData)
      inc chain
    maxChainLen = max(maxChainLen, chain)
  when withThreads: release profilingLock

when defined(memProfiler):
  const
    SamplingInterval = 50_000
  var
    gTicker {.threadvar.}: int

  proc hook(st: TStackTrace, size: int) {.nimcall.} =
    if gTicker == 0:
      gTicker = -1
      when defined(ignoreAllocationSize):
        hookAux(st, 1)
      else:
        hookAux(st, size)
      gTicker = SamplingInterval
    dec gTicker

else:
  var
    t0 {.threadvar.}: TTicks

  proc hook(st: TStackTrace) {.nimcall.} =
    if interval == 0:
      hookAux(st, 1)
    elif getTicks() - t0 > interval:
      hookAux(st, 1)
      t0 = getTicks()

proc getTotal(x: ptr TProfileEntry): int =
  result = if isNil(x): 0 else: x.total

proc cmpEntries(a, b: ptr 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.} =
  when declared(system.TStackTrace):
    system.profilerHook = nil
  const filename = "profile_results.txt"
  echo "writing " & filename & "..."
  var f: File
  if open(f, filename, fmWrite):
    sort(profileData, cmpEntries)
    writeln(f, "total executions of each stack trace:")
    var entries = 0
    for i in 0..high(profileData):
      if profileData[i] != nil: inc entries

    var perProc = initCountTable[string]()
    for i in 0..entries-1:
      var dups = initSet[string]()
      for ii in 0..high(TStackTrace):
        let procname = profileData[i].st[ii]
        if isNil(procname): break
        let p = $procname
        if not containsOrIncl(dups, p):
          perProc.inc(p, profileData[i].total)

    var sum = 0
    # only write the first 100 entries:
    for i in 0..min(100, entries-1):
      if profileData[i].total > 1:
        inc sum, profileData[i].total
        writeln(f, "Entry: ", i+1, "/", entries, " Calls: ",
          profileData[i].total // totalCalls, " [sum: ", sum, "; ",
          sum // totalCalls, "]")
        for ii in 0..high(TStackTrace):
          let procname = profileData[i].st[ii]
          if isNil(procname): break
          writeln(f, "  ", procname, " ", perProc[$procname] // totalCalls)
    close(f)
    echo "... done"
  else:
    echo "... failed"

var
  disabled: int

proc disableProfiling*() =
  when declared(system.TStackTrace):
    atomicDec disabled
    system.profilerHook = nil

proc enableProfiling*() =
  when declared(system.TStackTrace):
    if atomicInc(disabled) >= 0:
      system.profilerHook = hook

when declared(system.TStackTrace):
  system.profilerHook = hook
  addQuitProc(writeProfile)

{.pop.}