\nf1(int n) {\n int i; for (i = 0; i <= 5; i++) {}; return i;\n};\nf2(int n) {\n int i; for (i = 0; i <= 5; i++) {}; return i;\n};\nmain() {\n int r; \n int i; for (i = 0;; i++) {\n (i % 3 == 0) ? f1(i): f2(i);\n };\n return r;\n}\n<\/code><\/pre>\nI have two functions f1() and f2() which do exactly the same thing. I just want to have different names. And the main() function loops and calls the f1() function 1\/3rd of times and f2() 2\/3rd of times, thanks to the (i % 3) condition on modulo 3<\/p>\n
\nperf top -F100 -d10 -p$(pgrep -d, a.out)\n<\/code><\/pre>\nYou can simply run `perf top` but here I explicitly reduced the sample frequency to 100Hz (safer to reduce the overhead of sampling) and the display refresh frequency to 10 seconds because it is simple to take consistent screenshots. I measure only my program by getting the PID through `pgrep -d, a.out`. I display only the userspace symbols by hiding the kernel ones (-K). There are many possibilities to target specific processes in `perf` as well in `pgrep`but that’s not the goal of this post. The man pages are clear about that.<\/p>\n
\nSamples: 4K of event 'cycles', 100 Hz, Event count (approx.): 69818773752 lost: 0\/0 drop: 0\/0\nOverhead Share Symbol\n 59.86% a.out [.] f2\n 31.10% a.out [.] f1\n 9.04% a.out [.] main\n<\/code><\/pre>\nThe “Shared Object” is my program (a.out) or a library that is called, or the kernel. Here I didn’t specify the process. Symbols are the C functions. And the “Overhead” percentage sums to 100% and this is where it is important to filter what you sample so that it is easy to profile it as a ratio of the total samples for this target.<\/p>\n
This is the default option, showing the symbols but not the call stack, the percentages are the time spend in the function. My program spends only 9.04% of its CPU time in main() because very few is done there. When main() calls a function, the samples are accounted for the function but not for main(). On the remaining time (91%) one third of the time is spent in f1() and two third in f2().<\/p>\n
This may already be sufficient to know where to investigate for optimizing the code. For example, if you divide by two the work done in f2() you know that this will reduce by 30% the CPU usage for your program (the math is: 50% x 59.86%)<\/p>\n
call-graph<\/h3>\n
Reducing the resources used by a function is one possibility. But the best optimization would be to avoid calling it too often. And I have no information to help me about that. Nothing here tells me that f1() is called from main(). It could have been called from f2(). Or from both. When troubleshooting a program execution, knowing the function is not enough, we need to see the whole call stack.<\/p>\n
\nperf top -F100 -d10 -p$(pgrep a.out) -K -g\n<\/code><\/pre>\nI’ve added -g here to record the call stack (not only in which function we are when sampling, but also where the functions come from). There are different modes that you can choose with –call-graph but I’m using the default here.<\/p>\n
\nSamples: 3K of event 'cycles', 100 Hz, Event count (approx.): 37649486188 lost: 0\/0 drop: 0\/0\n Children Self Shared Objec Symbol\n+ 95.61% 8.19% a.out [.] main\n+ 60.64% 60.64% a.out [.] f2\n+ 31.17% 31.17% a.out [.] f1\n+ 15.55% 0.00% libc-2.17.so [.] __libc_start_main\n<\/code><\/pre>\nHere the “Self” column is similar to what I had without “-g”: this is the percentage of CPU cycles spent in each function. But the “Children” column adds the time spent in all called functions below it. Not only the immediate children, but all descendants. For leaves of the call graph, functions not calling anything else, the value of Self and Children is equal. But for main() it adds the time spent in f1()<-main() and f2()<-main(). You read the first line as: 95.61% of time is spent in the call to main() and only 8.19% is on main() instructions because it calls other functions most of the time. Note that you cad add “Self” to cover 100% but in “Children” the children samples are accounted in many lines. The idea is to see on top the fragment of call stack that accounts for the most samples.<\/p>\n
There’s a “+” where you can drill down. I do it for all of them here be you typically go to the one you want to analyze deeper:<\/p>\n
\n- 95.61% 8.19% a.out [.] main \n - 87.42% main \n 57.68% f2 \n 29.74% f1 \n - 8.19% __libc_start_main \n main \n- 60.64% 60.64% a.out [.] f2 \n - 60.64% __libc_start_main \n - 57.68% main \n f2 \n 2.97% f2 \n- 31.17% 31.17% a.out [.] f1 \n - 31.17% __libc_start_main \n - 29.74% main \n f1 \n 1.42% f1 \n- 15.55% 0.00% libc-2.17.so [.] __libc_start_main \n - __libc_start_main \n - 14.63% main \n 8.96% f2 \n 4.58% f1 \n<\/code><\/pre>\nWhen drilling-down the first line I can see that the difference between 95.61% in main() call and 8.19% in main() instructions is in calls to f2() and f1(). Note that you understand the reason why I’ve set –delay to 10 seconds: to be able to drill down on the same numbers before refresh in order to make this clearer in the blog post. Because with 100Hz sampling the numbers may change slightly.<\/p>\n
callee\/caller<\/h3>\n
In order to investigate on functions that are called from many places, I replace the work done in f2() by a call to f1():<\/p>\n
\nf1(int n) {\n int i; for (i = 0; i <= 5; i++) {}; return i;\n};\nf2(int n) {\n return f1(n);\n};\nmain() {\n int r; \n int i; for (i = 0;; i++) {\n (i % 3 == 0) ? f1(i): f2(i);\n };\n return r;\n}\n<\/code><\/pre>\nNow, in addition to being called 1\/3 of time from main, most of the time spent in f2() is also calling f1().<\/p>\n
\nSamples: 255 of event 'cycles', 100 Hz, Event count (approx.): 5934954123 lost: 0\/0 drop: 0\/0\nOverhead Share Symbol\n 83.59% a.out [.] f1\n 12.81% a.out [.] main\n 3.60% a.out [.] f2\n<\/code><\/pre>\nWithout the call graph, the time spend in the function instructions is, proportionally to the total time, now mostly in f1() because f1() is called in all by branch condition. The part accounted in f2() is minimal.<\/p>\n
\nperf record -F100 -g --delay=5 -v -p $(pgrep -d, a.out) -a sleep 30\nperf report | cat\n<\/code><\/pre>\nRather than looking at it live, I record the samples (mentioning the PID but running a `sleep 30` to record for 30 seconds).<\/p>\n
\nSamples: 764 of event 'cycles', Event count (approx.): 18048581591\n Children Self Command Shared Object Symbol\n+ 100.00% 0.00% a.out libc-2.17.so [.] __libc_start_main\n+ 99.47% 10.87% a.out a.out [.] main\n- 86.22% 85.68% a.out a.out [.] f1\n - 85.68% __libc_start_main\n - main\n - 57.78% f2\n f1\n 27.90% f1\n - 0.54% f1\n + 0.54% apic_timer_interrupt\n- 60.82% 2.77% a.out a.out [.] f2\n - 58.05% f2\n f1\n - 2.77% __libc_start_main\n - 2.24% main\n f2\n 0.53% f2\n+ 0.68% 0.00% a.out [kernel.kallsyms] [k] apic_timer_interrupt\n+ 0.68% 0.00% a.out [kernel.kallsyms] [k] smp_apic_timer_interrupt\n<\/code><\/pre>\nIf we look at the f1() detail we can see 27.90% with f1()<-main() which is the 1\/3rd calls from there. And 57.78% with f1()<-f2()<-main() for the 2\/3rd of the conditional branch. With of course some time in main() itself (10.87%) and in f2() itself (2.77%)<\/p>\n
This is the caller breakdown which can also be displayed with `perf report –call-graph ,,,,caller`
\nWe see that f1() is on CPU 57.78% of time through f1()<-f2()<-main() and 27.90% directly through f2()<-main()<\/p>\n
We can also display it with breakdown on callee: by changing the call graph order as `perf report –call-graph ,,,,callee`<\/p>\n
\nSamples: 764 of event 'cycles', Event count (approx.): 18048581591\n Children Self Command Shared Object Symbol\n- 100.00% 0.00% a.out libc-2.17.so [.] __libc_start_main\n __libc_start_main\n- 99.47% 10.87% a.out a.out [.] main\n main\n __libc_start_main\n- 86.22% 85.68% a.out a.out [.] f1\n - f1\n - 58.05% f2\n main\n __libc_start_main\n - 28.17% main\n __libc_start_main\n- 60.82% 2.77% a.out a.out [.] f2\n - f2\n - 60.29% main\n __libc_start_main\n 0.53% __libc_start_main\n+ 0.68% 0.00% a.out [kernel.kallsyms] [k] apic_timer_interrupt\n+ 0.68% 0.00% a.out [kernel.kallsyms] [k] smp_apic_timer_interrupt\n<\/code><\/pre>\nThis shows that among the 86.22% samples in f1() 58.05% are from f2() and 28.17% from main<\/p>\n
folded<\/h3>\n
![\"\"](\"https:\/\/www.dbi-services.com\/blog\/wp-content\/uploads\/sites\/2\/2022\/04\/Screenshot-2021-03-13-234231.jpg\")
<\/a><\/p>\n