Interpreting the Results

The graphical output of Massif is largely self explanatory. Each band represents the memory allocated by one function over time. Once you identify which bands are using the most memory, usually the big thick ones at the top you will have to consult the text file for the details.

The text file is arranged as a hierarchy of sections, at the top is a list of the worst memory users arranged in order of decreasing spacetime. Below this are further sections, each breaking the results down into finer detail as you proceed down the call-stack. To illustrate this we will use the output of the command above.

Figure 2-1Massif output for the unoptimized version of the Swell Foop program.

Figure 2-1 shows a typical postscript output from Massif. This is the result you would get from playing a single game of Swell Foop (version 2.8.0) and then quitting. The postscript file will have a name like massif.12345.ps and the text file will be called massif.12345.txt. The number in the middle is the process ID of the program that was examined. If you actually try this example you will find two versions of each file, with slightly different numbers, this is because Swell Foop starts a second process and Massif follows that too. We will ignore this second process, it consumes very little memory.

At the top of the graph we see a large yellow band labelled gdk_pixbuf_new. This seems like an ideal candidate for optimization, but we will need to use the text file to find out what is calling gdk_pixbuf_new. The top of the text file will look something like this:

Command: ./swell-foop

== 0 ===========================
Heap allocation functions accounted for 90.4% of measured spacetime

Called from:
  28.8% : 0x6BF83A: gdk_pixbuf_new (in /usr/lib/libgdk_pixbuf-2.0.so.0.400.9)

    6.1% : 0x5A32A5: g_strdup (in /usr/lib/libglib-2.0.so.0.400.6)

    5.9% : 0x510B3C: (within /usr/lib/libfreetype.so.6.3.7)

    3.5% : 0x2A4A6B: __gconv_open (in /lib/tls/libc-2.3.3.so)
        

The line with the '=' signs indicates how far down the stack trace we are, in this case we are at the top. After this it lists the heaviest users of memory in order of decreasing spacetime. Spacetime is the product of the amount of memory used and how long it was used for. It corresponds to the area of the bands in the graph. This part of the file tells us what we already know: most of the spacetime is dedicated to gdk_pixbuf_new. To find out what called gdk_pixbuf_new we need to search further down the text file:

== 4 ===========================
Context accounted for 28.8% of measured spacetime
  0x6BF83A: gdk_pixbuf_new (in /usr/lib/libgdk_pixbuf-2.0.so.0.400.9)
  0x3A998998: (within /usr/lib/gtk-2.0/2.4.0/loaders/libpixbufloader-png.so)
  0x6C2760: (within /usr/lib/libgdk_pixbuf-2.0.so.0.400.9)
  0x6C285E: gdk_pixbuf_new_from_file (in /usr/lib/libgdk_pixbuf-2.0.so.0.400.9)

Called from:
  27.8% : 0x804C1A3: load_scenario (swell-foop.c:463)

    0.9% : 0x3E8095E: (within /usr/lib/libgnomeui-2.so.0.792.0)

  and 1 other insignificant place
        

The first line tells us we are now four levels deep into the stack. Below it is a listing of the function calls that leads from here to gdk_pixbuf_new. Finally there is a list of functions that are at the next level down and call these functions. There are, of course, also entries for levels 1, 2, and 3, but this is the first level to reach right down through the GDK code to the Swell Foop code. From this listing, we can see instantly that the problem code is load_scenario.

Now that we know what part of our code is using all the spacetime we can look at it and find out why. It turns out that the load_scenario is loading a pixbuf from file and then never freeing that memory. Having identified the problem code, we can start to fix it.