-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Using gprof
The gprof utility is used to analyze and view the profile data contained in the gmon.out files. Two versions of gprof are available on the Blue Gene/Q system: the standard gprof (in /usr/bin) and powerpc64-bgq-linux-gprof (in /bgsys/drivers/ppcfloor/gnu-linux/bin). The latter version provides some additional functionality over the standard version, but both provide the same functionality for standard operations. Basic usage of gprof is:

   gprof <executable-file> gmon.out.<id> {gmon.out.<id> ...}

    or

   powerpc64-bgq-linux-gprof <executable-file> gmon.out.<id> {gmon.out.<id> ...}
When multiple gmon.out.<id> files are specified, the profile data is summed across all gmon.out.<id> files and then displayed. The most commonly used options for gprof are:

   -p : display flat profile
   -P : suppress display of flat profile
   -q : display call graph information
   -Q : suppress display of call graph information
   -l : displays instruction profile at source line level instead of function level (requires debug info)
   -C : display routine names and the execution counts obtained by invocation profiling
   -A : print annotated source code, only annotates with function call count (requires debug info)
   -s : sums all the profile data for the specified input files and writes the results to the file gmon.sum
   -I : search path for source files, used mostly for annotating source (can also use GPROF_PATH environment variable)
   -b : prevents gprof from printing the verbose descriptions of the output
   -d : shows gprof debugging information, can be used to access raw data in gmon files
   -S : A Blue Gene specific option that allows large numbers of gmon.out files to be combined. Sequentially sums
        the gmon.out files in a directory, starting with gmon.out.0 until the next in the sequence is not found.
        The result are placed in gmon.sum.
If invoked without any options, the default gprof behavior is the same as specifying the options '-p –q,' meaning a flat profile and call graph information will be displayed.

Five basic output forms can be produced by gprof:

A routine level flat profile;
A line level flat profile;
Call graph information;,
A routine execution count list; and
Source code annotated with routine call counts.
These output forms are described below and share several common aspects and, in many cases, present the same information in different forms. As described earlier, time estimates are based on the number of executing instruction observed at an interrupt interval that belongs to a routine. By default, the sampling interval is 0.01 seconds, so each observation of an instruction represents 0.01 seconds of execution time in that routine. Therefore, all times reported extend to one-hundredth of a second. The number of observed instructions for a routine is the time reported for the routine divided by the sampling interval of 0.01 seconds

Some routines may execute with an execution time low enough that no executing instructions were observed. These routines will be estimated to have an execution time of zero seconds. If invocation profiling was not enabled for these routines or if the invocation count is zero, these routines will not be listed in the gprof output. If, however, the invocation count is non-zero, the routine will be listed even if the estimated execution time is zero.

Due to the sampling methodology employed, execution times are estimates with large relative error for small execution counts. Conversely, routine invocation counts are exact and will not vary between identical runs of a program. The calculated routine child times are subject to error due to error in the routine time estimates and due to the assumption that all invocations of a routine take the same amount of time.

Back to top
Routine Level Flat Profile
The flat profile, generated with the '-p' option, presents a list of routines that were estimated to consume time while the program was running or were invoked at least once, sorted by the amount of time the routine consumes. The flat profile provides an easy way to see which routines consume the largest percentage of the program run time and are therefore good candidates for optimization. An example of a flat profile (for the example described in the Invocation Profiling section above) is shown below.

  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 50.23      9.98     9.98       10     1.00     1.00  routine2
 24.91     14.93     4.95        1     4.95    13.91  routine1
 14.95     17.90     2.97        2     1.49     1.49  routine3
  9.91     19.87     1.97        1     1.97    19.87  main
The third column in the output above, labeled “self seconds,” shows the time estimated to be spent in the routine. The time reported may be estimated to be zero if no instructions for that routine were observed to be executing. The first column shows the self time as a percentage of the total run time. The second column, labeled “cumulative seconds,” shows an accumulation of the self time in the rows above; therefore, for the last entry it represents the total estimated run time of the program. The fourth column shows the number of times a routine was called, as recorded by the framework’s invocation profiling mechanism. If a routine was compiled without invocation profiling enabled (with '-pg'), this information is not recorded for that routine and the call count will be blank.

The fifth column, “self s/call,“ is simply the self seconds divided by the number of call to the routine and represents the average spent in the routine time per call. The sixth column, “total s/call,” is the self time plus the estimated child time divided by the number of calls to the routine. It represents the total time used per call to a routine, including the time in the routine and in the routines that it calls.

Back to top
Line Level Flat Profile
The line level profile, generated with the '-l -p' option, presents the same information as the routine level flat profile but with times broken out at the source code line level instead of at the routine level. Generating this profile requires that the routine be compiled with the '-g' option so as to include the debugging information. Generating this profile for large programs can take significant time.

  %   cumulative   self             self     total           
 time   seconds   seconds   calls  Ts/call  Ts/call  name    
 36.49      7.25     7.25                            routine2 (routine2.c:5 @ 1001604)
 16.26     10.48     3.23                            routine1 (routine1.c:9 @ 10014e4)
 13.74     13.21     2.73                            routine2 (routine2.c:6 @ 10015f8)
 10.57     15.31     2.10                            routine3 (routine3.c:5 @ 10016c4)
  8.66     17.03     1.72                            routine1 (routine1.c:10 @ 10014d8)
  7.00     18.42     1.39                            main (gprof_test.c:13 @ 10013bc)
  4.38     19.29     0.87                            routine3 (routine3.c:6 @ 10016b8)
  2.92     19.87     0.58                            main (gprof_test.c:14 @ 10013b0)
  0.00     19.87     0.00      10     0.00     0.00  routine2 (routine2.c:1 @ 10015a0)
  0.00     19.87     0.00       2     0.00     0.00  routine3 (routine3.c:1 @ 1001660)
  0.00     19.87     0.00       1     0.00     0.00  main (gprof_test.c:9 @ 1001360)
  0.00     19.87     0.00       1     0.00     0.00  routine1 (routine1.c:5 @ 1001480)
