| Valgrind 3.3 - Advanced Debugging and Profiling for GNU/Linux applications by J. Seward, N. Nethercote, J. Weidendorfer and the Valgrind Development Team Paperback (6"x9"), 164 pages ISBN 0954612051 RRP £12.95 ($19.95) |
6.2.3 Annotating C/C++ programs
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 output looks like this:
-------------------------------------------------------
I1 cache: 65536 B, 64 B, 2-way associative
D1 cache: 65536 B, 64 B, 2-way associative
L2 cache: 262144 B, 64 B, 8-way associative
Command: concord vg_to_ucode.c
Events recorded: Ir I1mr I2mr Dr D1mr D2mr Dw D1mw D2mw
Events shown: Ir I1mr I2mr Dr D1mr D2mr Dw D1mw D2mw
Event sort order: Ir I1mr I2mr Dr D1mr D2mr Dw D1mw D2mw
Threshold: 99%
Chosen for annotation:
Auto-annotation: on
-------------------------------------------------------
Ir I1mr I2mr Dr D1mr D2mr Dw
D1mw D2mw
-------------------------------------------------------
27,742,716 276 275 10,955,517 21,905 3,987 4,474,773
19,280 19,098 PROGRAM TOTALS
-------------------------------------------------------
Ir I1mr I2mr Dr D1mr D2mr Dw
D1mw D2mw 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 lockfile.c:__flockfile
598,068 0 0 299,034 0 0 149,517
0 0 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
First up is a summary of the annotation options:
- I1 cache, D1 cache, L2 cache: cache configuration. So you know the configuration with which these results were obtained.
- Command: the command line invocation of the program under examination.
-
Events recorded: event abbreviations are:
- ‘Ir’: I cache reads (i.e. instructions executed)
- ‘I1mr’: I1 cache read misses
- ‘I2mr’: L2 cache instruction read misses
- ‘Dr’: D cache reads (i.e. memory reads)
- ‘D1mr’: D1 cache read misses
- ‘D2mr’: L2 cache data read misses
- ‘Dw’: D cache writes (i.e. memory writes)
- ‘D1mw’: D1 cache write misses
- ‘D2mw’: L2 cache data write misses
- ‘Bc’: Conditional branches executed
- ‘Bcm’: Conditional branches mispredicted
- ‘Bi’: Indirect branches executed
- ‘Bim’: Conditional branches mispredicted
- Events shown: the events shown, which is a subset of the events gathered. This can be adjusted with the ‘--show’ option.
-
Event sort order: the sort order in which functions are
shown. For example, in this case the functions are sorted
from highest ‘Ir’ counts to
lowest. If two functions have identical
‘Ir’ counts, they will then be
sorted by ‘I1mr’ counts, and
so on. This order can be adjusted with the
‘--sort’ option.
Note that this dictates the order the functions appear.
It is
notthe order in which the columns appear; that is dictated by the “events shown” line (and can be changed with the ‘--show’ option). - Threshold: cg_annotate by default omits functions that cause very low counts to avoid drowning you in information. In this case, cg_annotate shows summaries the functions that account for 99% of the ‘Ir’ counts; ‘Ir’ is chosen as the threshold event since it is the primary sort event. The threshold can be adjusted with the ‘--threshold’ option.
- Chosen for annotation: names of files specified manually for annotation; in this case none.
- Auto-annotation: whether auto-annotation was requested via the ‘--auto=yes’ option. In this case no.
Then follows summary statistics for the whole program. These are similar to the summary provided when running ‘valgrind --tool=cachegrind’.
Then follows function-by-function statistics. 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 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’. If any code was invalidated (either due to self-modifying code or unloading of shared objects) its counts are aggregated into a single cost centre written as ‘(discarded):(discarded)’.
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 choosing them manually, or with the ‘--auto=yes’ option. To do it manually, just specify the filenames as additional arguments to cg_annotate. 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 I2mr Dr D1mr D2mr Dw D1mw D2mw
. . . . . . . . .
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, e.g.:
(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, run ‘cg_annotate <filename> --auto=yes’. 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, e.g.:
------------------------------------------------------- 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!
| ISBN 0954612051 | Valgrind 3.3 - Advanced Debugging and Profiling for GNU/Linux applications | See the print edition |