Callchain Capture and Analysis with PmcTools
Callchain capture is an experimental feature in the PmcTools toolset. You will need to apply the following patch against -CURRENT, before you can try it out: http://people.freebsd.org/~jkoshy/download/pmctools-callgraph-patch.gz
Introduction
With this patch, at the time of a PMC interrupt, hwpmc(4) will record a caller information from the stack in addition to the interrupted PC value.
In this wiki page we will take a brief look at the new information this feature can provide. We will also examine the shortcomings of the current set of heuristics used by tools.
How to capture callchains
pmcstat(8) will configure sampling PMCs to capture callchains by default, so you do not need to do anything special to turn this feature on.
The new -N option to pmcstat(8) turns off callchain capture for the times you prefer 'flat' profiles.
For example, to allocate system-wide sampling PMCs that count "instructions retired" on all CPUs of your system, use:
# pmcstat -S instructions -O sample.out
Analysis
The information captured in the log can be post-processed by pmcstat. Two kinds of summaries can be generated:
A callchain summary that summarizes frequently sampled functions and their callers. Callchain summaries are requested using the new -G option.
Traditional gprof(1) compatible gmon.out files can also be generated. gmon.out output is specified using the -g option.
An Example
The samples for this example were collected during a short interval (10 seconds) while the system was executing a make buildworld.
The Callchain Summary
The command pmcstat -R sample.out -G cc-summary-file generates a callchain summary.
# cat cc-summary-file @ p4-instr-retired [95282 samples] 03.10% [2951] fnmatch1 @ /usr/bin/ld 98.58% [2909] fnmatch 01.42% [42] fnmatch1
The first line of the summary informs us that the log file had 95282 valid samples for PMC event "p4-instr-retired".
The most frequently sampled function was fnmatch1 in executable /usr/bin/ld, with 2951 samples out of the total. Function fnmatch, in the same executable object, was the most frequent caller of function fnmatch1.
The next most frequent samples fell in function Buf_AddByte in executable /home/obj/home/fcpi/src/make.i386/make:
02.30% [2194] Buf_AddByte @ /home/obj/home/fcpi/src/make.i386/make 45.81% [1005] Parse_File 17.01% [171] ReadMakefile 87.72% [150] TryReadMakefile 12.28% [21] main 26.66% [585] Var_SubstOnly 22.22% [130] For_Run 100.0% [130] parse_for 12.40% [272] parse_for 99.26% [270] Parse_File 100.0% [270] ReadMakefile 04.79% [105] CondGetArg 89.52% [94] CondToken 100.0% [94] CondT ...output snipped for brevity...
The callchain summary is sorted with the most frequently sampled locations and their locations first.
Traditional gprof(1) style profiles
The -g option to pmcstat(8) turns on gmon.out generation:
# pmcstat -R sample.out -g
You would then run gprof(1) on the generated gmon.out files as before:
# gprof /usr/bin/ld p4-instr-retired/ld.gmon > ld.gprof # gprof /boot/kernel/kernel p4-instr-retired/kernel.gmon > kernel.gprof # gprof /lib/libc.so.7 p4-instr-retired/libc.so.7.gmon > libc.gprof
Lets take a look at what the kernel was doing:
# cat kernel.gprof
...header snipped...
called/total parents
index %time self descendents called+self name index
called/total children
<spontaneous>
[1] 24.7 64.00 2696.05 syscall [1]
1.00 1476.19 37/37 stat [7]
1.00 655.74 1/1 open [18]
0.00 204.05 72/72 execve [39]
2.00 129.17 2/2 read [57]
0.00 61.12 4/4 lstat [102]
0.00 32.95 1/1 mkdir [155]
0.00 27.99 2/2 unlink [165]
1.00 20.70 2/2 write [193]
0.00 16.52 1/1 fstatfs [231]
1.00 14.20 2/2 munmap [238]
1.00 12.31 1/1 sigaction [248]
12.60 0.00 7/10 generic_copyout [215]
2.00 8.00 1/1 fstat [269]
7.64 0.88 2/11 userret [126]
4.86 0.00 1/7 sched_userret [149]
0.00 2.13 1/1 getdirentries [422]As to be expected, gprof(1) has propagated most of the samples to function syscall.
<spontaneous> [2] 21.0 2348.00 0.00 sse2_pagezero [2]
2348 samples fell into sse2_pagezero. However, hwpmc(4) was not able to trace the call stack further.
0.60 25.96 1/87 kern_rmdir [166]
0.60 25.96 1/87 kern_execve [60]
0.60 25.96 1/87 kern_unlink [164]
0.60 25.96 1/87 kern_lstat [159]
0.60 25.96 1/87 lstat [102]
0.60 25.96 1/87 vn_open [21]
0.60 25.96 1/87 kern_chown [171]
0.60 25.96 1/87 elf32_load_file [170]
0.60 25.96 1/87 kern_mkdir [154]
1.20 51.92 2/87 kern_readlink [118]
1.20 51.92 2/87 kern_access [108]
12.55 545.17 21/87 vn_open_cred [22]
31.68 1375.90 53/87 kern_stat [8]
[3] 20.7 52.00 2258.56 87 namei [3]
282.00 1747.26 132/132 lookup [4]
2.12 69.18 3/41 VOP_LOOKUP_APV [10]
3.53 33.70 7/131 vput [16]
7.43 25.85 4/7 vrele [110]
27.33 5.28 18/27 uma_zfree_arg [123]
19.11 5.46 8/18 uma_zalloc_arg [115]
2.60 13.92 1/52 _vn_lock [12]
0.00 9.50 1/1 VOP_READLINK_APV [272]
0.29 1.31 1/17 vfs_busy [168]
1.50 0.00 1/2 compute_cn_lkflags [375]
1.18 0.00 1/39 critical_enter [127]Here's what ld was doing:
# cat ld.gprof
...header snipped...
18 map_input_to_output_sections [1]
[1] 86.9 1.00 6079.64 0+18 map_input_to_output_sections [1]
0.00 6079.64 67/67 walk_wild [2]
18 map_input_to_output_sections [1]
-----------------------------------------------
0.00 6079.64 67/67 map_input_to_output_sections [1]
[2] 86.9 0.00 6079.64 67 walk_wild [2]
12.00 6012.36 1742/1742 walk_wild_file [3]
16.88 31.33 17/1840 fnmatch [5]
0.33 3.49 1/21 bfd_check_format [20]
0.08 3.17 1/1818 walk_wild_section [4]
-----------------------------------------------
12.00 6012.36 1742/1742 walk_wild [2]
[3] 86.1 12.00 6012.36 1742 walk_wild_file [3]
138.92 5765.95 1817/1818 walk_wild_section [4]
6.67 69.78 20/21 bfd_check_format [20]
22.18 0.00 4/11 strcmp [25]
5.00 0.00 5/610 wildcardp [7]
0.95 2.91 1/20 bfd_check_format_matches [21]
...output snipped...And libc.so.7:
# cat libc.so.7.gmon
...header snipped...
<spontaneous>
[1] 95.0 1.00 3167.77 regcomp [1]
382.00 2785.77 1/1 regexec [2]
-----------------------------------------------
1 regexec [2]
382.00 2785.77 1/1 regcomp [1]
[2] 95.0 382.00 2785.77 1+1 regexec [2]
2643.00 25.37 1618/1618 fgetwc [3]
4.00 49.24 9/9 malloc [5]
32.00 0.00 1/1 malloc_usable_size [8]
17.33 9.54 7/21 free [4]
5.29 0.00 5/35 __i686.get_pc_thunk.bx [6]
1 regexec [2]
Caveats
hwpmc(4) currently uses a simple heuristic to determine the initial stack frame given an interrupted PC value. This heuristic doesn't always work correctly in the presence of aggressive instruction scheduling that is the default with the current GCC compiler. Thus a small percentage of samples could appear to be missing call frames. For example, a call chain foo->bar->buzz may be collected as foo->buzz, if the interrupted PC value fell in function buzz when it was just about to return to bar.
This has the following undesirable side-effects:
- The callchain summary could show 'call chains' that do not happen in practice.
Caller/callee information tracked by gprof can be similarly incorrect.