Back to top
Call Graph Analysis
The call graph analysis, generated with the -q option, displays information about a routine, its child routines, and its parent routines. Each section of the call graph analysis provides information pertaining to a specific routine.

The routine of interest is indicated by its index number in the first column and indentation from the lists of parent and child routines. The percentage of time listed in the second column indicates the percentage of program runtime accounted for by the routine and its children. The self column indicates times with different meanings depending on whether it is for the primary routine for that section or the routine's parent or child routines. For the primary routine, the time represents the time spent in that routine during the execution of the program. For a parent routine, it represents the amount of the primary routine’s self time being propagated to that parent, based on the percentage of calls to the primary routine made by that parent. For a child routine, it represents the amount of that child routine’s self time being propagated to the primary routine based on percentage of calls made to that routine by the primary routine.

Similarly for the “children” column, the times reported vary depending on the routine context. For the primary routine, it is the total amount of time from child routines propagated to that routine; for child routines, it is the amount of that routine’s child time being propagated to the primary routine; and for parents, it is the amount of the primary routine’s child time being propagated to that parent.

The ”called” columns indicate the number of times the primary routine was called, and the fraction of call made from parents and to children. Allocations of time from child routines to parent routines are based on the fraction of calls to the child routine made by the parent, using the (sometimes incorrect) assumption that each call to a routine takes the same amount of time. If a routine was not compiled with the '-pg' option to enable invocation profiling, its parent routines will be unknown and indicated as <spontaneous>. If no routines are compiled with invocation profiling enabled, no call graph analysis information will be available (call graph analysis output may need to be suppressed with the -Q option in order for gprof to run).

On the Blue Gene, the system libraries and other libraries (such as MPI) have not been compiled with invocation profiling enabled, so parent functions for those routines cannot be determined and the routines parent will be listed as <spontaneous>. The line-by-line option, '-l', may be used with the call graph analysis option, '-q', to present the call graph analysis information broken down on a source line basis.

index % time    self  children    called     name
    1.97   17.90       1/1           generic_start_main [2]
[1]    100.0    1.97   17.90       1         main [1]
                4.95    8.96       1/1           routine1 [3]
                3.99    0.00       4/10          routine2 [4]
-----------------------------------------------
                                                 <spontaneous>
[2]    100.0    0.00   19.87                 generic_start_main [2]
                1.97   17.90       1/1           main [1]
-----------------------------------------------
                4.95    8.96       1/1           main [1]
[3]     70.0    4.95    8.96       1         routine1 [3]
                5.99    0.00       6/10          routine2 [4]
                2.97    0.00       2/2           routine3 [5]
-----------------------------------------------
                3.99    0.00       4/10          main [1]
                5.99    0.00       6/10          routine1 [3]
[4]     50.2    9.98    0.00      10         routine2 [4]
-----------------------------------------------
                2.97    0.00       2/2           routine1 [3]
[5]     14.9    2.97    0.00       2         routine3 [5]
Back to top
Routine Execution Count List
The routine execution count list, generated with the -C option, displays a simple list of routines and the execution counts for the routines as recorded by the invocation profiling mechanism. If a routine was not compiled with invocation profiling enabled, it will not appear in the list.

   /gpfs/gprof_tests/src/gprof_test.c:9: (main:0x1001360) 1 executions
   /gpfs/gprof_tests/src/routine1.c:5: (routine1:0x1001480) 1 executions
   /gpfs/gprof_tests/src/routine2.c:1: (routine2:0x10015a0) 10 executions
   /gpfs/gprof_tests/src/routine3.c:1: (routine3:0x1001660) 2 executions
Back to top
Annotated Source Listing
The annotated source listing, generated with the -A option, displays the program source code annotated with the number of calls made to the routines. This output can only be produced if the program was compiled with the debugging information option, '-g.'

   *** File /gpfs/gprof_tests/src/routine2.c:
          10 -> void routine2(int *x) {
                  *x= *x+2; 
                
                  int a;
                  for(int j=0; j < 60600000; j++) {
                    a++;
                  }
                
                  return;
                  }
Back to top
Issues in Interpreting Profile Data
Several considerations must be keep in mind when interpreting the information reported by gprof:

The times reported by gprof are estimates based on the instructions observed to be executing when the program is interrupted at the end of the sampling interval. A consequence of this sampling methodology is that time estimates may vary from run to run and contain high relative error when based on a small number of observations.
The expected error in a time estimate is the square root of the number of observations upon which it is based. For example, for an estimate based on 9 observations, the expected error is approximately 3 and the relative error is 33.3%. For an estimate based on 400 observations, the expected error is 20, or about 5%.
Sampling with gprof imposes some overhead on the execution of the program. This overhead is generally small for instruction profling (only linking with -pg) and is generally small, but can in some instances be signficant, for invocation profiling (compiling and linking with -pg). If a significant amount of time is reported in the mcount() (or _mcount or __mcount) routine turning off invocation profiling can reduce the overhead.
The time spent in all functions, including all functions called within a library, is reported by gprof. This can make the output hard to interpret as many of the reported functions may be low level library functions that are not otherwise visible user of the library. For example a call to MPI_Bcast() may spend relatively little time in the MPI_Bcast() routine itself and most of its time in supporting function (on the BG/Q these are often PAMI functions). As a result gprof may show time spent in numerous PAMI functions, some of which may have also been called from other MPI routines, and no time directly in MPI_Bcast(). It is therefore hard to determine the total time spent in specific library routines, such as MPI_Bcast(), that are called directly from user code.
Routines that execute quickly may register no observations, and therefore have a time estimate of 0.00 seconds, despite having an actual non-zero runtime.
Routines compiled without invocation profiling enabled (without the '-pg' option) will not have call counts reported and will not have identified parent routines. Parents will be labeled as <spontaneous>.
Routines with no observations and for which invocation profiling was not enabled (compiled without '-pg') will not be reported by gprof despite being called and having a (very small) runtime.
When attributing time from a child routine to a parent routine, it is assumed that all calls to that child routine, from the parent routine of interest or from any other caller of that child routine, take the same amount of time. If this assumption is incorrect, significant errors in child time estimates may occur.
gprof show only time spent in user code, not in system calls. Therefore, time spent performing IO and other tasks involving the operating system will not be reported. For codes spending significant time system call the total runtime reported by gprof will be noticeably lower than the actual runtime of the code.
Compiler optimization can produce errors in time estimates and call counts.
Recursive routines require special consideration in how their call graph analysis is generated. See the gprof documentation in the References section for details.
Back to top
Profiling Concepts
The information presented by the gprof framework is derived from the two basic types of information

