5. Cachegrind: a cache and branch-prediction profiler

To run Cachegrind on a program prog, run:

valgrind --tool=cachegrind prog

The program will execute (slowly). Upon completion, summary statistics that look like this will be printed:

==31751== I   refs:      27,742,716
==31751== I1  misses:           276
==31751== LLi misses:           275
==31751== I1  miss rate:        0.0%
==31751== LLi miss rate:        0.0%
==31751== 
==31751== D   refs:      15,430,290  (10,955,517 rd + 4,474,773 wr)
==31751== D1  misses:        41,185  (    21,905 rd +    19,280 wr)
==31751== LLd misses:        23,085  (     3,987 rd +    19,098 wr)
==31751== D1  miss rate:        0.2% (       0.1%   +       0.4%)
==31751== LLd miss rate:        0.1% (       0.0%   +       0.4%)
==31751== 
==31751== LL misses:         23,360  (     4,262 rd +    19,098 wr)
==31751== LL miss rate:         0.0% (       0.0%   +       0.4%)

Cache accesses for instruction fetches are summarised first, giving the number of fetches made (this is the number of instructions executed, which can be useful to know in its own right), the number of I1 misses, and the number of LL instruction (LLi) misses.

Cache accesses for data follow. The information is similar to that of the instruction fetches, except that the values are also shown split between reads and writes (note each row's rd and wr values add up to the row's total).

Combined instruction and data figures for the LL cache follow that. Note that the LL miss rate is computed relative to the total number of memory accesses, not the number of L1 misses. I.e. it is (ILmr + DLmr + DLmw) / (Ir + Dr + Dw) not (ILmr + DLmr + DLmw) / (I1mr + D1mr + D1mw)

Branch prediction statistics are not collected by default. To do so, add the option --branch-sim=yes.

