Callgrind main() inclusive cost much smaller than 100%

Question

I profiled a few very simple C++ programs running on Linux. The inclusive cost of main() for all of them is far from 100%, something like 3.83%. Am I using callgrind correctly? I have the output of callgrind_annotate with --inclusive=yes pasted below.

The program is called heap which does simple heap sort. The command I used is

valgrind --tool=callgrind ./heap

Then, I type

callgrind_annotate --inclusive=yes callgrind.out.25434

Output:

`--------------------------------------------------------------------------------

Profile data file 'callgrind.out.25434' (creator: callgrind-3.6.0)

`--------------------------------------------------------------------------------

I1 cache:
D1 cache:
LL cache:
Timerange: Basic block 0 - 361578
Trigger: Program termination
Profiled target:  ./heap (PID 25434, part 1)
Events recorded:  Ir
Events shown:     Ir
Event sort order: Ir
Thresholds:       99
Include dirs:
User annotated:
Auto-annotation:  off

`--------------------------------------------------------------------------------

       Ir
`--------------------------------------------------------------------------------

2,552,558  PROGRAM TOTALS

`--------------------------------------------------------------------------------

       Ir  file:function

`--------------------------------------------------------------------------------

2,552,558  ???:0x00000810 [/lib/ld-2.7.so]

2,515,793  ???:0x00000a60 [/lib/ld-2.7.so]

2,515,219  ???:0x00015270 [/lib/ld-2.7.so]

2,514,780  ???:0x000021e0 [/lib/ld-2.7.so]

2,456,164  ???:0x0000b2f0 [/lib/ld-2.7.so]

2,256,719  ???:0x00009e40 [/lib/ld-2.7.so]

1,702,371  ???:0x00009ac0 [/lib/ld-2.7.so]

  657,883  ???:0x000098e0 [/lib/ld-2.7.so]

  367,045  ???:0x00017040 [/lib/ld-2.7.so]

   33,170  ???:0x080483e0 [/home/test/heap]

   33,036  ???:0x0000ce60 [/lib/ld-2.7.so]

   31,347  ???:0x0000e850 [/lib/ld-2.7.so]

   30,706  ???:(below main) [/lib/libc-2.7.so]

   30,071  ???:0x00008570 [/lib/ld-2.7.so]

   27,954  ???:0x0000f500 [/lib/ld-2.7.so]

   27,758  ???:0x0000ca30 [/lib/ld-2.7.so]

   21,366  ???:0x0001767b [/lib/ld-2.7.so]

Answer 1

The main() is not the top function in call graph. There is an _start function in glibc, which will call main() and it also will take return value from main. Also there is (for dynamically linked programs = almost all) an ELF interpreter, also known as dynamic linker (run-time): /lib/ld-linux.so (this name is used in linux, in other Unixes something like /lib/ld.so). Linker will load and initialize all dynamic libraries needed by the application; and it is called by OS before _start.

What is done before main? Loading of libraries (open library file, parse its header, mmap it, adopt code for new location in memory=relocations processing), and initialization of them (both dynamically and statlically linked libraries need this; note that glibc=libc is library too). Each library may have a code, which will be started just after loading of the library (__attribute__((constructor)) or non-trivial constructors of global objects). Also, glibc can register some functions to be run after main (e.g. via atexit(); if main returns normally, they will be called by _start), and libraries may have a destructor functions for global objects.

If your program uses threads, the top function of threads 1..n will be not a main (each thread can separate stack; and chain of function calls from main is stored in stack of thread 0).

In your example we see /lib/ld-*.so, and it is a dynamic linker. Seems, your application execution is too short to be correctly profiled and it uses high number of dynamic libraries.