it can collect: 1) a record of which portion of the program was observed to executing when the program is interrupted at regular intervals, and 2) a count of how many times a routine is invoked along with a record of the location in the program from which that routine was invoked.

Back to top
Programs in Memory
To understand the basic information the gprof framework collects, it is helpful to understand how a program looks after it is compiled and loaded into memory. Consider the routine:

   void test_routine() {
     int a=0;

     for(int j=0; j < 100; j++) {
       a++;
     }

     return;
     }
After it is compiled, linked, and loaded into memory, the routine becomes a series of machine instructions generated by the compiler from the source lines above that exist at a series of memory locations. An example of the routine on Blue Gene is shown below:

   00001000 <test_routine>:
     1000:   stwu    r1,-32(r1)
     1004:   li      r0,0  
     1008:   stw     r0,16(r1)
     100c:   li      r0,0  
     1010:   stw     r0,24(r1)
     1014:   cmpwi   r0,100
     1018:   bge-    3c <test_routine+0x3c>
     101c:   lwz     r3,16(r1)
     1020:   addi    r0,r3,1
     1024:   stw     r0,16(r1)
     1028:   lwz     r3,24(r1)
     102c:   addi    r0,r3,1
     1030:   stw     r0,24(r1)
     1034:   cmpwi   r0,100
     1038:   blt+    1c <test_routine+0x1c>
     103c:   b       40 <test_routine+0x40>
     1040:   addi    r1,r1,32
     1044:   blr   
The first line shows that the symbol <test_routine> is associated with the address 00001000. The following lines all contain three columns: 1) the address of the instruction, 2) the machine instruction, and 3) the operands of the instruction. In the simplest cases, when there is no significant re-ordering due to compiler optimization, all of the code in a routine becomes a sequential block of machine instructions that follow the symbol (here <test_routine>) that comes from the name of the routine. Each source code line generally maps to a sequence of machine instructions and each machine instruction maps to a source code line, usually with multiple instructions mapping to the same line of source code. Instruction Profiling

Back to top
Instruction Profiling
The first set of information is collected when a program, which is linked so as to include the gprof framework, is executed. When the program begins, the framework starts the timer which interrupts the execution of the program at a fixed interval. Typically, this interval or sampling frequency is every 10 milli-seconds, or every 0.01 seconds. At each interrupt, the address at which the program is executing is noted and recorded in an array in memory. At the end of the program execution, this array contains a count of the number of times the various instruction addresses were observed executing at the time of the interrupt, and the array is written to a file named gmon.out.

Using this instruction count information, it is possible to estimate the amount of time a program spent in a given routine. From the example above, any instructions in the address range 1000 to 1044 observed to be executing would be attributable to the routine test_routine(). If a program containing the routine test_routine() ran for 10 seconds, approximately 1000 interrupts would occur during its execution and at each interrupt an execution address is recorded. If 200 of the 1000 observed addresses were attributable to the routine test_routine(), it can be estimated that 20% of the program runtime, or 2 seconds, were spent in the test_routine() routine. This instruction address sampling method has the advantage of limited impact upon the program’s runtime, and minimal side effects.

Conversely, it has the disadvantage of being inexact: the instruction addresses observed depend on the exact timing of the interrupt and two different runs of the same program can produce different observed address counts. Following the earlier example, the first run of the program may show 200 observed instruction addresses attributable to test_routine(), a second execution of the program may show 195 observations in test_routine(), and a third execution may show 205. This variation is inherent in the sampling methodology; the error in the estimated time is inversely proportional to the number of observations. For large observation counts, the relative error will be small. There is only a 2.5% difference between 200 and 205 observations. For small observation counts, relative error can be quite significant: there is a 50% difference between 2 and 3 observations for a routine.

Back to top
Invocation Profiling
The second set of information, routine invocation counts and invoking locations, is collected when a program is executed. In addition to being linked to the gprof framework, routine invocation counts and invoking locations have routines compiled with compiler flags enabling routine invocation profiling. When a routine is compiled with routine invocation profiling enabled, the compiler inserts a call to a profiling library routine at the start of the routine. On the Blue Gene this routine is named _mcount(). An example of the earlier routine test_routine(), compiled with the routine invocation profiling enabled, the result is shown below:

00001000 <test_routine>:
  1000:   mflr    r0
  1004:   stw     r0,4(r1)
  1008:   lis     r12,0
  100c:   addi    r0,r12,0
  1010:   bl      <_mcount>          <- call to _mcount()
  1014:   stwu    r1,-32(r1)
  1018:   li      r0,0
  101c:   stw     r0,16(r1)
  1020:   li      r0,0
  1024:   stw     r0,24(r1)
  1028:   cmpwi   r0,100
  102c:   bge-    50 <test_routine+0x50>
  1030:   lwz     r3,16(r1)
  1034:   addi    r0,r3,1
  1038:   stw     r0,16(r1)
  103c:   lwz     r3,24(r1)
  1040:   addi    r0,r3,1
  1044:   stw     r0,24(r1)
  1048:   cmpwi   r0,100
  104c:   blt+    30 <test_routine+0x30>
  1050:   b       54 <test_routine+0x54>
  1054:   lwz     r0,36(r1)
  1058:   mtlr    r0
  105c:   addi    r1,r1,32
  1060:   blr