As well as printing summary information, Cachegrind also writes more detailed profiling information to a file. By default this file is named cachegrind.out.<pid> (where <pid> is the program's process ID), but its name can be changed with the --cachegrind-out-file option. This file is human-readable, but is intended to be interpreted by the accompanying program cg_annotate, described in the next section.

The default .<pid> suffix on the output file name serves two purposes. Firstly, it means you don't have to rename old log files that you don't want to overwrite. Secondly, and more importantly, it allows correct profiling with the --trace-children=yes option of programs that spawn child processes.

The output file can be big, many megabytes for large applications built with full debugging information.

Before using cg_annotate, it is worth widening your window to be at least 120-characters wide if possible, as the output lines can be quite long.

To get a function-by-function summary, run:

cg_annotate <filename>

on a Cachegrind output file.

The first part of the output looks like this:

--------------------------------------------------------------------------------
I1 cache:              65536 B, 64 B, 2-way associative
D1 cache:              65536 B, 64 B, 2-way associative
LL cache:              262144 B, 64 B, 8-way associative
Command:               concord vg_to_ucode.c
Events recorded:       Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw
Events shown:          Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw
Event sort order:      Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw
Threshold:             99%
Chosen for annotation:
Auto-annotation:       off

This is a summary of the annotation options:

Then follows summary statistics for the whole program:

--------------------------------------------------------------------------------
Ir         I1mr ILmr Dr         D1mr   DLmr  Dw        D1mw   DLmw
--------------------------------------------------------------------------------
27,742,716  276  275 10,955,517 21,905 3,987 4,474,773 19,280 19,098  PROGRAM TOTALS

These are similar to the summary provided when Cachegrind finishes running.

Then comes function-by-function statistics:

--------------------------------------------------------------------------------
Ir        I1mr ILmr Dr        D1mr  DLmr  Dw        D1mw   DLmw    file:function
--------------------------------------------------------------------------------
8,821,482    5    5 2,242,702 1,621    73 1,794,230      0      0  getc.c:_IO_getc
5,222,023    4    4 2,276,334    16    12   875,959      1      1  concord.c:get_word
2,649,248    2    2 1,344,810 7,326 1,385         .      .      .  vg_main.c:strcmp
2,521,927    2    2   591,215     0     0   179,398      0      0  concord.c:hash
2,242,740    2    2 1,046,612   568    22   448,548      0      0  ctype.c:tolower
1,496,937    4    4   630,874 9,000 1,400   279,388      0      0  concord.c:insert
  897,991   51   51   897,831    95    30        62      1      1  ???:???
  598,068    1    1   299,034     0     0   149,517      0      0  ../sysdeps/generic/lockfile.c:__flockfile
  598,068    0    0   299,034     0     0   149,517      0      0  ../sysdeps/generic/lockfile.c:__funlockfile
  598,024    4    4   213,580    35    16   149,506      0      0  vg_clientmalloc.c:malloc
  446,587    1    1   215,973 2,167   430   129,948 14,057 13,957  concord.c:add_existing
  341,760    2    2   128,160     0     0   128,160      0      0  vg_clientmalloc.c:vg_trap_here_WRAPPER
  320,782    4    4   150,711   276     0    56,027     53     53  concord.c:init_hash_table
  298,998    1    1   106,785     0     0    64,071      1      1  concord.c:create
  149,518    0    0   149,516     0     0         1      0      0  ???:tolower@@GLIBC_2.0
  149,518    0    0   149,516     0     0         1      0      0  ???:fgetc@@GLIBC_2.0
   95,983    4    4    38,031     0     0    34,409  3,152  3,150  concord.c:new_word_node
   85,440    0    0    42,720     0     0    21,360      0      0  vg_clientmalloc.c:vg_bogus_epilogue

Each function is identified by a file_name:function_name pair. If a column contains only a dot it means the function never performs that event (e.g. the third row shows that strcmp() contains no instructions that write to memory). The name ??? is used if the file name and/or function name could not be determined from debugging information. If most of the entries have the form ???:??? the program probably wasn't compiled with -g.

It is worth noting that functions will come both from the profiled program (e.g. concord.c) and from libraries (e.g. getc.c)

There are two ways to annotate source files -- by specifying them manually as arguments to cg_annotate, or with the --auto=yes option. For example, the output from running cg_annotate <filename> concord.c for our example produces the same output as above followed by an annotated version of concord.c, a section of which looks like:

--------------------------------------------------------------------------------
-- User-annotated source: concord.c
--------------------------------------------------------------------------------
Ir        I1mr ILmr Dr      D1mr  DLmr  Dw      D1mw   DLmw

        .    .    .       .     .     .       .      .      .  void init_hash_table(char *file_name, Word_Node *table[])
        3    1    1       .     .     .       1      0      0  {
        .    .    .       .     .     .       .      .      .      FILE *file_ptr;
        .    .    .       .     .     .       .      .      .      Word_Info *data;
        1    0    0       .     .     .       1      1      1      int line = 1, i;
        .    .    .       .     .     .       .      .      .
        5    0    0       .     .     .       3      0      0      data = (Word_Info *) create(sizeof(Word_Info));
        .    .    .       .     .     .       .      .      .
    4,991    0    0   1,995     0     0     998      0      0      for (i = 0; i < TABLE_SIZE; i++)
    3,988    1    1   1,994     0     0     997     53     52          table[i] = NULL;
        .    .    .       .     .     .       .      .      .
        .    .    .       .     .     .       .      .      .      /* Open file, check it. */
        6    0    0       1     0     0       4      0      0      file_ptr = fopen(file_name, "r");
        2    0    0       1     0     0       .      .      .      if (!(file_ptr)) {
        .    .    .       .     .     .       .      .      .          fprintf(stderr, "Couldn't open '%s'.\n", file_name);
        1    1    1       .     .     .       .      .      .          exit(EXIT_FAILURE);
        .    .    .       .     .     .       .      .      .      }
        .    .    .       .     .     .       .      .      .
  165,062    1    1  73,360     0     0  91,700      0      0      while ((line = get_word(data, line, file_ptr)) != EOF)
  146,712    0    0  73,356     0     0  73,356      0      0          insert(data->;word, data->line, table);
        .    .    .       .     .     .       .      .      .
        4    0    0       1     0     0       2      0      0      free(data);
        4    0    0       1     0     0       2      0      0      fclose(file_ptr);
        3    0    0       2     0     0       .      .      .  }

(Although column widths are automatically minimised, a wide terminal is clearly useful.)

Each source file is clearly marked (User-annotated source) as having been chosen manually for annotation. If the file was found in one of the directories specified with the -I/--include option, the directory and file are both given.

Each line is annotated with its event counts. Events not applicable for a line are represented by a dot. This is useful for distinguishing between an event which cannot happen, and one which can but did not.

Sometimes only a small section of a source file is executed. To minimise uninteresting output, Cachegrind only shows annotated lines and lines within a small distance of annotated lines. Gaps are marked with the line numbers so you know which part of a file the shown code comes from, eg:

(figures and code for line 704)
-- line 704 ----------------------------------------
-- line 878 ----------------------------------------
(figures and code for line 878)

The amount of context to show around annotated lines is controlled by the --context option.

To get automatic annotation, use the --auto=yes option. cg_annotate will automatically annotate every source file it can find that is mentioned in the function-by-function summary. Therefore, the files chosen for auto-annotation are affected by the --sort and --threshold options. Each source file is clearly marked (Auto-annotated source) as being chosen automatically. Any files that could not be found are mentioned at the end of the output, eg:

------------------------------------------------------------------
The following files chosen for auto-annotation could not be found:
------------------------------------------------------------------
  getc.c
  ctype.c
  ../sysdeps/generic/lockfile.c

This is quite common for library files, since libraries are usually compiled with debugging information, but the source files are often not present on a system. If a file is chosen for annotation both manually and automatically, it is marked as User-annotated source. Use the -I/--include option to tell Valgrind where to look for source files if the filenames found from the debugging information aren't specific enough.

Beware that cg_annotate can take some time to digest large cachegrind.out.<pid> files, e.g. 30 seconds or more. Also beware that auto-annotation can produce a lot of output if your program is large!

Valgrind can annotate assembly code programs too, or annotate the assembly code generated for your C program. Sometimes this is useful for understanding what is really happening when an interesting line of C code is translated into multiple instructions.

To do this, you just need to assemble your .s files with assembly-level debug information. You can use compile with the -S to compile C/C++ programs to assembly code, and then assemble the assembly code files with -g to achieve this. You can then profile and annotate the assembly code source files in the same way as C/C++ source files.

If your program forks, the child will inherit all the profiling data that has been gathered for the parent.

If the output file format string (controlled by --cachegrind-out-file) does not contain %p, then the outputs from the parent and child will be intermingled in a single output file, which will almost certainly make it unreadable by cg_annotate.

There are a couple of situations in which cg_annotate issues warnings.

Some odd things that can occur during annotation:

This list looks long, but these cases should be fairly rare.

cg_merge is a simple program which reads multiple profile files, as created by Cachegrind, merges them together, and writes the results into another file in the same format. You can then examine the merged results using cg_annotate <filename>, as described above. The merging functionality might be useful if you want to aggregate costs over multiple runs of the same program, or from a single parallel run with multiple instances of the same program.

cg_merge is invoked as follows:

cg_merge -o outputfile file1 file2 file3 ...

It reads and checks file1, then read and checks file2 and merges it into the running totals, then the same with file3, etc. The final results are written to outputfile, or to standard out if no output file is specified.

Costs are summed on a per-function, per-line and per-instruction basis. Because of this, the order in which the input files does not matter, although you should take care to only mention each file once, since any file mentioned twice will be added in twice.

cg_merge does not attempt to check that the input files come from runs of the same executable. It will happily merge together profile files from completely unrelated programs. It does however check that the Events: lines of all the inputs are identical, so as to ensure that the addition of costs makes sense. For example, it would be nonsensical for it to add a number indicating D1 read references to a number from a different file indicating LL write misses.

A number of other syntax and sanity checks are done whilst reading the inputs. cg_merge will stop and attempt to print a helpful error message if any of the input files fail these checks.

cg_diff is a simple program which reads two profile files, as created by Cachegrind, finds the difference between them, and writes the results into another file in the same format. You can then examine the merged results using cg_annotate <filename>, as described above. This is very useful if you want to measure how a change to a program affected its performance.

cg_diff is invoked as follows:

cg_diff file1 file2

It reads and checks file1, then read and checks file2, then computes the difference (effectively file1 - file2). The final results are written to standard output.

Costs are summed on a per-function basis. Per-line costs are not summed, because doing so is too difficult. For example, consider differencing two profiles, one from a single-file program A, and one from the same program A where a single blank line was inserted at the top of the file. Every single per-line count has changed. In comparison, the per-function counts have not changed. The per-function count differences are still very useful for determining differences between programs. Note that because the result is the difference of two profiles, many of the counts will be negative; this indicates that the counts for the relevant function are fewer in the second version than those in the first version.

cg_diff does not attempt to check that the input files come from runs of the same executable. It will happily merge together profile files from completely unrelated programs. It does however check that the Events: lines of all the inputs are identical, so as to ensure that the addition of costs makes sense. For example, it would be nonsensical for it to add a number indicating D1 read references to a number from a different file indicating LL write misses.

A number of other syntax and sanity checks are done whilst reading the inputs. cg_diff will stop and attempt to print a helpful error message if any of the input files fail these checks.

Sometimes you will want to compare Cachegrind profiles of two versions of a program that you have sitting side-by-side. For example, you might have version1/prog.c and version2/prog.c, where the second is slightly different to the first. A straight comparison of the two will not be useful -- because functions are qualified with filenames, a function f will be listed as version1/prog.c:f for the first version but version2/prog.c:f for the second version.

When this happens, you can use the --mod-filename option. Its argument is a Perl search-and-replace expression that will be applied to all the filenames in both Cachegrind output files. It can be used to remove minor differences in filenames. For example, the option --mod-filename='s/version[0-9]/versionN/' will suffice for this case.

Similarly, sometimes compilers auto-generate certain functions and give them randomized names. For example, GCC sometimes auto-generates functions with names like T.1234, and the suffixes vary from build to build. You can use the --mod-funcname option to remove small differences like these; it works in the same way as --mod-filename.