utils/profiling/README

   1 Profiling Notion:
   2
   3 Because Notion is not CPU-bound, and we want to optimize for low latencies,
   4 if we do any profiling/tracing we'll want to perform those in 'real', 'wall
   5 clock' time, not CPU time.
   6
   7 All linux profiling tools I've found either measure CPU time rather than real
   8 time, or work based on SIGALRM (google perftools) which does not appear to
   9 work for us. There's generally 2 ways to do real time profiling: stack sampling
  10 and tracing. I'm not sure how we could implement sampling. Tracing can be
  11 accomplished with the GCC '-finstrument-functions' feature.
  12
  13 This only traces the C side of things. We don't get much insight in the lua
  14 part of the code (yet).
  15
  16 == Enabling (compile-time) ==
  17
  18 To enable tracing, add to your system-local.mk:
  19
  20   CFLAGS += -finstrument-functions -g -DPROFILING_ENABLED
  21   LDFLAGS += -g
  22
  23 == Starting/stopping (run-time) ==
  24
  25 You can start/stop tracing with the methods in ioncore/profiling.h
  26
  27 == Shared libraries ==
  28
  29 Unfortunately, it seems like you cannot profile shared libraries this way,
  30 or something needs to be fixed in order for that to work. Our modules are
  31 loaded as shared libraries by default.
  32
  33 For now, to profile our modules too, preload the modules:
  34
  35 PRELOAD_MODULES=1
  36 X11_LIBS += -lXinerama -lXrandr
  37
  38 == Interpreting the trace output ==
  39
  40 This will generate a trace file showing records like this:
  41
  42 e 0x809ccd1 0x809d4ed 1345834871.209096315
  43 e 0x809d580 0xb7e2e1b7 1345834871.209104766
  44 e 0x80a005e 0x809d5d5 1345834871.209112658
  45 x 0x80a005e 0x809d5d5 1345834871.209121598
  46 x 0x809d580 0xb7e2e1b7 1345834871.209129211
  47 | |         |          |          |-- timestamp (nanosecond part)
  48 | |         |          |-- timestamp (second part)
  49 | |         |-- source address of the call
  50 | |- Function being called
  51 |-- 'Entry' or 'eXit' record
  52
  53 To convert the addresses of functions and call sites to human-readable form,
  54 use the 'addr2line.pl' script:
  55
  56 $ utils/profiling/addr2line.pl `which notion` < trace > trace-humanreadable
  57
  58 The result will contain some 'noise' caused by libextl which can be removed
  59 with:
  60
  61 $ ./utils/profiling/filterinternal.pl < trace-humanreadable > trace-humanreadable-filtered
  62
  63 This will be better, but you'll miss some 'exit' tracepoints because lua
  64 doesn't emit events for tail calls. To add them back:
  65
  66 $ ./utils/profiling/addtailcalls.pl < trace-humanreadable-filtered > trace-humanreadable-filtered-balanced
  67
  68 To view this trace in kcachegrind, use the prof2callgrind tool. This tool
  69 can basically convert any file format consisting of entry/exit records with
  70 filenames, line numbers and timestamps.
  71
  72 It currently ignores the source address of the call, making it a bit less
  73 exact and a bit more flexible to use.
  74
  75 $ utils/profiling/prof2callgrind.pl < trace-filtered-balanced > trace-callgrind
  76
  77 Or all in two lines:
  78
  79 $ ./utils/profiling/addr2line.pl `which notion` < trace | ./utils/profiling/filterinternal.pl  | ./utils/profiling/addtailcalls.pl | ./utils/profiling/prof2callgrind.pl > kcg
  80 $ kcachegrind kcg