This result can be compared with the earlier version of the routine where invocation profiling was not used. The major difference is the instruction at the beginning is to set up for the call to _mcount() and the instruction "bl <_mcount>," which invokes the _mcount() routine (two additional instructions are also present at the end of the routine as a side effect of the call to _mcount()).

When the profiling library routine _mcount() is called, it unwinds the call stack and records the address from which it was called (in the above case, the address would be 1010). It also records the address from which the calling routine was invoked (the location from which test_routine() was called). The record of the two addresses is kept in memory. If the same two addresses are seen for multiple invocations of _mcount(), a counter for that pair of addresses is incremented. Unlike the counts obtained from instruction profiling, the counts from invocation profiling are not subject to error and will not vary from one execution of the same program to the next. The address pair count information is written to the gmon.out file at the end of the program execution.

As was the case with instruction profiling, the addresses recorded can be associated with program routines. The address pairs then resolves to pairs of routines that have a caller/callee relationship and represent links in a call graph. A call graph is a graph in which routines are nodes and a call between two routines is represented as a link between the nodes. An example call graph is shown below, where main() calls routine1() and routine2(), routine1() calls routine3() and also calls routine2().

             main()
             |  |
             |  |
             |  -> routine1()
             |       |  |
            \|/      |  |-> routine3()
        routine2() <-|
The collected address pairs and count information provides information on which links were active during the execution of a program and how many times a link was traversed. Using this information, the gprof framework can provide an estimate of the time spent not just in a routine, but also the cumulative time spent in all of the child routines invoked by that routine. For the call graph above, consider the example where the time spent in routines main(), routine1(), routine2(), and routine3() is estimated to be 2, 5, 10, and 3 seconds, respectively, from the instruction profile information.

Further consider that main() invokes routine1() 1 time and routine2() 4 times, and routine1() invokes routine2() six times and routine3() two times. The cumulative time spent in the child routines of routine1() is the sum of all of the time spent in routine3(), since it is only invoked by routine1(), and some fraction of the total time consumed by routine2() since routine2() is called by both main() and routine1().

The time attributable to routine1() is estimated based on the total fraction of calls to routine2() that came from routine1(). In this example, 6 of the 10 calls to routine2() originated in routine1() and therefore 6 of the 10 seconds consumed by routine2() are attributed to calls from routine1(). The child time for routine1() is then the 6 seconds from routine2() plus the 3 seconds from routine3() for a total of 9 seconds of child time. The self time for routine1() is the 5 seconds the routine itself consumes. The total time associated with the call to routine1() is then the self time plus the child time, or a total of 14 seconds.

Back to top
Conclusion
Profiling with the gprof framework provides a low-impact method for gathering information about the execution of a program. Estimates of the time spent in each program routine are provided by instruction profiling. Invocation profiling collects information that can be used to determine the number of times a routine was invoked, which links in the call graph were active, how many times each link was activated, and an estimate of the time spent in child routines attributable to the parent routine. In order to have minimal impact, basic execution address counts and call address pair counts are collected during program execution and written to the gmon.out file at the end of program execution. Since the collected information consists entirely of counts of a finite set of items (instructions addresses and call graph links), the amount of profile information does not increase with the runtime of the program. All analysis, such as mapping addresses to routines and assembly of the call graph, is done after program execution using the post-processing utility gprof.
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
GProf
This is the traditional profiling tool in UNIX® environments. It requires the help of the compiler to insert probes in the code. The theory of operation here is that the compiler inserts timing probes at every function as it compiles your program. When the program runs, the probing code generates timing information into a special file, which can then be analyzed with gprof.

To use gprof:

Enable profile code generation with -pg. This asks the compiler to insert timing probes in every function. Notice that it is not necessary to recompile every file in your application, only those that you want to instrument. It is also important to specify -pg when you are compiling each individual file and when you are linking the final binary. Otherwise, the runtime libraries used by gprof will not be linked in.
Run the application as you would normally do. The new code inserted by the compiler will write out timing information to a file named gmon.out. You should expect your program to run a bit slower, but the overhead is usually not too unpleasant.
Use gprof to analyze the file gmon.out. The default report provided by gprof is fairly verbose but it is also easy to understand.
As an example, we will use a small application that just eats up CPU time by doing repeated matrix multiplications. To get a binary instrumented with profiling code, execute the following commands:

gcc -pg -O2 -o matmul matmul.c
./matmul
gprof ./matmul
To produce the following output:

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls   s/call   s/call  name
100.12    443.81   443.81       24    18.49    18.49  matMult
  0.00    443.81     0.00        4     0.00     0.00  timeconversion
  0.00    443.81     0.00        1     0.00     0.00  RunStats

[ ... Detailed explanation of each column ... ]

                     Call graph (explanation follows)


granularity: each sample hit covers 2 byte(s) for 0.00% of 443.81 seconds

index % time    self  children    called     name
              443.81    0.00      24/24          cpuHog [2]
[1]    100.0  443.81    0.00      24         matMult [1]
-----------------------------------------------
[2]    100.0    0.00  443.81                 cpuHog [2]
              443.81    0.00      24/24          matMult [1]
-----------------------------------------------

[  ... Detailed explanation of each column ... ]
The report is split in two sections. The first one shows a flat ranking of all the functions called, how much total time was spent in the function, how many calls were made to it, etc. The functions at the top of this list are the ones that you want to focus on. Improving the performance of these functions will give you the best returns. Trying to improve functions that do not show up high in this list are just not worth worrying about (of course, this assumes that you are looking at CPU usage).

The second chart, sometimes called a "butterfly" chart, is a call graph that shows functions ranked by CPU usage together with their callers and callees. So, for function matMult ranked in the first position, the names above it are the callers to matMult (in this case cpuHog). If the function makes any other calls, they are listed below it.

One of the nice things about gprof is that it is available almost everywhere. Since it modifies the source code and uses generic timer calls (roughly what you would do if you were instrumenting the code yourself), it does not need special hardware support. This also works against it, though. Since it does require recompiling your code and works at a fairly coarse granularity, it is not usable in every situation. In those cases, Valgrind or OProfile may be better suited.

Valgrind
Valgrind is a program that emulates the x86 instruction set and runs the application under its control. The system is split into a core module that does all the emulation and a set of add-on modules that provide various profiling services: checking for memory references, a cache profiler, a heap profiler, and a data race detector for multi-threaded applications.

While Valgrind will not provide direct timing information about your application, it may give you hints on what could be going on. For instance, when using the cache profiler, you may find that your program is causing a lot of cache misses. Rearranging your data to improve cache locality would probably boost the performance of your application.

For instance, going back to the matrix multiplication program, we can ask valgrind to show cache utilization statistics after compiling with gcc:

gcc -O2 matmul.c -o matmul
valgrind --tool=cachegrind ./hog -cpu 1
The output is as follows:

[ ... program output ... ]
==9811==
==9811== I   refs:      10,449,449,620
==9811== I1  misses:             1,715
==9811== L2i misses:               998
==9811== I1  miss rate:            0.0%
==9811== L2i miss rate:            0.0%
==9811==
==9811== D   refs:       7,987,098,008  (7,606,832,264 rd + 380,265,744 wr)
==9811== D1  misses:       366,400,427  (  364,930,098 rd +   1,470,329 wr)
==9811== L2d misses:        22,052,577  (   21,958,898 rd +      93,679 wr)
==9811== D1  miss rate:            4.5% (          4.7%   +         0.3%  )
==9811== L2d miss rate:            0.2% (          0.2%   +         0.0%  )
==9811==
==9811== L2 refs:          366,402,142  (  364,931,813 rd +   1,470,329 wr)
==9811== L2 misses:         22,053,575  (   21,959,896 rd +      93,679 wr)
==9811== L2 miss rate:             0.1% (          0.1%   +         0.0%  )
Valgrind shows information about the instruction and data cache references for both instruction (I, I1) and data caches (D1, L2d). This information is highly specific to the architecture, of course.

While Valgrind can provide fairly detailed information about the program, it can be extremely slow. Since it emulates and instruments every instruction executed by the program, it may take 20x longer or more to execute. If your application is already slow, the added overhead may be prohibitive.

Perhaps one of the more useful features of Valgrind are its memory checking tools. When you invoke it with --tool=memcheck, it will report any out-of-bounds memory references and memory leaks. Valgrind is also flexible enough that you can write your own analysis modules. However, it is highly architecture specific. Currently it has been ported to x86, ppc, and x86_64 architectures.

Valgrind comes standard with recent Fedora™ Core distributions and it can also be downloaded from http://valgrind.org/.

OProfile
OProfile is different from the other profiling tools. Instead of working on a single application, OProfile collects system-wide timing information. It does not require modifications to the source code nor does it emulate the instruction set. It uses hardware counters to collect profiling information. Basically, modern CPUs have a set of registers that just count events like instructions executed or cache misses. Whenever these counters overflow, an interrupt is triggered which is caught by OProfile, which records it together with information about the current state of the CPU registers.

OProfile outputs data about samples because that's what it does. It samples the specified hardware counters, and that's the information it gives you. You have to specify which particular counter you are interested in when you start OProfile.

All this collected information can then be retrieved. In particular, one of the saved registers is the program counter. In its most basic usage, when you ask OProfile to display profiling information, it will show a list of all the applications that were running in the system since it started collecting data. Going back to our matrix multiplication application:

$ sudo opcontrol --no-vmlinux
$ sudo opcontrol --start
Using 2.6+ OProfile kernel interface.
Using log file /var/lib/oprofile/oprofiled.log
Daemon started.
Profiler running.

$ ./matmult -cpu 45
[ ... ]

$ sudo opcontrol --stop
Stopping profiling.

$ opreport -l ./matmult
CPU: P4 / Xeon with 2 hyper-threads, speed 2993.46 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during which processor is not stopped) with a unit mask of 0x01 (mandatory) count 100000
samples  %        symbol name
1981120  99.9890  matMult
215       0.0109  .plt
2        1.0e-04  cpuHog
You may have noticed that OProfile needs a bit more preparation than the other profilers we've seen. The reason for this is that OProfile is a system-wide daemon, so you will need root access to use it. However, the reporting tool, opreport, can be used by any user.

Also notice that we had to specify the name of the binary that we wanted to see. Otherwise, OProfile will display information about all the applications running at the time:

CPU: P4 / Xeon with 2 hyper-threads, speed 2993.46 MHz (estimated)
Counted GLOBAL_POWER_EVENTS events (time during which processor is not stopped)
with a unit mask of 0x01 (mandatory) count 100000
GLOBAL_POWER_E...|
  samples|      %|
------------------
  2145332 38.3077 no-vmlinux
  1981337 35.3793 hog
   427801  7.6389 libperl.so
   244002  4.3570 libc-2.3.5.so
   172337  3.0773 vmware-vmx
   126713  2.2626 libqt-mt.so.3.3.4
    74947  1.3383 Xorg
    55229  0.9862 oprofiled
    49886  0.8908 libgklayout.so
    35876  0.6406 libpthread-2.3.5.so
OProfile is a fairly powerful tool that can help you analyze performance problems that go beyond a single application. For instance, if your application is causing significant kernel activity inside a specific driver, the profile listing will include those modules in the kernel that are being used by your code. Moreover, since it is based on hardware performance counters, it incurs in very little overhead, so it is quite possible to have it running constantly without any noticeable slowdowns.

You will find more detailed information about OProfile in this month's article Using OProfile to analyze an RPM package build. It also comes standard in Fedora™ Core and Red Hat® Enterprise Linux® distributions. For additional information, visit the OProfile project home page.

Conclusions
Tuning your application to perform better is rarely a matter of adding a few obscure set of compiler flags to your Makefiles. Compiler transformations are limited to mechanical changes that are not only limited by strict semantic preservation guidelines, they are also not particularly smart. If your program requires an algorithmic change, no compiler in the world will be able to rewrite that for you.

