[wontfix] [profiling] provide good support for valgrind's callgrind

[timotheecour]

[Please don't close as "not Nim problem; won't fix", at least not before some discussion]

motivation

valgrind's callgrind likely offers the most accurate profiling results, eg see: http://gernotklingler.com/blog/gprof-valgrind-gperftools-evaluation-tools-application-level-cpu-profiling-linux/
, at the expense of large slowdown eg 50x.
In short, it uses valgrind's VM with JIT recompilation of x86 => RISC-like Ucode.
IMO we should have a good support for it, as it can inform us more accurately than other tools about nim compiler (or any other nim program)'s actual hotspots, which is important when optimizing code (eg helps avoiding blindly optimizing stuff that's not actual hotspot). For nim itself, that means: making nim compiler faster!

While I'm making some improvements to --profile:on (eg #10119), I'm not yet convinced Nim profiling story starts and ends with --profile:on until I can at least compare results with valgrind's callgrind, for several reasons:

• (most important point) really not clear how accurate are results given its sampling strategy:

These calls are injected at every loop end (except perhaps loops that have no side-effects). At every Nth call a stack trace is taken.

• no wall/cpu time info generated by nimprof
• not sure how well it supports shared libraries / syscalls (not clear from https://nim-lang.github.io/Nim/estp.html)
• not sure how well it works with recursive calls given that it reports stacktraces
• stdlib has a few {.push profiler: off.} here and there that could affect profiling results

Besides accuracy, valgrind's callgrind has other advantages:

• works without needing recompilation with specially instrumented profiling code (maybe just needs --passC:-g, but that's less intrusive, and IIUC, optional)
• kcachegrind for visualization
• many more features
• nimprof shows stacktraces instead of a callgraph, which has pros and cons, but oftentimes callgraph may be more useful

callgrind usage example

# note that `--passC:-g` isn't required, but helps, since it shows debugging info
nim c --passC:-g main.nim
valgrind --tool=callgrind ./main
# inspect callgrind.out.$pid using text editor or kcachegrind or `callgrind_annotate callgrind.out.$pid` (see [1])

callgrind issues

• would be nice to have tooling to convert callgrind_annotate (see [1]) to Nim source code(with line info and un-mangled name, IIRC there was some filename generated by some tool (?) that generated a mapping bw mangled Nim names and C names); EDIT: probably --genMapping
• valgrind --tool=callgrind nim c main.nim fails with : see [2] [wontfix] [profiling] provide good support for valgrind's callgrind #10121 (comment)
  Note that it works with some other programs built by nim, just not nim itself

links

• https://nim-lang.github.io/Nim/estp.html
• http://gernotklingler.com/blog/gprof-valgrind-gperftools-evaluation-tools-application-level-cpu-profiling-linux/

[1] example output with callgrind_annotate

... other info
10,198,980,164  build/nimcache/timn_t0088.c:nimFrame [/Users/timothee/git_clone//nim//timn//bugs/all/t0088]
 5,249,475,000  build/nimcache/timn_t0088.c:fun_BlHd55MPDKaD6djg1BFZKw [/Users/timothee/git_clone//nim//timn//bugs/all/t0088]
 4,500,450,000  build/nimcache/timn_t0088.c:addInt [/Users/timothee/git_clone//nim//timn//bugs/all/t0088]
 3,899,610,000  build/nimcache/timn_t0088.c:pluseq__7kHiltrvRlcg6wSYR3CxAwt0088 [/Users/timothee/git_clone//nim//timn//bugs/all/t0088]
 3,024,705,957  ???:exp$fenv_access_off [/usr/lib/system/libsystem_m.dylib]
 2,399,760,040  build/nimcache/timn_t0088.c:popFrame [/Users/timothee/git_clone//nim//timn//bugs/all/t0088]
 2,300,310,108  build/nimcache/timn_t0088.c:main_JpOAt9ckLsMzNQ7rIf9bUW9bw [/Users/timothee/git_clone//nim//timn//bugs/all/t0088]
 1,150,155,054  build/nimcache/timn_t0088.c:main2_JpOAt9ckLsMzNQ7rIf9bUW9bw_2 [/Users/timothee/git_clone//nim//timn//bugs/all/t0088]

[timotheecour]

[2] (linked from top post)

==44029== For interactive control, run 'callgrind_control -h'.
--44029-- UNKNOWN fcntl 98!
--44029-- UNKNOWN fcntl 98! (repeated 2 times)
--44029-- UNKNOWN fcntl 98! (repeated 4 times)
--44029-- UNKNOWN fcntl 98! (repeated 8 times)
--44029-- UNKNOWN fcntl 98! (repeated 16 times)
--44029-- UNKNOWN fcntl 98! (repeated 32 times)
--44029-- WARNING: unhandled amd64-darwin syscall: mach:50
--44029-- You may be able to write your own handler.
--44029-- Read the file README_MISSING_SYSCALL_OR_IOCTL.
--44029-- Nevertheless we consider this a bug.  Please report
--44029-- it at http://valgrind.org/support/bug_reports.html.
eq_SyscallStatus:
  {78 0 43}
  {78 0 40}

valgrind: m_syswrap/syswrap-main.c:438 (Bool eq_SyscallStatus(UInt, SyscallStatus *, SyscallStatus *)): the 'impossible' happened.

host stacktrace:
==44029==    at 0x258024285: ???
==44029==    by 0x2580245F4: ???
==44029==    by 0x2580245D7: ???
==44029==    by 0x25809F774: ???
==44029==    by 0x25809EC33: ???
==44029==    by 0x25809D11A: ???
==44029==    by 0x25809B938: ???
==44029==    by 0x2580AC2CF: ???

sched status:
  running_tid=1

Thread 1: status = VgTs_Runnable (lwpid 771)
==44029==    at 0x100547D02: thread_get_special_reply_port (in /usr/lib/system/libsystem_kernel.dylib)
==44029==    by 0x1005F5AB9: xpc_pipe_routine (in /usr/lib/system/libxpc.dylib)
==44029==    by 0x1005F58C4: _xpc_interface_routine (in /usr/lib/system/libxpc.dylib)
==44029==    by 0x1005F54A3: bootstrap_look_up3 (in /usr/lib/system/libxpc.dylib)
==44029==    by 0x1005F52FC: bootstrap_look_up2 (in /usr/lib/system/libxpc.dylib)
==44029==    by 0x10052C1B4: _notify_fork_child (in /usr/lib/system/libsystem_notify.dylib)
==44029==    by 0x100232DCE: _dispatch_client_callout (in /usr/lib/system/libdispatch.dylib)
==44029==    by 0x100234514: _dispatch_once_callout (in /usr/lib/system/libdispatch.dylib)
==44029==    by 0x10052C181: _notify_fork_child (in /usr/lib/system/libsystem_notify.dylib)
==44029==    by 0x10052ABC2: notify_set_state (in /usr/lib/system/libsystem_notify.dylib)
==44029==    by 0x100528977: notify_register_check (in /usr/lib/system/libsystem_notify.dylib)
==44029==    by 0x1003910E6: notify_register_tz (in /usr/lib/system/libsystem_c.dylib)
==44029==    by 0x100390A68: tzsetwall_basic (in /usr/lib/system/libsystem_c.dylib)
==44029==    by 0x1000014DE: PreMainInner (in /Users/timothee/.nimble//bin/nim)
==44029==    by 0x100001A03: main (in /Users/timothee/.nimble//bin/nim)


Note: see also the FAQ in the source distribution. It contains workarounds to several common problems. In particular, if Valgrind aborted or crashed after identifying problems in your program, there's a good chance that fixing those problems will prevent Valgrind aborting or crashing, especially if it happened in m_mallocfree.c.  If that doesn't help, please report this bug to: www.valgrind.org  In the bug report, send all the above text, the valgrind version, and what OS and version you are using.  Thanks. 

EDIT: just filed upstream bug for valgrind: https://bugs.kde.org/show_bug.cgi?id=402696

[Araq]

[Please don't close as "not Nim problem; won't fix", at least not before some discussion]

Aww.

[timotheecour]

well I fixed the main blocker for using valgrind/callgrind in #10124 ;
the remaining would improve usability but is not a blocker, if you feel strongly about closing, go ahead, otherwise I'd like to keep it open for tracking remaining point;

For the remaining point (un-mangling mangled nim symbols appearing in callgrind.out.$pid), I was hoping to use --genMapping unfortunately it doesn't seem to work (blocked by #1592); and PR #9992 is furthermore aiming at removing it altogether...
(note that this need for demangling applies to other tools as well, eg OSX sample etc)

EDIT: looks like it could be ndi files, eg /Users/timothee/.cache/nim/t10137_d/system.ndi ;
this seems to require --debugger:native ; I'm curious whether it's an acceptable solution in case we want to profile an optimized build, given that --debugger:native may affect performance characteristics and show skewed performance bottlenecks