Allegro.cc - Online Community

Allegro.cc Forums » Off-Topic Ordeals » need help understanding pprof output

Credits go to Arthur Kalliokoski for helping out!
This thread is locked; no one can reply to it. rss feed Print
need help understanding pprof output
iam_donald
Member #14,318
May 2012
avatar

Hi,
I need help understanding the output of pprof [part of gperftool]. I pulled this from the documentation:

Text mode has lines of output that look like this:

14 2.1% 17.2% 58 8.7% std::_Rb_tree::find
Here is how to interpret the columns:

1. Number of profiling samples in this function
2. Percentage of profiling samples in this function
3. Percentage of profiling samples in the functions printed so far
4. Number of profiling samples in this function and its callees
5. Percentage of profiling samples in this function and its callees
6. Function name

Help me understand what a profiling sample is and the rest of the output please, thanks.

Arthur Kalliokoski
Second in Command
February 2005
avatar

14      Number of profiling samples in this function

        The profiler interrupts your program every millisecond or so and examines
        the instruction pointer.  While you were profiling, the instruction
        pointer happened to be in std::_Rb_tree::find 14 times.

2.1%    Percentage of profiling samples in this function

        this 14 times was 2.1% of the samples, so your program spent 2.1% of its
        time there

17.2%   Percentage of profiling samples in the functions printed so far

        Apparently the functions already printed in the output have taken
        17.2 - 2.1 = 15.1% of the samples.  The last thing printed should
        be 100%

58      Number of profiling samples in this function and its callees

        Since your function was sampled 14 times, 58 - 14 = 44, so the
        functions std::_Rb_tree::find called were sampled 44 times.

std::_Rb_tree::find    Function name

“Throughout history, poverty is the normal condition of man. Advances which permit this norm to be exceeded — here and there, now and then — are the work of an extremely small minority, frequently despised, often condemned, and almost always opposed by all right-thinking people. Whenever this tiny minority is kept from creating, or (as sometimes happens) is driven out of a society, the people then slip back into abject poverty. This is known as "bad luck.”

― Robert A. Heinlein

iam_donald
Member #14,318
May 2012
avatar

Thanks a lot. That explains it all, I get it now.

Update: One more thing. In the profile info I'm getting a lot of hex values for method names. Now I was thinking compiling with debug info [-g] would take care of this. How do I resolve this please?

Arthur Kalliokoski
Second in Command
February 2005
avatar

Aren't you compiling and linking with -pg? e.g.

g++ -c -pg prog.cpp
g++ -pg prog.o -o prog

There might be other options such as -gstabs or -gdwarf but I haven't tried those for many years.

“Throughout history, poverty is the normal condition of man. Advances which permit this norm to be exceeded — here and there, now and then — are the work of an extremely small minority, frequently despised, often condemned, and almost always opposed by all right-thinking people. Whenever this tiny minority is kept from creating, or (as sometimes happens) is driven out of a society, the people then slip back into abject poverty. This is known as "bad luck.”

― Robert A. Heinlein

iam_donald
Member #14,318
May 2012
avatar

I was compiling with just -g. Tried -pg but I'm still getting hex values for names, a lot of them. I'm actually using clang.

I switched to gcc and tried out -pg, no dice. Here is the the output:

person said:

in core/ on master
› make furi_debug
gcc -pg -std=c99 -c -o engine.o engine.c
gcc -pg -std=c99 -c -o core.o core.c
gcc -pg -std=c99 -c -o display.o display.c
gcc -pg -std=c99 -c -o background.o background.c
gcc -pg -std=c99 -c -o helper_funcs.o helper_funcs.c
gcc engine.o core.o display.o background.o helper_funcs.o -pg -std=c99 -o furi_debug -lallegro-debug -lallegro_main-debug -lallegro_image-debug -ljansson -ltcmalloc -lprofiler

in core/ on master
› env CPUPROFILE=dump.prof ./furi_debug
PROFILE: interrupts/evictions/bytes = 10/0/1864

