This is oprofile 2026
Like gprof, oprofile is useful for understanding where time is spent. Unlike gprof it does not require the program to be re-compiled because it uses kernel perf-events rather than inserting additional functions/macros into the code.
The basic usage is
Set security level for the session (wont reset until reboot).
sudo sysctl -w kernel.perf_event_paranoid=-1
Flat profile
operf <your-program>
./<your-program>
opreport -l symbols <your-program>
To get callgraphs
operf --callgraph <your-program>
./<your-program>
opreport --callgraph -l symbols <your-program>
Security and oprofile
Since oprofile uses kernel events - you may find that you need to use sudo even to trace your own programs. This is most likely due to settings in /proc/sys/kernel/perf_event_paranoid. On some modern Ubuntu distributions it is set to “4” which means you cannot trace anything. Set this to some more sane value like “2” which is still ‘Strict’
perf_event modes
- 2 Strict
- 1 Normal
- 0 Moderate
- -1 Open
Set temporarily
Set permissive for testing and hacking
sudo sysctl -w kernel.perf_event_paranoid=-1
Set permanently
Be a bit more strict by default
echo 'kernel.perf_event_paranoid=2' | sudo tee /etc/sysctl.d/99-perf.conf
We will use the same C program as we did earlier in the gprof example.
Overhead
Unlike gprof we are not recording the stack on every function call - so the overhead is usually much lower than gprof - though less then 100% accurate since we are now sampling
Execution times
- No profiling:
real 0m10.966s ; user 0m10.955s ; sys 0m0.013s - pg (gprof) profiling:
real 0m17.308s ; user 0m17.299s ; sys 0m0.010s - oprofile :
real 0m11.931s ; user 0m12.305s ; sys 0m0.508s
In fact we can see the overhead of the stack capture in gprof by running oprofile on a gprof build - we see nearly 49% of the runtime is spent in __mcount_internal which is the gprof stack counter.
profile the gprof build
$ operf ./calcme-nested-asymmetric-pg
$ opreport -l symbols ./calcme-nested-asymmetric-pg
samples % image name symbol name
277854 48.7363 libc.so.6 __mcount_internal
141886 24.8872 calcme-nested-asymmetric-pg spinme
65119 11.4220 libc.so.6 mcount
40871 7.1689 calcme-nested-asymmetric-pg main
29114 5.1067 calcme-nested-asymmetric-pg calcme2
15077 2.6445 calcme-nested-asymmetric-pg calcme1
194 0.0340 no-vmlinux /no-vmlinux
1 1.8e-04 ld-linux-x86-64.so.2 _dl_map_object_from_fd
1 1.8e-04 ld-linux-x86-64.so.2 do_lookup_x
profile the regular build
$ operf ./calcme-nested-asymmetric
$ opreport -l symbols ./calcme-nested-asymmetric
samples % image name symbol name
279916 76.8400 calcme-nested-asymmetric spinme
34447 9.4561 calcme-nested-asymmetric calcme2
33037 9.0690 calcme-nested-asymmetric main
16751 4.5983 calcme-nested-asymmetric calcme1
132 0.0362 no-vmlinux /no-vmlinux
1 2.7e-04 ld-linux-x86-64.so.2 _dl_relocate_object
Capture the profile
$ sudo operf ./calcme-nested-asymmetric
Dump the profile
$ opreport
Output no symbols (opreport) not very useful
samples| %|
------------------
364497 100.000 calcme-nested-asymmetric
cpu_clk_unhalt...|
samples| %|
------------------
364369 99.9649 calcme-nested-asymmetric
126 0.0346 kallsyms
1 2.7e-04 tls
1 2.7e-04 ld-linux-x86-64.so.2
Output with symbols (opreport -l symbols <binary>)
$ opreport -l symbols ./calcme-nested-asymmetric
samples % image name symbol name
279916 76.8400 calcme-nested-asymmetric spinme
34447 9.4561 calcme-nested-asymmetric calcme2
33037 9.0690 calcme-nested-asymmetric main
16751 4.5983 calcme-nested-asymmetric calcme1
132 0.0362 no-vmlinux /no-vmlinux
1 2.7e-04 ld-linux-x86-64.so.2 _dl_relocate_object
Dump with callgraphs
- (operf must be run with –callgraph during collection phase also)
- No additional flags used may want (-fno-omit-frame-pointer) if it looks weird, but does not seem to add anything in the normal case.
$ operf --callgraph ./calcme-nested-asymmmetric
$ opreport --symbols --callgraph ./calcme-nested-asymmetric
Using /home/gary/git/perfeng-demos-pub/oprofile/oprofile_data/samples/ for samples directory.
CPU: Intel Skylake microarchitecture, speed 3600 MHz (estimated)
Counted cpu_clk_unhalted events () with a unit mask of 0x00 (Core cycles when at least one thread on the physical core is not in halt state) count 30000045
samples % image name symbol name
-------------------------------------------------------------------------------
16 1.6032 calcme-nested-asymmetric main
333 33.3667 calcme-nested-asymmetric calcme1
649 65.0301 calcme-nested-asymmetric calcme2
995 76.8934 calcme-nested-asymmetric spinme
995 99.6994 calcme-nested-asymmetric spinme [self]
3 0.3006 no-vmlinux /no-vmlinux
-------------------------------------------------------------------------------
9 1.1643 libc.so.6 __libc_start_call_main
764 98.8357 calcme-nested-asymmetric main
123 9.5054 calcme-nested-asymmetric calcme2
649 83.9586 calcme-nested-asymmetric spinme
123 15.9120 calcme-nested-asymmetric calcme2 [self]
1 0.1294 no-vmlinux /no-vmlinux
-------------------------------------------------------------------------------
1280 100.000 libc.so.6 __libc_start_call_main
113 8.7326 calcme-nested-asymmetric main
764 59.6875 calcme-nested-asymmetric calcme2
387 30.2344 calcme-nested-asymmetric calcme1
113 8.8281 calcme-nested-asymmetric main [self]
16 1.2500 calcme-nested-asymmetric spinme
-------------------------------------------------------------------------------
5 1.2755 libc.so.6 __libc_start_call_main
387 98.7245 calcme-nested-asymmetric main
59 4.5595 calcme-nested-asymmetric calcme1
333 84.9490 calcme-nested-asymmetric spinme
59 15.0510 calcme-nested-asymmetric calcme1 [self]
-------------------------------------------------------------------------------
1 25.0000 calcme-nested-asymmetric calcme2
3 75.0000 calcme-nested-asymmetric spinme
4 0.3091 no-vmlinux /no-vmlinux
4 100.000 no-vmlinux /no-vmlinux [self]
-------------------------------------------------------------------------------
0 0 calcme-nested-asymmetric _start
1294 100.000 libc.so.6 __libc_start_main@@GLIBC_2.34
0 0 calcme-nested-asymmetric _start [self]
-------------------------------------------------------------------------------
1294 100.000 libc.so.6 __libc_start_main@@GLIBC_2.34
0 0 libc.so.6 __libc_start_call_main
1280 98.9181 calcme-nested-asymmetric main
9 0.6955 calcme-nested-asymmetric calcme2
5 0.3864 calcme-nested-asymmetric calcme1
0 0 libc.so.6 __libc_start_call_main [self]
-------------------------------------------------------------------------------
1294 100.000 calcme-nested-asymmetric _start
0 0 libc.so.6 __libc_start_main@@GLIBC_2.34
1294 100.000 libc.so.6 __libc_start_call_main
0 0 libc.so.6 __libc_start_main@@GLIBC_2.34 [self]
-------------------------------------------------------------------------------
opannotate
This is a really nice output and we see that it points to a line that looks plausible
opannotate source code
$ opannotate --source calcme-nested-asymmetric-fp
...
:int spinme(long looplen)
20 1.5456 :{ /* spinme total: 996 76.9706 */
: long i, z;
336 25.9660 : for (i = 0; i <= looplen; i++)
: {
591 45.6723 : z = z * i;
: }
25 1.9320 : return z;
24 1.8547 :}
:
:int calcme1(int i)
11 0.8501 :{ /* calcme1 total: 64 4.9459 */
: long z, innerloop = 10;
11 0.8501 : z = spinme(innerloop);
18 1.3910 : return (i * z);
24 1.8547 :}
:
:int calcme2(int i)
20 1.5456 :{ /* calcme2 total: 109 8.4235 */
: long z, innerloop = 10;
19 1.4683 : z = spinme(innerloop);
39 3.0139 : return (i * z);
31 2.3957 :}
:
:int main()
:{ /* main total: 124 9.5827 */
: int i, res = 0, total = 0;
: long int iterations = 500000000;
35 2.7048 : for (i = 0; i <= iterations; i++)
: {
54 4.1731 : if (i % 3 == 0) {
16 1.2365 : res = calcme1(i);
: }
: else
: {
19 1.4683 : res = calcme2(i);
: }
: }
: total = total + res;
:}
:
opannotate assembly
Identify the appropriate assembly instructions.
gary@rodney:~/git/perfeng-demos-pub/oprofile$ opannotate --assembly calcme-nested-asymmetric-fp
:
:Disassembly of section .text:
:
0000000000001129 <spinme>: /* spinme total: 996 76.9706 */
:
:int spinme(long looplen)
:{
: 1129: endbr64
8 0.6182 : 112d: push %rbp
12 0.9274 : 112e: mov %rsp,%rbp
: 1131: mov %rdi,-0x18(%rbp)
: long i, z;
: for (i = 0; i <= looplen; i++)
10 0.7728 : 1135: movq $0x0,-0x10(%rbp)
5 0.3864 : 113d: jmp 1151 <spinme+0x28>
: {
: z = z * i;
132 10.2009 : 113f: mov -0x8(%rbp),%rax
112 8.6553 : 1143: imul -0x10(%rbp),%rax
347 26.8161 : 1148: mov %rax,-0x8(%rbp)
: for (i = 0; i <= looplen; i++)
252 19.4745 : 114c: addq $0x1,-0x10(%rbp)
29 2.2411 : 1151: mov -0x10(%rbp),%rax
40 3.0912 : 1155: cmp -0x18(%rbp),%rax
: 1159: jle 113f <spinme+0x16>
: }
: return z;
25 1.9320 : 115b: mov -0x8(%rbp),%rax
:}
24 1.8547 : 115f: pop %rbp
: 1160: ret
Using perf for similar results
Capture the profile
$ perf record ./calcme-nested-asymmetric
Output the processed result
$ perf report --stdio