QuickRef
- Compile program with profiling enabled
-pg - Compile program with profiling and debug
-pg -g - Generate succinct profile output
gprof -b <prog> [gmon.out] - Generate profile
gprof <prog> [gmon.out] - Generate profile with annotactions
gprof -A <prog> - Generate profile with lin-by-line output
gprof -l <prog>
How Tos
Generating the profile
- Compiling a program for standard profiling
- Compiling a program for annotated / line-by-line profiling
- Generating gprof output default
- Generating output with code annotations
- Generating output with line-by-line annotations
Using the profile
- Read the profile (the output of gprof)
- View program as assembler
- Check binary to see if profiling is enabled
Tips and Meta
- gnu gprof manual <link>
- Measuring gprof overhead
- Understanding impact of compiler optimization on profiling
- How does gprof work
- How are mcount and monstartup used?
- [Why is the timing 0(zero)]
- End to end gprof example
- Un-Annotated gprof output
Example programs
gprof use cases
gprof can give us a rough estimate of what our program is doing, without the user/programmer adding explicit instrumentation. We get the compiler to add the instrumentation for us at compile time using the -pg flag. The main downside to gprof is that you need the source code to use it (since we have to compile-in the telemetry) and it can have quite a high overhead, depending on how the program under test is structured (lots of small functions cause a high overhead)
Using gprof for performance analysis
When we use gprof for performance work, we use the gprof profile output and observe where time is spent. It tells us who called whom, how many times and how much runtime was spent where. This is pretty useful information for understanding a running program. Some example output is below
There are three steps to get to a point where you can analyze the program under test
- Compile the program with profiling enabled
- Run the program (program must exit cleanly)
- Run gprof and inspect the output generated
Compiling a program with standard profiling
- Pass the
-pgparameter to gcc
$ gcc -o simple-pg -pg simple.c
Compiling a program with annotated or line-by-line profiling
- Pass
-pgAND-gto gcc (-gmeans enable debug information)
$ gcc -o simple-pg -pg -g simple.c
Generating a standard profile output
- Compile the program with at least
-pgon the command line - Run the program
- Run
gprof
Run the program
$ ./simple-pg
Once the program exits there will be a file called gmon.out which contains the execution information (the profile) in the current working directory (the location where you ran the program from, not where the program itself is located)
gprof default output
$ gprof ./simple-pg
We don’t need to specify ‘gmon.out’ since gprof assumes that. If the gmon.out file is renamed, or located away from the CWD then you can specify it on the command line too. e.g. if the gmon.out is in /tmp - use $ gprof ./simple-pg /tmp/gmon.out
gprof profile, call graph only (eliminates extra text)
$ gprof -b simple-pg
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ns/call ns/call name
57.58 0.19 0.19 100000001 1.90 1.90 calcme
42.42 0.33 0.14 main
Call graph
granularity: each sample hit covers 4 byte(s) for 3.03% of 0.33 seconds
index % time self children called name
<spontaneous>
[1] 100.0 0.14 0.19 main [1]
0.19 0.00 100000001/100000001 calcme [2]
-----------------------------------------------
0.19 0.00 100000001/100000001 main [1]
[2] 57.6 0.19 0.00 100000001 calcme [2]
-----------------------------------------------
Index by function name
[2] calcme [1] main
Generating a profile with code annotations
- Compile the program with both
-pgAND-gto get additional debug output - Run the program
- Run
gprof -Ato get “Annotated Output”
Annotated output
*** File /home/gary/git/perfeng-demos-pub/gprof/calcme-with-inner-loop.c:
500000001 -> int calcme(int i) {
long z,innerloop=10;
for (i=0 ; i <= innerloop ; i++) {
z=i*i;
}
return(i*i*z);
}
##### -> int main() {
int i,res=0,total=0;
long int iterations=500000000;
for (i=0 ; i <= iterations ; i++) {
res=calcme(i);
total=total+res;
}
}
Top 10 Lines:
Line Count
1 500000001
Execution Summary:
2 Executable lines in this file
2 Lines executed
100.00 Percent of the file executed
Generating a profile with line-by-line profiling
DO NOT COMBINE -A and -l. In this case you only get Annotations and not the line-numbers
- Compile the program with both
-pgAND-gto get additional debug output - Run the program
- Run
gprof -lto get “Line-By-Line Output”
Line-by-Line output
granularity: each sample hit covers 4 byte(s) for 0.13% of 7.78 seconds
index % time self children called name
0.40 0.00 500000001/500000001 main (calcme-with-inner-loop.c:13 @ 125c) [3]
[6] 5.1 0.40 0.00 500000001 calcme (calcme-with-inner-loop.c:1 @ 11d9) [6]
-----------------------------------------------
<spontaneous>
[10] 1.9 0.14 0.00 main (calcme-with-inner-loop.c:9 @ 122b) [10]
...
Index by function name
[6] calcme (calcme-with-inner-loop.c:1 @ 11d9) [1] calcme (calcme-with-inner-loop.c:3 @ 120b) [3] main (calcme-with-inner-loop.c:13 @ 125c)
[11] calcme (calcme-with-inner-loop.c:2 @ 11ee) [8] calcme (calcme-with-inner-loop.c:6 @ 121a) [4] main (calcme-with-inner-loop.c:14 @ 1269)
[7] calcme (calcme-with-inner-loop.c:3 @ 11f6) [9] calcme (calcme-with-inner-loop.c:7 @ 1229) [5] main (calcme-with-inner-loop.c:12 @ 126f)
[2] calcme (calcme-with-inner-loop.c:4 @ 11ff) [10] main (calcme-with-inner-loop.c:9 @ 122b)
Reading the profile output
Using the profile from calcme-nested-asymmetric.c, here is what each line means.
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ns/call ns/call name
66.19 5.76 5.76 500000001 11.53 11.53 spinme <--- 66% of time spent in spinme function
16.07 7.17 1.40 main <--- 16% of time spent in main
11.60 8.18 1.01 333333334 3.03 14.56 calcme2 <--- 12% of time spent in calcme2
6.14 8.71 0.54 166666667 3.21 14.74 calcme1 <--- 6% of time spent in calcme1
== 100%
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] <-- main calls calcme2 333,333,334 times
0.54 1.92 166666667/166666667 calcme1 [4] <-- main calls calcme1 166,666,667 times (500,000,0001 total)
-----------------------------------------------
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] <-- spinme called 500M times 333M by calcme2, 166M by calcme1
-----------------------------------------------
1.01 3.84 333333334/333333334 main [1] <-- calcme2 called 333M times by main
[3] 55.7 1.01 3.84 333333334 calcme2 [3]
3.84 0.00 333333334/500000001 spinme [2] <-- calcme2 calls spinme 333M times
-----------------------------------------------
0.54 1.92 166666667/166666667 main [1] <-- calcme1 called 166M times by main
[4] 28.2 0.54 1.92 166666667 calcme1 [4]
1.92 0.00 166666667/500000001 spinme [2] <-- calcme1 calls spinme 166M times
-----------------------------------------------
Dumping program as assembler (objdump)
Sometimes you will want to see the assembler representation of some code that you are profiling. This can be achieved using objdump -d (-d is disassemble.)
objdump output
$ objdump -d ./simple-no-pg-no-opt
./simple-no-pg-no-opt: file format elf64-x86-64
...
000000000000113c <main>:
113c: f3 0f 1e fa endbr64
1140: 55 push %rbp
1141: 48 89 e5 mov %rsp,%rbp
1144: 48 83 ec 20 sub $0x20,%rsp
1148: c7 45 f4 00 00 00 00 movl $0x0,-0xc(%rbp)
114f: c7 45 f0 00 00 00 00 movl $0x0,-0x10(%rbp)
1156: 48 c7 45 f8 00 e1 f5 movq $0x5f5e100,-0x8(%rbp)
115d: 05
115e: c7 45 ec 00 00 00 00 movl $0x0,-0x14(%rbp)
1165: eb 17 jmp 117e <main+0x42>
1167: 8b 45 ec mov -0x14(%rbp),%eax
Check to see if profiling is enabled
The easiest way to check to see if a binary has been compiled with -pg for profiling is to look for the presence of the gprof symbols mcount and __monstartup use nm to dump the symbols.
$ nm simple_caller_pg | egrep "monstart|mcount"
U mcount@GLIBC_2.2.5
U __monstartup@GLIBC_2.2.5
Understanding gprof overhead
The overhead of gprof comes mainly from the fact that for every function call the compiler inserts an additional function call (inside the user function call) to keep track of both the caller/callee and the exact number of times a function is called.
The remainder of gprof (time spent in each function) is sampled and is generally a lower overhead than the stack-tracing.
Therefore the overhead of gprof is mainly a function of how “large” each function is - or - how often are functions called as a proportion of the overall runtime. Many tiny functions will have a high overhead - fewer, longer-running functions will have a larger overhead.
Example overhead with many tiny function calls
The overhead of profiling is 3X! when we have many calls to a short function
$ time ./simple-no-pg-no-opt
real 0m0.378s
user 0m0.375s
sys 0m0.002s
$ time ./simple-with-pg-no-opt
real 0m1.346s
user 0m1.344s
sys 0m0.0
Example overhead when functions do some work
In this case we just insert a spin-loop into the same example - the runtime is longer in both cases, but the difference between profiled and non-profiled is closer to 30% rather than 300%
$ time ./calcme-with-inner-loop
real 0m9.968s
user 0m9.961s
sys 0m0.001s
$ time ./calcme-with-inner-loop-pg
real 0m13.811s
user 0m13.801s
sys 0m0.004s
Measuring overhead with oprofile
We can get a sense of the overhead that stack-counting costs us by running a profile enabled program under oprofile. We see that nearly 60% of the runtime in this example is attributed to mcount + __mcount_internal.
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 100000
samples % image name symbol name
309643 48.4532 libc.so.6 __mcount_internal
159212 24.9136 calcme-nested-asymmetric-pg spinme
73298 11.4697 libc.so.6 mcount
45451 7.1122 calcme-nested-asymmetric-pg main
32565 5.0958 calcme-nested-asymmetric-pg calcme2
17216 2.6940 calcme-nested-asymmetric-pg calcme1
318 0.0498 kallsyms __irqentry_text_end
Understanding the effects of profiler optimization on gprof
Since gprof relies on inserting additional code into every function call - gprof will be affected by anything which reduces function calls. This is often done by compiler optimization to save time.
Furthermore, when generating trivial test code - the compiler optimizer will simply throw away code where the results are not used. Take a look at the objdump output of the binary compiled with optimizations - because of the simplicity of the code the program basically enters main() and immediately returns! The profile looks a bit weird, because in this case it’s totally empty, but the objdump shows us why.
Profile of un-optimized compilation
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ns/call ns/call name
70.59 0.12 0.12 100000001 1.20 1.20 calcme
29.41 0.17 0.05 main
Profile of optimized compilation
Flat profile:
Each sample counts as 0.01 seconds.
no time accumulated
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
objdump of unoptimized code
This binary was compiled with no optimizations.
$ objdump -d ./simple-no-pg-no-opt
./simple-no-pg-no-opt: file format elf64-x86-64
...
000000000000113c <main>:
113c: f3 0f 1e fa endbr64
1140: 55 push %rbp
1141: 48 89 e5 mov %rsp,%rbp
1144: 48 83 ec 20 sub $0x20,%rsp
1148: c7 45 f4 00 00 00 00 movl $0x0,-0xc(%rbp)
114f: c7 45 f0 00 00 00 00 movl $0x0,-0x10(%rbp)
1156: 48 c7 45 f8 00 e1 f5 movq $0x5f5e100,-0x8(%rbp)
115d: 05
115e: c7 45 ec 00 00 00 00 movl $0x0,-0x14(%rbp)
1165: eb 17 jmp 117e <main+0x42>
1167: 8b 45 ec mov -0x14(%rbp),%eax
116a: 89 c7 mov %eax,%edi
116c: e8 b8 ff ff ff call 1129 <calcme>
1171: 89 45 f4 mov %eax,-0xc(%rbp)
1174: 8b 45 f4 mov -0xc(%rbp),%eax
1177: 01 45 f0 add %eax,-0x10(%rbp)
117a: 83 45 ec 01 addl $0x1,-0x14(%rbp)
117e: 8b 45 ec mov -0x14(%rbp),%eax
1181: 48 98 cltq
1183: 48 39 45 f8 cmp %rax,-0x8(%rbp)
1187: 7d de jge 1167 <main+0x2b>
1189: b8 00 00 00 00 mov $0x0,%eax
118e: c9 leave
118f: c3 ret
...
objdump of optimized code
This binary was compiled with -Ofast.
$ objdump -d ./simple-no-pg-Ofast
./simple-no-pg-Ofast: file format elf64-x86-64
...
0000000000001040 <main>:
1040: f3 0f 1e fa endbr64
1044: 31 c0 xor %eax,%eax
1046: c3 ret
1047: 66 0f 1f 84 00 00 00 nopw 0x0(%rax,%rax,1)
104e: 00 00
...
As we see we enter <main> then immediately return! So, not only is the optimized code fast - there is nothing for gmon to report since there were no function calls, and the program probably exited before any sampling of the PC was even attempted.
How does gprof profiling work
When gcc sets up profiling, it does three main things - it inserts a call to __gmon_start__ at the beginning of the execution, and then inserts mcount into every function. When the program exits, it writes the accumulated profiling information to gmon.out
gmon_start
There is a call to __gmon_start__ at the beginning of execution, this sets up things like a timer to sample how long we spend in each function, basically it sets up an interrupt that samples the program counter (PC) of the program under test. Because the PC is “sampled” it - the duration is not 100% accurate.
0000000000001000 <_init>:
1000: f3 0f 1e fa endbr64
1004: 48 83 ec 08 sub $0x8,%rsp
1008: 48 8d 05 c1 00 00 00 lea 0xc1(%rip),%rax # 10d0 <__gmon_start__>
mcount
The compiler inserts a call to mcount in every function which records exactly how many times each function was called and where it was called from. This generates the count. Since mcount is itself a function - we are in effect asking the compiler to add an additional function call into EVERY existing function call in the program. For function calls that are short and called often - using -pg / gprof can create a massive overhead on the running program.
00000000000011d9 <calcme>:
11d9: f3 0f 1e fa endbr64
11dd: 55 push %rbp
11de: 48 89 e5 mov %rsp,%rbp
11e1: 48 83 ec 08 sub $0x8,%rsp
11e5: ff 15 fd 2d 00 00 call *0x2dfd(%rip) # 3fe8 <mcount@GLIBC_2.2.5>
A way of recording the execution (gmon.out)
Recording the execution is handled by the special code that the compiler inserts. After execution terminates, the recording is dumped to a file called gmon.out. To record the program in execution - just execute the code.
$ ./simple-with-pg-no-opt
<program exits>
$ file gmon.out
gmon.out: GNU prof performance data - version 1
A way of displaying the recorded information (gprof)
Once we have the gmon.out file, we have the “recording” of the program execution - but we need a way to display it. The gmon.out file does not contain anything we can read at the terminal
$ strings gmon.out
gmon
seconds
(obviously) the gmon.out that is created is “paired” with the binary that created it - if for instance you try and run gprof using a different binary than that which actually generated the gmon.out file it will run - but the output will be incorrect.
The gmon file does not contain a reference to the binary that was used to generate it. The output is just a text file on STDOUT that you can redirect.
Example profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ns/call ns/call name
70.59 0.12 0.12 100000001 1.20 1.20 calcme
29.41 0.17 0.05 main
mcount and monstartup detail
We can use objdump -d to see the assembly language for our file - when profiling is enabled we will see the calls to the special profiling functions (mcount and monstartup)
Counting stack frames and callers with mcount
$ objdump -d calcme-nested-asymmetric-pg
...
00000000000011d9 <spinme>:
11d9: f3 0f 1e fa endbr64
11dd: 55 push %rbp
11de: 48 89 e5 mov %rsp,%rbp
11e1: 48 83 ec 18 sub $0x18,%rsp
11e5: ff 15 fd 2d 00 00 call *0x2dfd(%rip) # 3fe8 <mcount@GLIBC_2.2.5>
...
000000000000121b <calcme1>:
121b: f3 0f 1e fa endbr64
121f: 55 push %rbp
1220: 48 89 e5 mov %rsp,%rbp
1223: 48 83 ec 18 sub $0x18,%rsp
1227: ff 15 bb 2d 00 00 call *0x2dbb(%rip) # 3fe8 <mcount@GLIBC_2.2.5>
...
0000000000001258 <calcme2>:
1258: f3 0f 1e fa endbr64
125c: 55 push %rbp
125d: 48 89 e5 mov %rsp,%rbp
1260: 48 83 ec 18 sub $0x18,%rsp
1264: ff 15 7e 2d 00 00 call *0x2d7e(%rip) # 3fe8 <mcount@GLIBC_2.2.5>
...
0000000000001295 <main>:
1295: f3 0f 1e fa endbr64
1299: 55 push %rbp
129a: 48 89 e5 mov %rsp,%rbp
129d: 48 83 ec 20 sub $0x20,%rsp
12a1: ff 15 41 2d 00 00 call *0x2d41(%rip) # 3fe8 <mcount@GLIBC_2.2.5>
Setting up PC sampling with monstartup
Disassembly of section .init:
0000000000001000 <_init>:
1000: f3 0f 1e fa endbr64
1004: 48 83 ec 08 sub $0x8,%rsp
1008: 48 8d 05 21 01 00 00 lea 0x121(%rip),%rax # 1130 <__gmon_start__>
100f: 48 85 c0 test %rax,%rax
1012: 74 02 je 1016 <_init+0x16>
1014: ff d0 call *%rax
1016: 48 83 c4 08 add $0x8,%rsp
101a: c3 ret
...
0000000000001130 <__gmon_start__>:
1130: f3 0f 1e fa endbr64
1134: 8b 05 d6 2e 00 00 mov 0x2ed6(%rip),%eax # 4010 <__TMC_END__>
113a: 85 c0 test %eax,%eax
113c: 74 02 je 1140 <__gmon_start__+0x10>
113e: c3 ret
113f: 90 nop
1140: 48 83 ec 08 sub $0x8,%rsp
1144: 48 8d 35 f2 04 00 00 lea 0x4f2(%rip),%rsi # 163d <etext>
114b: 48 8d 3d ae ee ff ff lea -0x1152(%rip),%rdi # 0 <__executable_start>
1152: c7 05 b4 2e 00 00 01 movl $0x1,0x2eb4(%rip) # 4010 <__TMC_END__>
1159: 00 00 00
115c: e8 5f ff ff ff call 10c0 <__monstartup@plt>
1161: 48 8b 3d 78 2e 00 00 mov 0x2e78(%rip),%rdi # 3fe0 <_mcleanup@GLIBC_2.2.5>
...
00000000000010c0 <__monstartup@plt>:
10c0: f3 0f 1e fa endbr64
10c4: f2 ff 25 e5 2e 00 00 bnd jmp *0x2ee5(%rip) # 3fb0 <__monstartup@GLIBC_2.2.5>
10cb: 0f 1f 44 00 00 nopl 0x0(%rax,%rax,1)
Example programs
Here are the programs used in this how-to
simple.c
simple function call, which does very little. The overhead with gprof is very high.
int calcme(int i) {
return(i*i);
}
int main() {
int i,res=0,total=0;
long int iterations=100000000;
for (i=0 ; i <= iterations ; i++) {
res=calcme(i);
total=total+res;
}
}
simple with spinloop
int calcme(int i) {
long z,innerloop=10;
for (i=0 ; i <= innerloop ; i++) {
z=i*i;
}
return(i*i*z);
}
int main() {
int i,res=0,total=0;
long int iterations=500000000;
for (i=0 ; i <= iterations ; i++) {
res=calcme(i);
total=total+res;
}
}
calcme-nested-asymmetric
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;
}
Why does gprof show zero for timing
If profile enabled program is run under a debugger or profiler that also uses the same interrupt as gprof to do PC sampling then the output of gprof shows zero for times, but does generate accurate stacks e.g.
There may be other reasons, but most likely you ran the program under another profiler.
Each sample counts as 0.01 seconds.
no time accumulated
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
0.00 0.00 0.00 500000001 0.00 0.00 spinme
0.00 0.00 0.00 333333334 0.00 0.00 calcme2
0.00 0.00 0.00 166666667 0.00 0.00 calcme1
Call graph
granularity: each sample hit covers 4 byte(s) no time propagated
index % time self children called name
0.00 0.00 166666667/500000001 calcme1 [3]
0.00 0.00 333333334/500000001 calcme2 [2]
[1] 0.0 0.00 0.00 500000001 spinme [1]
-----------------------------------------------
0.00 0.00 333333334/333333334 main [9]
[2] 0.0 0.00 0.00 333333334 calcme2 [2]
0.00 0.00 333333334/500000001 spinme [1]
-----------------------------------------------
0.00 0.00 166666667/166666667 main [9]
[3] 0.0 0.00 0.00 166666667 calcme1 [3]
0.00 0.00 166666667/500000001 spinme [1]
-----------------------------------------------
Misc
Un-annotated output
Flat profile
$ gprof -b ./calcme-nested-asymmetric-pg
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ns/call ns/call name
66.19 5.76 5.76 500000001 11.53 11.53 spinme
16.07 7.17 1.40 main
11.60 8.18 1.01 333333334 3.03 14.56 calcme2
6.14 8.71 0.54 166666667 3.21 14.74 calcme1
Call graph
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]
-----------------------------------------------
Index by function name
[4] calcme1 [1] main
[3] calcme2 [2] spinme
End-to-end gprof session
For example let’s look at a really simple ‘C’ program and compile it with two different optimization levels, then use gprof to tell us why one is faster than the other.
Using gprof to understand compiler optimizations
Our C program
int calcme(int i) {
return(i*i);
}
int main() {
int i,res=0,total=0;
long int iterations=100000000;
for (i=0 ; i <= iterations ; i++) {
res=calcme(i);
total=total+res;
}
}
Runtime measurements
Test program compiled with No Optimizations
First we compile the program with no optimizations and then time it. The runtime with no optimizations is 0m0.344s
$ gcc -o simple-no-pg-no-opt simple.c
$ time ./simple-no-pg-no-opt
real 0m0.344s
user 0m0.343s
sys 0m0.001s
Test program compiled with optimizations (Ofast)
Next we take the same program and compile it with -Ofast which will try and optimize the compiled code. The runtime with -Ofast is 0m0.001s which is a LOT faster.
$ gcc -o simple-no-pg-Ofast -Ofast simple.c
$ time ./simple-no-pg-Ofast
real 0m0.001s
user 0m0.000s
sys 0m0.001s
Analysis with gprof
By taking the timing measurements we can see that using the -Ofast compiler option is improving the runtime by a LOT. However we do not know why the optimized program is so much faster. We can use gprof to give us some clues. We will re-compile the program with profiling/instrumentation enabled (-pg) and compare the output of gprof when we run the instrumented binary with/without optimizations
Steps
- First we need to re-compile our program with the
-pgoption which will create an instrumented binary - Second we need to run the instrumented binary. When the program exits, it will create a file called
gmon.out - Third we use
gprofto read the instrumented binary AND thegmon.outfile (we dont need to specify gmon.out - gprof assumes that) - Lastly we analyze the output of
gprofto see what was going on
gprof analysis of program without compiler optimizations
- Compile the program with profiling (
-pg) but no optimizations
$ gcc -o simple-with-pg-no-opt -pg simple.c
- Run the instrumented program - at exit, the
gmon.outfile is generated
$ ./simple-with-pg-no-opt
- Run gprof - we don’t need to specify
gmon.outbecausegprofassumes that.
$ gprof ./simple-with-pg-no-opt
- Next we can look at the output of gprof (the profile) and see how the program ran. We see that
main()calledcalcme()100000001 times as expected.
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ns/call ns/call name
70.59 0.12 0.12 100000001 1.20 1.20 calcme
29.41 0.17 0.05 main
gprof analysis of program with compiler optimizations (-Ofast)
- Compile the program with profiling (
-pg) and optimizations (-Ofast)
$ gcc -o simple-with-pg-Ofast -Ofast -pg simple.c
- Run the instrumented program - at exit the
gmon.outfile is generated
$ ./simple-with-pg-Ofast
- Run gprof - we don’t need to specify
gmon.outbecausegprofassumes that.
$ gprof ./simple-with-pg-Ofast
- Finally we take a look at this profile that was generated by a binary compiled with
-Ofast; it looks like nothing ran at all. No wonder it was fast!
Flat profile:
Each sample counts as 0.01 seconds.
no time accumulated
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
What did gprof tell us?
By enabling gprof we were able to tell that the optimization (-Ofast) eliminated the calls to calcme() which sped up the program execution a lot! Since the result of calcme() was never used by the caller - this is a legitimate optimization for the compiler to make.
We could also figure out what the optimizer had done by disassembling the compiled program. This is simple enough with our trivial example - but much harder to do with a larger/longer execution
Analysis by disassembly
Looking at the compiled code in assembler
The profile output has shown us what is happening during execution. We can take a peek at the assembly to see exactly what’s happening… we use objdump -d to decode the binary.
objdump: Program compiled with no Optimizations
We see the main() function setup, and crucially loop around making calls to <calcme>.
$ objdump -d ./simple-no-pg-no-opt
./simple-no-pg-no-opt: file format elf64-x86-64
...
000000000000113c <main>:
113c: f3 0f 1e fa endbr64
1140: 55 push %rbp
1141: 48 89 e5 mov %rsp,%rbp
1144: 48 83 ec 20 sub $0x20,%rsp
1148: c7 45 f4 00 00 00 00 movl $0x0,-0xc(%rbp)
114f: c7 45 f0 00 00 00 00 movl $0x0,-0x10(%rbp)
1156: 48 c7 45 f8 00 e1 f5 movq $0x5f5e100,-0x8(%rbp)
115d: 05
115e: c7 45 ec 00 00 00 00 movl $0x0,-0x14(%rbp)
1165: eb 17 jmp 117e <main+0x42>
1167: 8b 45 ec mov -0x14(%rbp),%eax
116a: 89 c7 mov %eax,%edi
116c: e8 b8 ff ff ff call 1129 <calcme>
1171: 89 45 f4 mov %eax,-0xc(%rbp)
1174: 8b 45 f4 mov -0xc(%rbp),%eax
1177: 01 45 f0 add %eax,-0x10(%rbp)
117a: 83 45 ec 01 addl $0x1,-0x14(%rbp)
117e: 8b 45 ec mov -0x14(%rbp),%eax
1181: 48 98 cltq
1183: 48 39 45 f8 cmp %rax,-0x8(%rbp)
1187: 7d de jge 1167 <main+0x2b>
1189: b8 00 00 00 00 mov $0x0,%eax
118e: c9 leave
118f: c3 ret
...
objdump: Program compiled with optimizations
When we do the same thing on the binary compiled with optimizations - we see that main basically just returns!
$ objdump -d ./simple-no-pg-Ofast
./simple-no-pg-Ofast: file format elf64-x86-64
...
0000000000001040 <main>:
1040: f3 0f 1e fa endbr64
1044: 31 c0 xor %eax,%eax
1046: c3 ret
1047: 66 0f 1f 84 00 00 00 nopw 0x0(%rax,%rax,1)
104e: 00 00
...
In this extremely simple case it is just as easy to look at the compiled code in assembly language and observe what is going on at runtime. However with a much larger piece of code - having the profile can be very useful to us when we want to understand program execution at runtime.