in core/ on master
› pprof --text ./furi_debug dump.prof
Using local file ./furi_debug.
Using local file dump.prof.
Removing __sigtramp from all stack traces.
Total: 10 samples
8 80.0% 80.0% 8 80.0% _mach_msg_trap
1 10.0% 90.0% 1 10.0% ___workq_kernreturn
1 10.0% 100.0% 1 10.0% _getattrlist
0 0.0% 100.0% 1 10.0% +[ALDisplayHelper initialiseDisplay:]
0 0.0% 100.0% 9 90.0% 0x00000001055297c0
0 0.0% 100.0% 9 90.0% 0x00000001055298ca
0 0.0% 100.0% 9 90.0% 0x0000000105709f29
0 0.0% 100.0% 1 10.0% 0x000000010f0ef8bf
0 0.0% 100.0% 2 20.0% 0x00007fdc7a2259ff
0 0.0% 100.0% 2 20.0% 0x00007fff65125bb7
0 0.0% 100.0% 1 10.0% 0x00007fff8800801c
0 0.0% 100.0% 1 10.0% 0x00007fff8800842f
0 0.0% 100.0% 1 10.0% 0x00007fff880097e3
0 0.0% 100.0% 1 10.0% 0x00007fff880099f2
0 0.0% 100.0% 1 10.0% 0x00007fff8800b1a9
0 0.0% 100.0% 1 10.0% 0x00007fff8800b228
0 0.0% 100.0% 1 10.0% 0x00007fff8800b39e
0 0.0% 100.0% 1 10.0% 0x00007fff8800b43e
0 0.0% 100.0% 1 10.0% 0x00007fff8800b6b4
0 0.0% 100.0% 1 10.0% 0x00007fff8800b76d
0 0.0% 100.0% 1 10.0% 0x00007fff8800bb38
0 0.0% 100.0% 1 10.0% 0x00007fff88033549
0 0.0% 100.0% 1 10.0% 0x00007fff889e924d
0 0.0% 100.0% 1 10.0% 0x00007fff889e9a68
0 0.0% 100.0% 1 10.0% 0x00007fff889eb000
0 0.0% 100.0% 1 10.0% 0x00007fff889eb081
0 0.0% 100.0% 8 80.0% 0x00007fff889ec070
0 0.0% 100.0% 8 80.0% 0x00007fff889ef734
0 0.0% 100.0% 8 80.0% 0x00007fff889efe30
0 0.0% 100.0% 1 10.0% 0x00007fff88a2c2ec
0 0.0% 100.0% 1 10.0% 0x00007fff88a3386e
0 0.0% 100.0% 1 10.0% 0x00007fff88a3844e
0 0.0% 100.0% 1 10.0% 0x00007fff88a38f54
0 0.0% 100.0% 1 10.0% 0x00007fff88a3b979
0 0.0% 100.0% 1 10.0% 0x00007fff88a61e0c
0 0.0% 100.0% 1 10.0% 0x00007fff88a620a2
0 0.0% 100.0% 1 10.0% 0x00007fff88a68b4e
0 0.0% 100.0% 1 10.0% 0x00007fff88a6af46
0 0.0% 100.0% 1 10.0% 0x00007fff88a6b4d9
0 0.0% 100.0% 1 10.0% 0x00007fff88a6b73a
0 0.0% 100.0% 1 10.0% 0x00007fff88a6b7dd
0 0.0% 100.0% 1 10.0% 0x00007fff88a6b83e
0 0.0% 100.0% 1 10.0% 0x00007fff88a6bbb9
0 0.0% 100.0% 1 10.0% 0x00007fff88a6c110
0 0.0% 100.0% 1 10.0% 0x00007fff88a79408
0 0.0% 100.0% 1 10.0% 0x00007fff88a797b9
0 0.0% 100.0% 1 10.0% 0x00007fff88aae2c6
0 0.0% 100.0% 1 10.0% 0x00007fff88aca6b4
0 0.0% 100.0% 1 10.0% 0x00007fff88aca945
0 0.0% 100.0% 1 10.0% 0x00007fff88ad9396
0 0.0% 100.0% 1 10.0% 0x00007fff88ad9506
0 0.0% 100.0% 1 10.0% 0x00007fff88ae88cc
0 0.0% 100.0% 1 10.0% 0x00007fff88ae902b
0 0.0% 100.0% 1 10.0% 0x00007fff88ae93a7
0 0.0% 100.0% 1 10.0% 0x00007fff88ae99aa
0 0.0% 100.0% 1 10.0% 0x00007fff88afb584
0 0.0% 100.0% 1 10.0% 0x00007fff88c1e023
0 0.0% 100.0% 1 10.0% 0x00007fff88c1e8dc
0 0.0% 100.0% 1 10.0% 0x00007fff88c1ed73
0 0.0% 100.0% 1 10.0% 0x00007fff8b395d6f
0 0.0% 100.0% 1 10.0% 0x00007fff8e3cef37
0 0.0% 100.0% 1 10.0% 0x00007fff8e3cf31b
0 0.0% 100.0% 1 10.0% 0x00007fff8e3cf3e5
0 0.0% 100.0% 6 60.0% 0x00007fff8e3cf4d2
0 0.0% 100.0% 1 10.0% 0x00007fff8e3d62c9
0 0.0% 100.0% 1 10.0% 0x00007fff8e3d6345
0 0.0% 100.0% 8 80.0% 0x00007fff8e3d660d
0 0.0% 100.0% 2 20.0% 0x00007fff8e3d66d2
0 0.0% 100.0% 5 50.0% 0x00007fff8e3d6780
0 0.0% 100.0% 1 10.0% 0x00007fff8e3d679b
0 0.0% 100.0% 1 10.0% 0x00007fff8e3d70cf
0 0.0% 100.0% 1 10.0% 0x00007fff8e3d854b
0 0.0% 100.0% 1 10.0% 0x00007fff8e3dd270
0 0.0% 100.0% 1 10.0% 0x00007fff8e3dd8b6
0 0.0% 100.0% 1 10.0% 0x00007fff8e3e470e
0 0.0% 100.0% 1 10.0% 0x00007fff8e3e49d7
0 0.0% 100.0% 1 10.0% 0x00007fff8e3eacce
0 0.0% 100.0% 1 10.0% 0x00007fff8e3eafe3
0 0.0% 100.0% 1 10.0% 0x00007fff8e3eec2e
0 0.0% 100.0% 1 10.0% 0x00007fff8e3eee23
0 0.0% 100.0% 1 10.0% 0x00007fff8e3f4dee
0 0.0% 100.0% 1 10.0% 0x00007fff8e3f5168
0 0.0% 100.0% 1 10.0% 0x00007fff8e3f5f84
0 0.0% 100.0% 1 10.0% 0x00007fff8e3f6223
0 0.0% 100.0% 1 10.0% 0x00007fff8e3f657f
0 0.0% 100.0% 1 10.0% 0x00007fff8e3f67c5
0 0.0% 100.0% 1 10.0% 0x00007fff8e3f6cad
0 0.0% 100.0% 1 10.0% 0x00007fff8e3f7631
0 0.0% 100.0% 1 10.0% 0x00007fff8e41d874
0 0.0% 100.0% 1 10.0% 0x00007fff8e41d9e4
0 0.0% 100.0% 1 10.0% 0x00007fff8e41e837
0 0.0% 100.0% 1 10.0% 0x00007fff8e41fa12
0 0.0% 100.0% 1 10.0% 0x00007fff8e41fcb0
0 0.0% 100.0% 1 10.0% 0x00007fff8e41ffe4
0 0.0% 100.0% 1 10.0% 0x00007fff8e420143
0 0.0% 100.0% 1 10.0% 0x00007fff8e420c2e
0 0.0% 100.0% 1 10.0% 0x00007fff8e420d08
0 0.0% 100.0% 1 10.0% 0x00007fff8e420d8a
0 0.0% 100.0% 1 10.0% 0x00007fff8ed576db
0 0.0% 100.0% 1 10.0% 0x00007fff8ed60ea1
0 0.0% 100.0% 1 10.0% 0x00007fff8f965221
0 0.0% 100.0% 1 10.0% 0x00007fff8fc15d5c
0 0.0% 100.0% 1 10.0% 0x00007fff8fc160a3
0 0.0% 100.0% 1 10.0% 0x00007fff8fc16120
0 0.0% 100.0% 1 10.0% 0x00007fff8fc162d1
0 0.0% 100.0% 1 10.0% 0x00007fff8fc164f0
0 0.0% 100.0% 5 50.0% 0x00007fff8fc3450b
0 0.0% 100.0% 6 60.0% 0x00007fff8fc3c485
0 0.0% 100.0% 1 10.0% 0x00007fff8fc3cb48
0 0.0% 100.0% 5 50.0% 0x00007fff8fc3cc73
0 0.0% 100.0% 1 10.0% 0x00007fff8fc3d2ba
0 0.0% 100.0% 1 10.0% 0x00007fff8fc3d3c4
0 0.0% 100.0% 1 10.0% 0x00007fff8fc3eeea
0 0.0% 100.0% 1 10.0% 0x00007fff8fc3f804
0 0.0% 100.0% 1 10.0% 0x00007fff8fc40886
0 0.0% 100.0% 1 10.0% 0x00007fff8fc5b224
0 0.0% 100.0% 1 10.0% 0x00007fff8fcd1d9c
0 0.0% 100.0% 1 10.0% 0x00007fff902f00a5
0 0.0% 100.0% 1 10.0% 0x0100000000c07670
0 0.0% 100.0% 9 90.0% __al_osx_run_main
0 0.0% 100.0% 1 10.0% __dispatch_queue_push_list_slow
0 0.0% 100.0% 1 10.0% __dispatch_queue_wakeup_global
0 0.0% 100.0% 1 10.0% __dispatch_wakeup
0 0.0% 100.0% 9 90.0% __mh_execute_header
0 0.0% 100.0% 1 10.0% _mach_port_insert_member
0 0.0% 100.0% 1 10.0% _pthread_workqueue_additem_np
0 0.0% 100.0% 1 10.0% _vm_deallocate
0 0.0% 100.0% 1 10.0% _xpc_connection_send_message

Arthur Kalliokoski
Second in Command
February 2005
avatar

I'm actually using clang

I don't have any experience with that, or what gprof will do with it.

“Throughout history, poverty is the normal condition of man. Advances which permit this norm to be exceeded — here and there, now and then — are the work of an extremely small minority, frequently despised, often condemned, and almost always opposed by all right-thinking people. Whenever this tiny minority is kept from creating, or (as sometimes happens) is driven out of a society, the people then slip back into abject poverty. This is known as "bad luck.”

― Robert A. Heinlein

iam_donald
Member #14,318
May 2012
avatar

The output I posted was from pprof [of gperftools]. Switching to gprof and gcc. Thanks.

Go to: