11.8. Using gdb to Generate Call Traces

The two different tools for retrieving information about which functions our application was calling gave us different information about which functions were the hot functions. We theorized that the high-level functions that ltrace reported were calling the low-level function that operofile was reporting. It would be nice to have a performance tool that could show us exactly which functions were calling g_type_check_instance_is_a to verify this theory.

Although no Linux performance tool shows us exactly which functions are calling a particular function, gprof should be able to present this callback information, but this requires recompiling the application and all the libraries that it relies on with the -pg flag to be effective. For nautilus, which relies on 72 shared libraries, this can be a daunting and infeasible task, so we have to look for another solution. Newer versions of oprofile can also provide this type of information, but because oprofile only samples periodically, it will still not be able to account for every call to any given function.

Fortunately, we can creatively use gdb to extract that information. Using gdb to trace the application greatly slows down the run; however, we do not really care whether the trace takes a long time. We are interested in finding the number of times that a particular function is called rather than the amount of time it is called, so it is acceptable for the run to take a long time. Luckily, the creation of the pop-up menu is in the millisecond range; even if it is 1,000 times slower with gdb, it still only takes about 15 minutes to extract the full trace. The value of the information outweighs our wait to retrieve it.

In particular, to find which functions are calling g_type_check_instance_is_a, we are going to use a few different features of gdb. First, we use gdb's ability to set a breakpoint at that function. Then we use gdb's ability to generate a backtrace with bt at that breakpoint. These two features are really all that we need to figure out which functions are calling this g_type_check_instance_is_a, but manually recording the information and continuing would be tedious. We would need to type bt ; cont after each time gdb breaks in the function.

To solve this, use another one of gdb's features. gdb can execute a given set of commands when it hits a breakpoint. By using the command command, we can tell gdb to execute bt; cont every time it hits the breakpoint in our function. So now the backtrace displays automatically, and the application continues running every time it hits g_type_check_instance_is_a.

Now we have to isolate when the trace actually runs. We could just set up the breakpoint in g_type_check_instance_is_a at the start of the nautilus execution, and gdb would show tracing information when it is called by any function. Because we only care about those functions that are called when we are creating a pop-up menu, we want to limit that tracing to only when pop-ups are being created. To do this, we set another breakpoint at the beginning and end of the fm_directory_view_pop_up_background_context_menu function. When we reach the first breakpoint, we turn on the backtracing in g_type_check_instance_is_a; when we reach the second breakpoint, we exit the debugger. This limits the backtrace information to that which is generated when we are creating a pop-up menu. Finally, we want to be able to save this backtrace information for post-processing. We can use gdb's ability to log its output to a file to save the information for later. The commands passed into gdb to extract this information are shown in Listing 11.12.

Listing 11.12.

# Prevent gdb from stopping after a screenful of output

set height 0

# Turn on output logging to a file (default: gdb.txt)

set logging on

# Turn off output to the screen

set logging redirect on

# Stop when a popup menu is about to be created

break fm-directory-view.c:5730

# Start the application

run

# When we've stopped at the preceding breakpoint, setup

# the breakpoint in g_type_check_instance_is_a

break g_type_check_instance_is_a

# When we reach the breakpoint, print a backtrace and exit

command

bt

cont

end

# break after the popup was created and exit gdb

break fm-directory-view.c:5769

command

quit

end

# continue running

cont

When running these gdb commands and opening a pop-up menu, gdb churns away for several minutes and creates a 33MB file containing all the backtrace information for functions that called the g_type_check_instance_is_a function. A sample of one is shown in Listing 11.13.

Listing 11.13.

Breakpoint 2, g_type_check_instance_is_a (type_instance=0x9d2b720,

iface_type=164410736) at gtype.c:31213121      if (!type_instance ||

!type_instance->g_class)

#1  0x08099f09 in fm_directory_view_pop_up_background_context_menu

(view=0x9d2b720, event=0x9ceb628)

    at fm-directory-view.c:5731

#2  0x080a2911 in icon_container_context_click_background_callback

(container=0x80c5a2b, event=0x9ceb628,

    icon_view=0x9d2b720) at fm-icon-view.c:2141

#3  0x00da32be in g_cclosure_marshal_VOID__POINTER (closure=0x9d37620,

return_value=0x0, n_param_values=2,

    param_values=0xfef67320, invocation_hint=0xfef67218,

marshal_data=0x0) at gmarshal.c:601

#4  0x00d8e160 in g_closure_invoke (closure=0x9d37620,

return_value=0x9d2b720, n_param_values=164804384,

    param_values=0x9d2b720, invocation_hint=0x9d2b720) at gclosure.c:437

#5  0x00da2195 in signal_emit_unlocked_R (node=0x9d33140, detail=0,

instance=0x9d35130, emission_return=0x0,

    instance_and_params=0xfef67320) at gsignal.c:2436

#6  0x00da1157 in g_signal_emit_valist (instance=0x9d35130, signal_id=0,

detail=0, var_args=0xfef674b0 "") at gsignal.c:2195

....

Although this information is very detailed, it is not exactly in an easy-to-digest format. It would be better if each backtrace were on a single line, with each function separated by arrows. It would also be nice to get rid of the backtrace information above the call to fm_directory_view_pop_up_background_context_menu, because we know that every one of the calls will have that same backtrace information. We can use the python program, slice.py, shown in Listing 11.14 to do exactly that. The program takes the verbose output file generated by gdb and creates a nicely formatted call trace of every function that called fm_directory_view_pop_up_background_context_menu.

Listing 11.14.

#!/usr/bin/python

import sys

import string

funcs = ""

stop_at = "fm_directory_view_pop_up_background_context_menu"

for  line  in sys.stdin:

    parsed = string.split(line)

    if (line[:1] == "#"):

        if (parsed[0] == "#0"):

            funcs = parsed[1]

        elif (parsed[3] == stop_at):

            print funcs

            funcs = ""

        else:

            funcs = parsed[3] + "->" + funcs

When we run the gdb.txt file into this python program using the command line shown in Listing 11.15, we have a more consolidated output, an example of which is shown in Listing 11.16.

Listing 11.15.

cat gdb.txt | ./slice.py > backtrace.txt

Listing 11.16.

....

create_popup_menu->gtk_widget_show->g_object_notify->g_type_check_

instance_is_a



create_popup_menu->gtk_widget_show->g_object_notify->g_object_ref->g_

type_check_instance_is_a



create_popup_menu->gtk_widget_show->g_object_notify->g_object_

notify_queue_add->g_param_spec_get_redirect_target->g_type_check_

instance_is_a



create_popup_menu->gtk_widget_show->g_object_notify->g_object_notify_

queue_add->g_param_spec_get_redirect_target->g_type_check_instance_is_a



create_popup_menu->gtk_widget_show->g_object_notify->g_object_unref->g_

type_check_instance_is_a



create_popup_menu->gtk_widget_show->g_object_unref->g_type_check_

instance_is_a

...

Because the output lines are long, they have been wrapped when displayed in this book; in the text file, however, there is one backtrace per line. Each line ends with the g_type_check_instance_is_a function. Because each backtrace spans only one line, we can extract information about the backtraces using some common Linux tools, such as wc, which we can use to count the number of lines in a particular file.

First, let's look at how many calls have been made to the g_type_check_instance_is_a function. This is the same as the number of backtraces and, hence, the number of lines in the backtrace.txt file. Listing 11.17 shows the wc command being called on our pruned backtrace file. The first number indicates the number of lines in the file.

Listing 11.17.

[ezolt@localhost menu_work]$ wc backtrace.txt

   6848    6848 3605551 backtrace.txt

As you can see, the function has been called 6,848 times just to create the pop-up menu. Next, let's see how many of those functions are made on behalf of bonobo_window_add_popup. This is shown in Listing 11.18.

Listing 11.18.

[ezolt@localhost menu_work]$ grep bonobo_window_add_popup backtrace.txt | wc

   6670    6670 3558590

bonobo_window_add_popup is responsible for 6,670 of the calls to our hot function. Looking at the backtrace.txt file reveals few of these are direct calls; most are made from other functions that it calls. From this, it appears as if the bonobo_window_add_popup is indeed responsible for much of the CPU time that is being spent. However, we still have to confirm that this is the case.