Most of the time you will be examining your program for hot spots, and it is important to know what tools can help you. The tools we discussed in this article will help you isolate problems in CPU-bound applications. If your application is I/O bound or makes lots of system calls, then OProfile will probably do a good job at telling you which OS module is being hit the most. Other tools like strace (system call tracer) and ltrace (library call tracer) are also worth exploring.
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Profiling Programs With prof, gprof, and tcov
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
The tools discussed in this appendix are standard utilities for timing programs and obtaining performance data to analyze, and are called traditional profiling tools. The profiling tools prof and gprof are provided with the Solaris OS. tcov is a code coverage tool provided with the Sun Studio software.


Note - If you want to track how many times a function is called or how often a line of source code is executed, use the traditional profiling tools. If you want a detailed analysis of where your program is spending time, you can get more accurate information using the Collector and Performance Analyzer. See Chapter 3 and the online help for information on using these tools.


TABLE A-1 describes the information that is generated by these standard performance profiling tools.


   TABLE A-1 	   Performance Profiling Tools  
Command

Output

prof

Generates a statistical profile of the CPU time used by a program and an exact count of the number of times each function is entered.

gprof

Generates a statistical profile of the CPU time used by a program, along with an exact count of the number of times each function is entered and the number of times each arc (caller-callee pair) in the program's call graph is traversed.

tcov

Generates exact counts of the number of times each statement in a program is executed.


Not all the traditional profiling tools work on modules written in programming languages other than C. See the sections on each tool for more information about languages.

This appendix covers the following topics:

Using prof to Generate a Program Profile
Using gprof to Generate a Call Graph Profile
Using tcov for Statement-Level Analysis
Using tcov Enhanced for Statement-Level Analysis
Using prof to Generate a Program Profile
prof generates a statistical profile of the CPU time used by a program and counts the number of times each function in a program is entered. Different or more detailed data is provided by the gprof call-graph profile and the tcov code coverage tools.

To generate a profile report using prof:

1. Compile your program with the -p compiler option.

2. Run your program.

Profiling data is sent to a profile file called mon.out. This file is overwritten each time you run the program.

3. Run prof to generate a profile report.

The syntax of the prof command is as follows.


% prof program-name

Here, program-name is the name of the executable. The profile report is written to stdout. It is presented as a series of rows for each function under these column headings:

%Time--The percentage of the total CPU time consumed by this function.
Seconds--The total CPU time accounted for by this function.
Cumsecs--A running sum of the number of seconds accounted for by this function and those listed before it.
#Calls--The number of times this function is called.
msecs/call--The average number of milliseconds this function consumes each time it is called.
Name--The name of the function.
The use of prof is illustrated in the following example.


% cc -p -o index.assist index.assist.c 
% index.assist 
% prof index.assist

The prof profile report shows that most of the program execution time is spent in the compare_strings() function; after that, most of the CPU time is spent in the _strlen() library function. To make this program more efficient, the user would concentrate on the compare_strings() function, which consumes nearly 20% of the total CPU time, and improve the algorithm or reduce the number of calls.

It is not obvious from the prof profile report that compare_strings() is heavily recursive, but you can deduce this by using the call graph profile described in Using gprof to Generate a Call Graph Profile. In this particular case, improving the algorithm also reduces the number of calls.


Note - For the Solaris 7 OS and the Solaris 8 OS, the profile of CPU time is accurate for programs that use multiple CPUs, but the fact that the counts are not locked may affect the accuracy of the counts for functions.


Using gprof to Generate a Call Graph Profile
While the flat profile from prof can provide valuable data for performance improvements, a more detailed analysis can be obtained by using a call graph profile to display a list identifying which modules are called by other modules, and which modules call other modules. Sometimes removing calls altogether can result in performance improvements.


Note - gprof attributes the time spent within a function to the callers in proportion to the number of times that each arc is traversed. Because all calls are not equivalent in performance, this behavior might lead to incorrect assumptions. See the performance analyzer tutorial on the developers.sun.com web site for an example.


Like prof, gprof generates a statistical profile of the CPU time that is used by a program and it counts the number of times that each function is entered. gprof also counts the number of times that each arc in the program's call graph is traversed. An arc is a caller-callee pair.


Note - The profile of CPU time is accurate for programs that use multiple CPUs for the Solaris 7 OS and the Solaris 8 OS, but the fact that the counts are not locked may affect the accuracy of the counts for functions.

To generate a profile report using gprof:

1. Compile your program with the appropriate compiler option.

For C programs, use the -xpg option.
For Fortran programs, use the -pg option.
2. Run your program.

Profiling data is sent to a profile file called gmon.out. This file is overwritten each time you run the program.

3. Run gprof to generate a profile report.

The syntax of the prof command is as follows.


% gprof program-name

Here, program-name is the name of the executable. The profile report is written to stdout, and can be large. The report consists of two major items:

The full call graph profile, which shows information about the callers and callees of each function in the program. The format is illustrated in the example given below.
The flat profile, which is similar to the summary the prof command supplies.
The profile report from gprof contains an explanation of what the various parts of the summary mean and identifies the granularity of the sampling, as shown in the following example.


granularity: each sample hit covers 4 byte(s) for 0.07% of 14.74 seconds

The 4 bytes means resolution to a single instruction. The 0.07% of 14.74 seconds means that each sample, representing ten milliseconds of CPU time, accounts for 0.07% of the run.

The use of gprof is illustrated in the following example.


% cc -xpg -o index.assist index.assist.c 
% index.assist 
% gprof index.assist > g.output

The call graph profile show there are 761 lines of data in the input file to the index.assist program. The following conclusions can be made:

fgets() is called 762 times. The last call to fgets() returns an end-of-file.
The insert_index_entry() function is called 760 times from main().
In addition to the 760 times that insert_index_entry() is called from main(), insert_index_entry() also calls itself 10,392 times. insert_index_entry() is heavily recursive.
compare_entry(), which is called from insert_index_entry(), is called 11,152 times, which is equal to 760+10,392 times. There is one call to compare_entry() for every time that insert_index_entry() is called. This is correct. If there were a discrepancy in the number of calls, you would suspect some problem in the program logic.
insert_page_entry() is called 820 times in total: 761 times from main() while the program is building index nodes, and 59 times from insert_index_entry(). This frequency indicates that there are 59 duplicated index entries, so their page number entries are linked into a chain with the index nodes. The duplicate index entries are then freed; hence the 59 calls to free().

