Blast from the past: gprof

I stumbled across this little tutorial I wrote back in the mists of time, probably around 1996 or 1997.  And it was based on a tutorial I wrote at Visix, probably in 1993 during one of our Optimization Parties.  It describes how to read the output of gprof, a profiling tool available on most unix systems.  It’s even still there on Mac OS X.  So you kids with your fancy Shark and Instruments, here’s what some of your elders used.

gprof is not a GNU tool, even though it has the leading “g”.  That “g” probably stands for “call Graph” profiler. You’ll need to check your system’s documentation (e.g. man gprof) for exact instructions on getting gprof to work, but usually it just involves compiling and linking with -pg, running your program, and doing gprof gmon.out > oopack.

Here’s a 300K sample of output from gprof on the Dec Alpha if you want to take a look at it. This particular report is from a run of AOLServer 2.2.1 which involved fetching index.html 53,623 times.  The links that follow go to anchors in that 300K sample.  What was I wanting to profile?  I wanted a gut check to make sure that life in the server was sane, and if there were any obvious bottlenecks that maybe I could address if I had the time.  The test was to fetch index.html over and over again. In this case, around 53,000 times

There’s 4 parts to gprof output:

• Built-in documentation: Short form of everything here, and more.
• Call-graph: Each function, who called it, whom it called, and how many times said calling happened.
• Flat profile How many times each function got called, the total times involved, sorted by time consumed.
• Index: Cross-reference of function names and gprof identification numbers numbers.

I go to the flat profile section when I first start looking at gprof output. The big time consumers are usually pretty obvious. You’ll notice that each function has a [number] after it. You can search on that number throughout the file to see who called that function and what functions that function calls. Emacs incremental search is really nice for bouncing around the file like this.

Here you can see that DString is a big time gobbler:

  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 17.7       3.72     3.72 13786208     0.00     0.00  Ns_DStringNAppend [8]
  6.1       5.00     1.28   107276     0.01     0.03  MakePath [10]
  2.9       5.60     0.60  1555972     0.00     0.00  Ns_DStringFree [35]
  2.7       6.18     0.58  1555965     0.00     0.00  Ns_DStringInit [36]
  2.3       6.67     0.49  1507858     0.00     0.00  ns_realloc [40]

Out of 21.05 seconds of total clock time, Ns_DStringNAppend consumed about 4 seconds, or about 18% of the time in and of itself. It was called 13 million times.

MakePath consumed one and a half seconds itself, and its children consumed three and a half seconds. At least one individual call to this consumed 0.01, and at least one individual call took a total of 0.03 seconds in MakePath and its children.

Handy tip – the function numbers in brackets are approximately sorted by time consumption, so a function with a [low number] will generally be more interesting than one with a [high number].

Now that you know that Ns_DStringNAppend is called a bunch of times, this could be a useful target for optimization, I’d look at its entry in the call graph section.

Before doing that, just for illustration, take a look at AllocateCa [33] since it has all of the interesting pieces of the call graph in a more compact size:

                0.04        0.18   53622/160866      Ns_CacheNewEntry [62]
                0.04        0.18   53622/160866      Ns_CacheDoStat [58]
                0.04        0.18   53622/160866      Ns_CacheLockURL [64]
[33]     3.0    0.11        0.53  160866         AllocateCa [33]
                0.16        0.17  160866/321890      Ns_DStringVarAppend [30]
                0.06        0.00  160866/1555972     Ns_DStringFree [35]
                0.06        0.00  160866/1555965     Ns_DStringInit [36]
                0.04        0.00  160866/1341534     Ns_LockMutex [43]
                0.03        0.00  160866/1341534     Ns_UnlockMutex [53]

The entries above AllocateCa [33] are the functions that call AllocateCa. The entries below that are the functions that AllocateCa calls. There are two numbers separated by a slash: the first number is the number of calls that the function has made, while the second number is the total number of invocations of that function.

In other words, for 160866/321890 Ns_DStringVarAppend [30], AllocateCa called Ns_DStringVarAppend 160866 times. Across all of AOLServer, Ns_DStringVarAppend was called 321890 times.

Similarly, for 53622/160866 Ns_CacheNewEntry [62], means that Ns_CacheNewEntry called AllocateCa 53622 times, and AllocateCa was called 160866 times total.

So, just by looking at this snippet, you know that the three Ns_Cache functions each call AllocateCa about once per serving of index.html, and that AllocateCa makes a single call to Ns_DStringVarAppend, Ns_DStringFree, etc… each time. What’s also interesting to note is that someone is calling Ns_DStringFree more than Ns_DStringInit. This may be (or may not) be a bug in AOLServer. You can go see Ns_DStringInit and Ns_DStringFree yourself and track down who the culprit is.

The floating “3.0” on the left is the percent of total time that the function consumed. The two columns of numbers are the amount of time (in seconds) that the function consumed itself (AllocateCa took 0.11 seconds of time total to run its own code) and the amount of time in the function’s children (0.53 seconds were spent in its children)

Getting back to real analysis of DStringNAppend, you can see that MakePath made 50% of the Ns_DStringNAppend calls. Since you know that there were 53623 fetches of index.html, that means that for each page, MakePath was called twice, and for each call to MakePath, Ns_DStringNAppend was called 64 times.

If one call to MakePath could be elided (since it’s getting called twice), or if fewer than 64 Ns_DStringNAppends could be done per call, we could see a performance boost.

Just browsing the gprof output can be an illuminating exercise. If you have a gut feeling that a particular function is a hot spot (say, Ns_LockMutex [43]), you can see the call graph for that function, see if it’s consuming lots of time, or if it’s being called a whole bunch.  Here it was called 1,341,534 times, or about 25 times per page serve. Maybe that’s high.  Maybe that’s right.  Sometimes a suspected culprit isn’t there, or you find a surprising time waster.

Because this sample gprof output was done on a Dec Alpha system, there was some suckage involved, such as no explicit time recorded for system calls. So we don’t know if, for example, select() blocked for a long time on each call.