The IgProf output is a simple text file, possibly gzip / bzip2 compressed. The first few lines of the output look like this:
P=(ID=32365 N=(ls) T=0.010000) C1 FN0=(F0=(/lib/tls/libc.so.6)+87962 N=(__libc_start_main))+218 C2 FN1=(F1=(ls)+8661 N=(strcoll))+2753 C3 FN2=(F1+14168 N=(strftime))+8740 C4 FN3=(F1+19717 N=(@?0x804cd05))+0 C5 FN4=(F0+171919 N=(qsort))+143 C6 FN5=(F0+171435 N=(@?0x13adab))+0 C7 FN5+0 C8 FN5+0 C9 FN6=(F0+171396 N=(@?0x13ad84))+0 C10 FN5+0 C11 FN5+0 C12 FN7=(F0+171552 N=(@?0x13ae20))+0 C13 FN8=(F1+19068 N=(@?0x804ca7c))+0 C14 FN9=(F1+17715 N=(@?0x804c533))+0 V0=(PERF_TICKS):(1,1,1) C3 FN2+8334 V0:(1,1,1) C3 FN2+8538
Each line of the profile output describes one piece of information, usually
just a call frame. The general format is “keyword”, usually just one letter,
either a reference or a definition, followed by trailing data. For example
A1=(foo)+5 would be definition of instance 1 of type
A, whose parameters
foo, followed by delta offset 5. A simple
A1 would be a reference to
an already redefined entity 1 of type
A1+4 would be a delta offset 4 of
instance 1 of type
A. Every instance is defined before referred to, no
instance is defined twice, and a definition may occur anywhere a reference
The possible top level entities are:
Pgives information about the progrram that was profiled. It is always on the very first line of the profile, and never occurs after that. An example is given below. It says the program name was
ls, the process id was 32365 and each performance profiler tick (
PERF_TICKS) marks 0.01 seconds.
P=(ID=32365 N=(ls) T=0.010000)
Cdefines a call frame and is always followed by a number indicating the depth of a call stack. This is followed by rest of the data for that call frame. The stack depth numbers always start from one, indicating calls from the operating system. If the call stack number is greater than the number on the previous line, it indicates a function called by the previous line. If the number is less or equal, the call stack is assumed to pop to previous line less than that depth, and calls continue from there. In other words the output includes actual call stacks, not flattened caller/callee pairs. Only unique call stacks are shown however, the counter values include information about how many times each counter was ticked, and the final sum total value of the counter.
The call stack (
C) entries may be followed function descriptor and counter values. The function descriptors are composed of:
FNfunction definition or reference, followed by a delta offset from the beginning of that symbol. Two examples are given below. The first one says the call stack level 2 was at offset 2753 into a function number 1 named
strcoll. The second defines an anonymous function 5 at call stack level 6, then recursive call at the same address at call stack level 7.
C2 FN1=(F1=(ls)+8661 N=(strcoll))+2753 C3 FN2=(F1+14168 N=(strftime))+8740</verbatim>
C6 FN5=(F0+171435 N=(@?0x13adab))+0 C7 FN5+0
Ffile definition or reference, followed by an virtual memory (VMA) offset in the object file. In the first example above, function 1, “strcoll”, is was defined in file “ls” and starts at VMA offset 8661; the actual call was at offset 2753 into that function. That function called function 2, “strftime”, at “ls” VMA offset 14168 plus 8740. Note that this is the information available from the dynamic linker and may be inaccurate; in this is case it’s highly likely to be inaccurate. Better symbol definitions are often available by inspecting the VMA addresses with NM or GDB, and igprof-analyse does exactly that if you give it the “-g” option. (FIXME: Replace the example with something actually more useful!?)
Vcounter definition or reference, followed by counter values. An example is given below. The first line defines counter 0 as PERF_TICKS, and indicates the function has an accumulated counter value 1, resulting from 1 call, and the peak value this counter had was also 1. (For performance ticks all three values will always be identical as each clock tick increments the counter. The values are different for memory profiling where the value of the counter is size in bytes and the call count is the number of memory allocation calls.) The second line defines another similar entry for another function.
C14 FN9=(F1+17715 N=(@?0x804c533))+0 V0=(PERF_TICKS):(1,1,1) C3 FN2+8334 V0:(1,1,1)</verbatim>
Vrecord may be followed by leaked resources for resource counters such as
MEM_LIVE. For each leaked resource allocated by the stack trace in question there will be a
LKentry, as shown below. The entry shows that function 796, an anonymous function in object file 39, leaked two resources in counter 2 for a total size of 722 bytes, the first 615 bytes at address 0x91441c8, the second 107 bytes at address 0x91633c0.
C17 FN796=(F39+21941 N=(@?0x2375b5))+0 V0:(2,722,0) V1:(2,615,0) V2:(2,722,722);LK=(0x91441c8,615);LK=(0x91633c0,107)