Linking in the Library

To install the CPU profiler into your executable, add -lprofiler to the link-time step for your executable. (It's also probably possible to add in the profiler at run-time using LD_PRELOAD, but this isn't necessarily recommended.)

This does not turn on CPU profiling; it just inserts the code. For that reason, it's practical to just always link -lprofiler into a binary while developing; that's what we do at Google. (However, since any user can turn on the profiler by setting an environment variable, it's not necessarily recommended to install profiler-linked binaries into a production, running system.)

Running the Code

There are two alternatives to actually turn on CPU profiling for a given run of an executable:

1. Define the environment variable CPUPROFILE to the filename to dump the profile to. For instance, to profile /usr/local/netscape:

         $ CPUPROFILE=/tmp/profile /usr/local/netscape           # sh
         % setenv CPUPROFILE /tmp/profile; /usr/local/netscape   # csh
        

   OR
2. In your code, bracket the code you want profiled in calls to ProfilerStart() and ProfilerStop(). ProfilerStart() will take the profile-filename as an argument.

Profiling works correctly with threads. To use, just call ProfilerRegisterThread() at the beginning of the routine the thread runs.

You can also turn profiling on and off throughout the code, and do other tweaks. This functionality will not frequently be needed. See /usr/local/include/google/profiler.h (or src/google/profiler.h in this directory) for more details.

Analyzing the Output

pprof is the script used to analyze a profile. It has many output modes, both textual and graphical. Some give just raw numbers, much like the -pg output of gcc, and others show the data in the form of a dependency graph.

pprof requires perl5 to be installed to run. It also requires dot to be installed for any of the graphical output routines, and gv to be installed for --gv mode (described below).

Here are some ways to call pprof. These are described in more detail below.

% pprof "program" "profile"
  Generates one line per procedure

% pprof --gv "program" "profile"
  Generates annotated call-graph and displays via "gv"

% pprof --gv --focus=Mutex "program" "profile"
  Restrict to code paths that involve an entry that matches "Mutex"

% pprof --gv --focus=Mutex --ignore=string "program" "profile"
  Restrict to code paths that involve an entry that matches "Mutex"
  and does not match "string"

% pprof --list=IBF_CheckDocid "program" "profile"
  Generates disassembly listing of all routines with at least one
  sample that match the --list= pattern.  The listing is
  annotated with the flat and cumulative sample counts at each line.

% pprof --disasm=IBF_CheckDocid "program" "profile"
  Generates disassembly listing of all routines with at least one
  sample that match the --disasm= pattern.  The listing is
  annotated with the flat and cumulative sample counts at each PC value.

Node Information

In the various graphical modes of pprof, the output is a call graph annotated with timing information, like so:

Each node represents a procedure. The directed edges indicate caller to callee relations. Each node is formatted as follows:

Class Name
Method Name
local (percentage)
of cumulative (percentage)

The last one or two lines contains the timing information. (The profiling is done via a sampling method, where by default we take 100 samples a second. Therefor one unit of time in the output corresponds to about 10 milliseconds of execution time.) The "local" time is the time spent executing the instructions directly contained in the procedure (and in any other procedures that were inlined into the procedure). The "cumulative" time is the sum of the "local" time and the time spent in any callees. If the cumulative time is the same as the local time, it is not printed.

For instance, the timing information for test_main_thread() indicates that 155 units (about 1.55 seconds) were spent executing the code in test_main_thread() and 200 units were spent while executing test_main_thread() and its callees such as snprintf().

The size of the node is proportional to the local count. The percentage displayed in the node corresponds to the count divided by the total run time of the program (that is, the cumulative count for main()).

Edge Information

An edge from one node to another indicates a caller to callee relationship. Each edge is labelled with the time spent by the callee on behalf of the caller. E.g, the edge from test_main_thread() to snprintf() indicates that of the 200 samples in test_main_thread(), 37 are because of calls to snprintf().

Note that test_main_thread() has an edge to vsnprintf(), even though test_main_thread() doesn't call that function directly. This is because the code was compiled with -O2; the profile reflects the optimized control flow.

Meta Information

      /tmp/profiler2_unittest
      Total samples: 202
      Focusing on: 202
      Dropped nodes with <= 1 abs(samples)
      Dropped edges with <= 0 samples

Focus and Ignore

You can ask pprof to generate a display focused on a particular piece of the program. You specify a regular expression. Any portion of the call-graph that is on a path which contains at least one node matching the regular expression is preserved. The rest of the call-graph is dropped on the floor. For example, you can focus on the vsnprintf() libc call in profiler2_unittest as follows:

% pprof --gv --focus=vsnprintf /tmp/profiler2_unittest test.prof

Similarly, you can supply the --ignore option to ignore samples that match a specified regular expression. E.g., if you are interested in everything except calls to snprintf(), you can say:

% pprof --gv --ignore=snprintf /tmp/profiler2_unittest test.prof

pprof Options

Output Type

Reporting Granularity

By default, pprof produces one entry per procedure. However you can use one of the following options to change the granularity of the output. The --files option seems to be particularly useless, and may be removed eventually.

Controlling the Call Graph Display

Some nodes and edges are dropped to reduce clutter in the output display. The following options control this effect:

The dropped edges and nodes account for some count mismatches in the display. For example, the cumulative count for snprintf() in the first diagram above was 41. However the local count (1) and the count along the outgoing edges (12+1+20+6) add up to only 40.

Caveats

• If the program exits because of a signal, the generated profile will be incomplete, and may perhaps be completely empty.
• The displayed graph may have disconnected regions because of the edge-dropping heuristics described above.
• If the program linked in a library that was not compiled with enough symbolic information, all samples associated with the library may be charged to the last symbol found in the program before the libary. This will artificially inflate the count for that symbol.
• If you run the program on one machine, and profile it on another, and the shared libraries are different on the two machines, the profiling output may be confusing: samples that fall within the shared libaries may be assigned to arbitrary procedures.