-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Using tcov for Statement-Level Analysis
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
The tcov utility gives information on how often a program executes segments of code. It produces a copy of the source file, annotated with execution frequencies. The code can be annotated at the basic block level or the source line level. A basic block is a linear segment of source code with no branches. The statements in a basic block are executed the same number of times, so a count of basic block executions also tells you how many times each statement in the block was executed. The tcov utility does not produce any time-based data.


Note - Although tcov works with both C and C++ programs, it does not support files that contain #line or #file directives. tcov does not enable test coverage analysis of the code in the #include header files.


To generate annotated source code using tcov:

1. Compile your program with the appropriate compiler option.

For C programs, use the -xa option.
For Fortran and C++ programs, use the -a option.
If you compile with the -a or -xa option you must also link with it. The compiler creates a coverage data file with the suffix .d for each object file. The coverage data file is created in the directory specified by the environment variable TCOVDIR. If TCOVDIR is not set, the coverage data file is created in the current directory.


Note - Programs compiled with -xa (C) or -a (other compilers) run more slowly than they normally would, because updating the .d file for each execution takes considerable time.


2. Run your program.

When your program completes, the coverage data files are updated.

3. Run tcov to generate annotated source code.

The syntax of the tcov command is as follows.


% tcov options source-file-list

Here, source-file-list is a list of the source code filenames. For a list of options, see the tcov(1) man page. The default output of tcov is a set of files, each with the suffix .tcov, which can be changed with the -o filename option.

A program compiled for code coverage analysis can be run multiple times (with potentially varying input); tcov can be used on the program after each run to compare behavior.

The following example illustrates the use of tcov.


% cc -xa -o index.assist index.assist.c
% index.assist 
% tcov index.assist.c 

This small fragment of the C code from one of the modules of index.assist shows the insert_index_entry() function, which is called recursively. The numbers to the left of the C code show how many times each basic block was executed. The insert_index_entry() function is called 11,152 times.


			struct index_entry * 
11152		->	insert_index_entry(node, entry) 
			struct index_entry *node; 
			struct index_entry *entry; 
			{ 
				int result; 
				int level; 
 
				result = compare_entry(node, entry); 
				if (result == 0) {						/* exact match */ 
										/* Place the page entry for the duplicate */ 
										/* into the list of pages for this node */ 
59		->				insert_page_entry(node, entry->page_entry); 
						free(entry); 
						return(node); 
				} 
 
11093		->		if (result > 0)						/* node greater than new entry -- */ 
											/* move to lesser nodes */ 
3956		->				if (node->lesser != NULL) 
3626		->						insert_index_entry(node->lesser, entry); 
						else { 
330		->						node->lesser = entry; 
								return (node->lesser); 
						}
					else					/* node less than new entry -- */ 
										/* move to greater nodes */ 
7137		->				if (node->greater != NULL) 
6766		->						insert_index_entry(node->greater, entry); 
						else { 
371		->						node->greater = entry; 
								return (node->greater); 
						} 
			} 

The tcov utility places a summary like the following at the end of the annotated program listing. The statistics for the most frequently executed basic blocks are listed in order of execution frequency. The line number is the number of the first line in the block.

The following is the summary for the index.assist program:



  Top 10 Blocks 





Line

 Count 


240

 21563 


241

 21563 


245

 21563 


251

 21563 


250

 21400 


244

 21299 


255

 20612 


257

 16805 


123

 12021 


124

 11962 




77

Basic blocks in this file 

55

Basic blocks executed

71.43

Percent of the file executed





439144

Total basic block executions


5703.17

Average executions per basic block


Creating tcov Profiled Shared Libraries
It is possible to create a tcov profiled shareable library and use it in place of the corresponding library in binaries which have already been linked. Include the -xa (C) or -a (other compilers) option when creating the shareable libraries, as shown in this example.


% cc -G -xa -o foo.so.1 foo.o 

This command includes a copy of the tcov profiling functions in the shareable libraries, so that clients of the library do not need to relink. If a client of the library is already linked for profiling, then the version of the tcov functions used by the client is used to profile the shareable library.

Locking Files
tcov uses a simple file-locking mechanism for updating the block coverage database in the .d files. It employs a single file, tcov.lock, for this purpose. Consequently, only one executable compiled with -xa (C) or -a (other compilers) should be running on the system at a time. If the execution of the program compiled with the -xa (or -a) option is manually terminated, then the tcov.lock file must be deleted manually.

Files compiled with the -xa or -a option call the profiling tool functions automatically when a program is linked for tcov profiling. At program exit, these functions combine the information collected at runtime for file xyz.f (for example) with the existing profiling information stored in file xyz.d. To ensure this information is not corrupted by several people simultaneously running a profiled binary, a xyz.d.lock lock file is created for xyz.d for the duration of the update. If there are any errors in opening or reading xyz.d or its lock file, or if there are inconsistencies between the runtime information and the stored information, the information stored in xyz.d is not changed.

If you edit and recompile xyz.f the number of counters in xyz.d can change. This is detected if an old profiled binary is run.

If too many people are running a profiled binary, some of them cannot obtain a lock. An error message is displayed after a delay of several seconds. The stored information is not updated. This locking is safe across a network. Since locking is performed on a file-by-file basis, other files may be correctly updated.

The profiling functions attempt to deal with automounted file systems that have become inaccessible. They still fail if the file system containing a coverage data file is mounted with different names on different machines, or if the user running the profiled binary does not have permission to write to either the coverage data file or the directory containing it. Be sure all the directories are uniformly named and writable by anyone expected to run the binary.

Errors Reported by tcov Runtime Functions
The following error messages may be reported by the tcov runtime functions:

