perf
Whereas profiling tools like gprof and operf sample the PC and count processor cycles to reveal program flow - perf can sample any counter that the CPU exports. For instance we can sample the cache-misses during a programs execution. Furthermore we can sample the counter only in user mode, system mode or both. We can sample all the CPUs or only the CPUs that are running the process under examination. We can also choose to sample the entire system.
Lastly we can combine these counters with PC sampling so that we are able to build a callgraph but with things like cache-misses so that we can see what was executing at the time the cache samples were taken.
Other Info and mdedia.
- Video: Using perf from Suse conference 2016 - the best I found so far"
- Speaker notes for the above talk
profiling with perf
Using our example program calcme-nested-asymmetric.c
generating a “cycles” profile
Profiles are generated using perf record which generates a file called perf.data by default - or will generate a filename of your choice by using -o <filenmame>
run perf record
I have found that most of the time you will want a record of the call graph if you are doing performance analysis - use -g to get a callgraph.
perf record -g ./calcme-nested-asymmetric
generating a profile with perf report
default
perf report --no-children
Output
The output looks simular to what we saw from gprof and oprofile which is expected.
# Overhead Command Shared Object Symbol
# ........ ............... ........................ .............................................
#
75.82% calcme-nested-a calcme-nested-asymmetric [.] spinme
|
---spinme
|
|--49.65%--calcme2
| main
| __libc_start_call_main
| __libc_start_main@@GLIBC_2.34
| _start
|
|--24.90%--calcme1
| main
| __libc_start_call_main
| __libc_start_main@@GLIBC_2.34
| _start
|
--1.27%--main
__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
9.16% calcme-nested-a calcme-nested-asymmetric [.] calcme2
|
---calcme2
|
|--8.28%--main
| __libc_start_call_main
| __libc_start_main@@GLIBC_2.34
| _start
|
--0.88%--__libc_start_call_main
__libc_start_main@@GLIBC_2.34
_start
compare to output of gprof
These were run on different machines - but both show that the bulk of time is spent in “spinme”.
Call graph
granularity: each sample hit covers 4 byte(s) for 0.11% of 8.71 seconds
index % time self children called name
<spontaneous>
[1] 100.0 1.40 7.31 main [1]
1.01 3.84 333333334/333333334 calcme2 [3]
0.54 1.92 166666667/166666667 calcme1 [4]
-----------------------------------------------
1.92 0.00 166666667/500000001 calcme1 [4]
3.84 0.00 333333334/500000001 calcme2 [3]
[2] 66.2 5.76 0.00 500000001 spinme [2]
-----------------------------------------------
1.01 3.84 333333334/333333334 main [1]
[3] 55.7 1.01 3.84 333333334 calcme2 [3]
3.84 0.00 333333334/500000001 spinme [2]
-----------------------------------------------
0.54 1.92 166666667/166666667 main [1]
[4] 28.2 0.54 1.92 166666667 calcme1 [4]
1.92 0.00 166666667/500000001 spinme [2]
-----------------------------------------------
mapping the profile to source with perf annotate
To get the nice source code mapping - you need to compile the program with -g which means add debugging information (for gdb) so probably that includes some mapping between source file and the compiled ASM
cc -o calcme-nested-asymmetric-g -g calcme-nested-asymmetric.c
Adding -g does not affect the runtime much, if at all, whereas -p affects runtime a lot since we are adding stack counting code into every function call (see gprof for details)
% time ./calcme-nested-asymmetric
./calcme-nested-asymmetric 13.13s user 0.00s system 99% cpu 13.140 total
% time ./calcme-nested-asymmetric-p
./calcme-nested-asymmetric-p 20.62s user 0.00s system 99% cpu 20.642 total
% time ./calcme-nested-asymmetric-g
./calcme-nested-asymmetric-g 13.10s user 0.00s system 99% cpu 13.108 total
When we run perf annotate on a program compiled with -g we get an annotated output with source and asm
% perf annotate --stdio --source
...
:
:
:
: 3 Disassembly of section .text:
:
: 5 0000000000001129 <spinme>:
:
: 7 int spinme(long looplen)
: 8 {
0.00 : 1129: endbr64
0.60 : 112d: push %rbp
1.06 : 112e: mov %rsp,%rbp
0.00 : 1131: mov %rdi,-0x18(%rbp)
: 13 long i, z;
: 14 for (i = 0; i <= looplen; i++)
0.63 : 1135: movq $0x0,-0x10(%rbp)
1.02 : 113d: jmp 1151 <spinme+0x28>
: 17 {
: 18 z = z * i;
13.43 : 113f: mov -0x8(%rbp),%rax
11.53 : 1143: imul -0x10(%rbp),%rax
36.34 : 1148: mov %rax,-0x8(%rbp)
: 22 for (i = 0; i <= looplen; i++)
25.61 : 114c: addq $0x1,-0x10(%rbp)
3.58 : 1151: mov -0x10(%rbp),%rax
2.42 : 1155: cmp -0x18(%rbp),%rax
0.00 : 1159: jle 113f <spinme+0x16>
: 27 }
: 28 return z;
1.64 : 115b: mov -0x8(%rbp),%rax
: 30 }
2.14 : 115f: pop %rbp
0.00 : 1160: ret
compare to opannotate
$ 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
Getting runtime stats
We have seen traces/profiles but we can get these elsewhere - what else can perf do?
perf stat
general stats incl instructions per cycle
Runtime stats for a simple program that mostly spins on proc
% perf stat ./calcme-nested-asymmetric gary 5:58PM
Performance counter stats for './calcme-nested-asymmetric':
13,123.79 msec task-clock # 0.999 CPUs utilized
61 context-switches # 4.648 /sec
4 cpu-migrations # 0.305 /sec
53 page-faults # 4.038 /sec
39,036,436,593 cycles # 2.974 GHz
65,254,960,404 instructions # 1.67 insn per cycle
9,681,290,509 branches # 737.690 M/sec
324,494 branch-misses # 0.00% of all branches
13.131093917 seconds time elapsed
13.122328000 seconds user
0.000999000 seconds sys
cache stats
cache stats initial look
If we look at user cache miss ratio - it seems pretty high for a very simple program. What could be going on?
% perf stat -e cache-misses:u -e cache-references:u ./calcme-nested-asymmetric
Performance counter stats for './calcme-nested-asymmetric':
6,921 cache-misses:u # 51.77% of all cache refs
13,370 cache-references:u
13.099561336 seconds time elapsed
13.092664000 seconds user
0.000000000 seconds sys
perf report comparison
If we look at a perf report -d for detail - we get another angle on the cache hitrate. This view of cache hitrate shows a tiny miss-rate. Also the shear volume of cache accesses is far far higher than what we see above.
% perf stat -d ./calcme-nested-asymmetric gary 9:38AM
Performance counter stats for './calcme-nested-asymmetric':
13,099.38 msec task-clock # 1.000 CPUs utilized
31 context-switches # 2.367 /sec
0 cpu-migrations # 0.000 /sec
52 page-faults # 3.970 /sec
0 cycles
65,252,126,681 instructions
9,680,743,645 branches # 739.023 M/sec
271,368 branch-misses # 0.00% of all branches
35,022,321,968 L1-dcache-loads # 2.674 G/sec
1,667,902 L1-dcache-load-misses # 0.00% of all L1-dcache accesses
<not supported> LLC-loads
<not supported> LLC-load-misses
13.104117737 seconds time elapsed
13.098804000 seconds user
0.000999000 seconds sys
perf stat with user and kernel
Firstly we see that there are far more misses when we count user and kernel :uk then when we just count user-space -u. But the values are still fare lower than L1-dcache-loads reported above.
% perf report -i calcme-cache-misses-u.perf 2>/dev/null|gre Event
# Event count (approx.): 2728
% perf report -i calcme-cache-misses-uk.perf 2>/dev/null|grep Event
# Event count (approx.): 466469
Apparently -e cache-misses counts the last level cache references - which would explain why the number is much lowere than the L1 misses - but it is not obvious why perf stat shows LLC-loads/misses is <not-suoported>. Perhaps because we are in a VM - but how does -e cacheXXX work?
cache call graph
If we generate a call-graph we can see where these misses are coming from - the data in the callgraph will now be the cache stats rather than the cycles stats as is the default. This is the power of perf and its ability to work with arbitrary counters - not just cycles - or PC samples
% perf record -e cache-misses -g ./calcme
% perf report --call-graph=none --no-children --stdio | less
# Overhead Command Shared Object Symbol
# ........ ............... ........................ ......................
#
12.90% calcme-nested-a [unknown] [k] 0xffffffffa9f55560
10.08% calcme-nested-a [unknown] [k] 0xffffffffa9f554ce
3.34% calcme-nested-a [unknown] [k] 0xffffffffa9f5551f
1.98% calcme-nested-a [unknown] [k] 0xffffffffa9f5553e
1.79% calcme-nested-a [unknown] [k] 0xffffffffaa671e6d
1.58% calcme-nested-a [unknown] [k] 0xffffffffa9f5555a
1.50% calcme-nested-a calcme-nested-asymmetric [.] spinme
and recall that when we do cycles instead - we see most activity in spinme as we expect
# Overhead Command Shared Object Symbol
# ........ ............... ........................ .................................
#
74.92% calcme-nested-a calcme-nested-asymmetric [.] spinme
9.42% calcme-nested-a calcme-nested-asymmetric [.] calcme2
8.78% calcme-nested-a calcme-nested-asymmetric [.] main
4.66% calcme-nested-a calcme-nested-asymmetric [.] calcme1
### calcme-nested-asymmetric.c source
int spinme(long looplen) { long i, z; for (i = 0; i <= looplen; i++) { z = z * i; } return z; }
int calcme1(int i) { long z, innerloop = 10; z = spinme(innerloop); return (i * z); }
int calcme2(int i) { long z, innerloop = 10; z = spinme(innerloop); return (i * z); }
int main() { int i, res = 0, total = 0; long int iterations = 500000000; for (i = 0; i <= iterations; i++) { if (i % 3 == 0) { res = calcme1(i); } else { res = calcme2(i); } } total = total + res; }