GNU Profiling Tool: gprof

1. GNU Profiling Tool: gprof Presentation by Chris Liebert on Wednesday, November 7th 2012 • Profile your code • Figure out which functions are consuming the most time • See which child functions are called • See how many times each function is called

2. How to Use gprof • Tell g++ to use profiling with -pg • Run the executable to generate gmon.out • Run gprof On unix: >g++ -pg main.cpp >./a.out >gprof On Windows: (msys or cygwin) >g++.exe -pg main.cpp >./a.exe >gprof.exe ./a.exe

3. Additional Information Command Line Arguments >gprof --help Full Documentation >man gprof

4. Flat Profile • Shows the total amount of time your program spent executing each function Example Flat Profile Table Each sample counts as 0.01 seconds. % cumulative self self total time seconds seconds calls s/call s/call name 41.05 3.61 3.61 3 1.20 1.20 columnsFirst(int, int (*) [9447]) 40.93 7.21 3.60 3 1.20 1.20 rowFirstIndicesReversed(int, int (*) [9447]) 12.69 8.33 1.12 3 0.37 0.37 rowsFirst(int, int (*) [9447]) 5.95 8.85 0.52 main 0.00 8.85 0.00 1 0.00 0.00 _GLOBAL__sub_I__Z9rowsFirstiPA9447_i 0.00 8.85 0.00 1 0.00 0.00 __static_initialization_and_destruction_0(int, int)

5. Flat Profile Description • Something like this is included in gprof's output. • % -- the percentage of the total running time of the time program used by this function. • cumulative seconds -- a running sum of the number of seconds accounted for by this function and those listed above it. • self seconds -- the number of seconds accounted for by this function alone. This is the major sort for this listing. • calls -- the number of times this function was invoked, if this function is profiled, else blank. • self ms/call -- the average number of milliseconds spent in this function per call, if this function is profiled, else blank. • total ms/call -- the average number of milliseconds spent in this function and its descendent's per call, if this function is profiled, else blank. • name -- the name of the function. This is the minor sort for this listing. The index shows the location of the function in the gprof listing. If the index is in parenthesis it shows where it would appear in the gprof listing if it were to be printed.

6. Call Graph • A table containing index, %, time, self, children, called, name • A description of each column is followed in gprof's output

7. Call Graph Example • This portion of the output is followed by a description key for the tables similar to the flat profile, followed by... granularity: each sample hit covers 2 byte(s) for 0.11% of 8.85 seconds index % time self children called name <spontaneous> [1] 100.0 0.52 8.33 main [1] 3.61 0.00 3/3 columnsFirst(int, int (*) [9447]) [2] 3.60 0.00 3/3 rowFirstIndicesReversed(int, int (*) [9447]) [3] 1.12 0.00 3/3 rowsFirst(int, int (*) [9447]) [4] ----------------------------------------------- 3.61 0.00 3/3 main [1] [2] 40.8 3.61 0.00 3 columnsFirst(int, int (*) [9447]) [2] ----------------------------------------------- 3.60 0.00 3/3 main [1] [3] 40.7 3.60 0.00 3 rowFirstIndicesReversed(int, int (*) [9447]) [3] ----------------------------------------------- 1.12 0.00 3/3 main [1] [4] 12.6 1.12 0.00 3 rowsFirst(int, int (*) [9447]) [4] ----------------------------------------------- 0.00 0.00 1/1 __libc_csu_init [19] [12] 0.0 0.00 0.00 1 _GLOBAL__sub_I__Z9rowsFirstiPA9447_i [12] 0.00 0.00 1/1 __static_initialization_and_destruction_0(int, int) [13] ----------------------------------------------- 0.00 0.00 1/1 _GLOBAL__sub_I__Z9rowsFirstiPA9447_i [12] [13] 0.0 0.00 0.00 1 __static_initialization_and_destruction_0(int, int) [13] ----------------------------------------------- Index by function name [12] _GLOBAL__sub_I__Z9rowsFirstiPA9447_i [3] rowFirstIndicesReversed(int, int (*) [9447]) [4] rowsFirst(int, int (*) [9447]) [2] columnsFirst(int, int (*) [9447]) [13] __static_initialization_and_destruction_0(int, int) [1] main