The user running the binary lacks permission to read or write to the coverage data file. The problem also occurs if the coverage data file has been deleted.

tcov_exit: Could not open coverage data file 'coverage-data-file-name' because 'system-error-message-string'.

The user running the binary lacks permission to write to the directory containing the coverage data file. The problem also occurs if the directory containing the coverage data file is not mounted on the machine where the binary is being run.

tcov_exit: Could not write coverage data file 'coverage-data-file-name' because 'system-error-message-string'.

Too many users are trying to update a coverage data file at the same time. The problem also occurs if a machine has crashed while a coverage data file is being updated, leaving behind a lock file. In the event of a crash, the longer of the two files should be used as the post-crash coverage data file. Manually remove the lock file.

tcov_exit: Failed to create lock file 'lock-file-name' for coverage data file 'coverage-data-file-name' after 5 tries. Is someone else running this executable?

No memory is available, and the standard I/O package will not work. You cannot update the coverage data file at this point.

tcov_exit: Stdio failure, probably no memory left.

The lock file name is longer by six characters than the coverage data file name. Therefore, the derived lock file name may not be legal.

tcov_exit: Coverage data file path name too long (length characters) 'coverage-data-file-name'.

A library or binary that has tcov profiling enabled is simultaneously being run, edited, and recompiled. The old binary expects a coverage data file of a certain size, but the editing often changes that size. If the compiler creates a new coverage data file at the same time that the old binary is trying to update the old coverage data file, the binary may see an apparently empty or corrupt coverage file.

tcov_exit: Coverage data file 'coverage-data-file-name' is too short. Is it out of date?

Using tcov Enhanced for Statement-Level Analysis
Like the original tcov, tcov Enhanced gives line-by-line information on how a program executes. It produces a copy of the source file, annotated to show which lines are used and how often. It also gives a summary of information about basic blocks. tcov Enhanced works with both C and C++ source files.

tcov Enhanced overcomes some of the shortcomings of the original tcov. The improved features of tcov Enhanced are:

It provides more complete support for C++.
It supports code found in #include header files and corrects a flaw that obscured coverage numbers for template classes and functions.
Its runtime is more efficient than the original tcov runtime.
It is supported for all the platforms that the compilers support.
To generate annotated source code using tcov Enhanced:

1. Compile your program with the -xprofile=tcov compiler option.

Unlike tcov, tcov Enhanced does not generate any files at compile time.

2. Run your program.

A directory is created to store the profile data, and a single coverage data file called tcovd is created in that directory. By default, the directory is created in the location where you run the program program-name, and it is called program-name.profile. The directory is also known as the profile bucket. The defaults can be changed using environment variables (see tcov Directories and Environment Variables).

3. Run tcov to generate annotated source code.

The syntax of the tcov command is as follows.


% tcov option-list source-file-list

Here, source-file-list is a list of the source code filenames, and option-list is a list of options, which can be obtained from the tcov(1) man page. You must include the -x option to enable tcov Enhanced processing.

The default output of tcov Enhanced is a set of annotated source files whose names are derived by appending .tcov to the corresponding source file name.

The following example illustrates the syntax of tcov Enhanced.


% cc -xprofile=tcov -o index.assist index.assist.c 
% index.assist 
% tcov -x index.assist.profile index.assist.c

The output of tcov Enhanced is identical to the output from the original tcov.

Creating Profiled Shared Libraries for tcov Enhanced
You can create profiled shared libraries for use with tcov Enhanced by including the -xprofile=tcov compiler option, as shown in the following example.


% cc -G -xprofile=tcov -o foo.so.1 foo.o 

Locking Files
tcov Enhanced uses a simple file-locking mechanism for updating the block coverage data file. It employs a single file created in the same directory as the tcovd file. The file name is tcovd.temp.lock. If execution of the program compiled for coverage analysis is manually terminated, then the lock file must be deleted manually.

The locking scheme does an exponential back-off if there is a contention for the lock. If, after five tries, the tcov runtime cannot acquire the lock, it exits, and the data is lost for that run. In this case, the following message is displayed.


tcov_exit: temp file exists, is someone else running this executable?

tcov Directories and Environment Variables
When you compile a program for tcov and run the program, the running program generates a profile bucket. If a previous profile bucket exists, the program uses that profile bucket. If a profile bucket does not exist, it creates the profile bucket.

The profile bucket specifies the directory where the profile output is generated. The name and location of the profile output are controlled by defaults that you can modify with environment variables.


Note - tcov uses the same defaults and environment variables that are used by the compiler options that you use to gather profile feedback: -xprofile=collect and -xprofile=use. For more information about these compiler options, see the documentation for the relevant compiler.


The default profile bucket is named after the executable with a .profile extension and is created in the directory where the executable is run. Therefore, if you run a program called /usr/bin/xyz from /home/userdir, the default behavior is to create a profile bucket called xyz.profile in /home/userdir.

A UNIX process can change its current working directory during the execution of a program. The current working directory used to generate the profile bucket is the current working directory of the program at exit. In the rare case where a program actually does change its current working directory during execution, you can use the environment variables to control where the profile bucket is generated.

You can set the following environment variables to modify the defaults:

SUN_PROFDATA
Can be used to specify the name of the profile bucket at runtime. The value of this variable is always appended to the value of SUN_PROFDATA_DIR if both variables are set. Doing this may be useful if the name of the executable is not the same as the value in argv[0] (for example, the invocation of the executable was through a symbolic link with a different name).

SUN_PROFDATA_DIR
Can be used to specify the name of the directory that contains the profile bucket. It is used at runtime and by the tcov command.

TCOVDIR
TCOVDIR is supported as a synonym for SUN_PROFDATA_DIR to maintain backward compatibility. Any setting of SUN_PROFDATA_DIR causes TCOVDIR to be ignored. If both SUN_PROFDATA_DIR and TCOVDIR are set, a warning is displayed when the profile bucket is generated.

TCOVDIR is used at runtime and by the tcov command.
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
