Jeremy Uejio's Blog

DTrace Tutorial for X Window Programmers

Here's some notes on a DTrace presentation I gave to our desktop sustaining group. It's geared towards application debugging esp. for X Window System programmers and not for kernel debugging.

DTrace is usually thought of as a tool for kernel debugging. However, I have found it very useful for user level debugging, too. It's especially useful when first debugging an issue that you don't know where to begin and for issues involving applications that are already running.

I usually use DTrace for debugging the call stack.  That is, trying to figure out what functions are being called, by whom, and with what arguments.  DTrace also lets you look at return values. I've also used DTrace for performance issues such as determining how many times a function is called and how long that took.

Useful One-liners:

Here are some one-liners for client debugging.  There are a number of useful ones from Brendan Gregg's website at:

http://www.brendangregg.com/DTrace/dtrace_oneliners.txt

Here's one which prints out new processes:

dtrace -qn 'syscall::exec*:return { printf("%Y %s\n",walltimestamp,curpsinfo->pr_psargs); }'

If I run gnome-terminal, I see the following output:

2007 Nov 14 16:56:17 gnome-terminal
2007 Nov 14 16:56:18 gnome-pty-helper
2007 Nov 14 16:56:18 pt_chmod 4
2007 Nov 14 16:56:18 /usr/lib/utmp_update testuser /5 pts/5 19917 7 0 0 1195088178 373248 0 000000000
2007 Nov 14 16:56:18 bash

Here's one for looking at files opened by processes:

dtrace -n 'syscall::open*:entry { printf("%s %s",execname,copyinstr(arg0)); }'

If I run gnome-terminal again, I get a lot of output:

...
  0  43837      open64:entry gnome-terminal /usr/share/themes/blueprint/gtk-2.0/vertStepDwnButton.png
  0  43837      open64:entry gnome-terminal /usr/share/themes/blueprint/gtk-2.0/menuBorderButton.png
  0  43453      open:entry nscd /etc/user_attr
  0  43453      open:entry utmpd /proc/19924/psinfo
  0  43453      open:entry gconfd-2 /export/home/testuser/.gconf/apps/panel/profiles/default/applets/...
  0  43453      open:entry gconfd-2 /export/home/testuser/.gconfd/saved_state.tmp
...

Try doing this with dbx or truss or any other tool, especially the first example!

Some things to notice about these one-liners:

The -q option means "quiet".  The -n means that the next argument is a probe name.  In these examples, we're looking at system calls so we use the syscall provider and then specify which function call and that we're looking at the entry to a function.  This probe fires at the entry to the function.

The arguments to the function are accessible via the variables arg0, arg1, arg2, etc.  So, in the open example, we're printing the first argument to the function open which is the pathname.  For strings variables, you need to use the copyinstr() function to print the contents of the string.  For integers you don't have to do any special conversion.

However, I found that it's not usually system calls that I want to look at, but rather user library calls.  Unfortunately, you can't just do something like:

# dtrace -n 'syscall::XOpenDisplay:entry'

You will get the error:

dtrace: invalid probe specifier syscall::XOpenDisplay:entry: probe
description syscall::XOpenDisplay:entry does not match any probes

DTrace only knows about system calls, but you can use the pid provider to look at all the calls in a particular process.  For example "dtrace -l" will list out the probes. You can limit that also with -n.  Let's look at the probes for metacity for an Xlib call XMoveWindow:

dtrace -l -n "pid`pgrep metacity`::XMove*:"
   ID   PROVIDER            MODULE                          FUNCTION NAME
44083   pid19834       libX11.so.4                       XMoveWindow return
44084   pid19834       libX11.so.4                       XMoveWindow entry
44085   pid19834       libX11.so.4                       XMoveWindow 0
44086   pid19834       libX11.so.4                       XMoveWindow 1
...

Lots of output.  There are probes for both entry and return points and also arbitrary instructions.  You could trace the execution of instructions within a function as well.  However, I find dbx is probably a much easier tool to use for doing that.

In my examples, I'm only going to mention entry and return points.

So, now, let's take a look at a simple DTrace script, libX11.d. This script  just traces all calls to libX11:

# ./libX11.d `pgrep gnome-terminal`
dtrace: script './libX11.d' matched 1629 probes
CPU     ID                    FUNCTION:NAME
  0  44400                   XPending:entry
  0  44401             _XEventsQueued:entry
  0  44326                    _XFlush:entry
  0  44309                 _XFlushInt:entry
  0  44402     _X11TransBytesReadable:entry
  0  44403 _X11TransSocketBytesReadable:entry
...

Wow, lots of calls to XPending() and other functions.  We probably don't want to debug those, so before we remove them, we can format the output nicer by adding to the libX11.d script:

#pragma D option flowindent

Now we can see that XPending is calling these functions and that's probably not a very interesting function to look at, so, we can get rid of them by setting a flag in the entry probe to XPending(). Then in the return probe of XPending unset the flag.  When the flag is set, don't print out the function calls and when it is not set, then print out calls.

However, I'm also going to remove the flowindent because the indenting is sometimes annoying.  Also, I'm going to add a "quiet" option which will cause DTrace to not print out every probe that fires. So, I need to add my own printfs.  This results in, libX11_pending.d:

# ./libX11_pending.d `pgrep gnome-terminal`
XNextEvent called
_XDeq called
XFilterEvent called
XNextEvent called
_XDeq called
...
XChangeGC called
_XUpdateGCCache called
XChangeGC called
XChangeGC called
XSetClipRectangles called
_XSetClipRectangles called
XSetTSOrigin called
XFillRectangle called
...

So, we see lots and lots of libX11 functions being called.  Well, this also is too much information and probably not useful.  Suppose, we wanted to instead limit the calls to a specific type of call.  So, let's look at the next example.  libX11_grab.d.  This example prints out all the calls to any Xlib grab functions.  It also prints out the stack trace of the user process (gnome-terminal in this case) whenever the grab or ungrab function is called.  Printing out stack traces for grabs can be a problem when running in dbx since you probably can't type in the dbx window if client has a keyboard or pointer grab. So, DTrace is definitely the better tool here. In this example, I press the mouse button on the Edit menu item and get a popdown menu.

# ./libX11_grab.d `pgrep gnome-terminal`
XGrabPointer called

              libX11.so.4`XGrabPointer
              libgdk-x11-2.0.so.0.400.9`gdk_pointer_grab+0x180
XGrabKeyboard called

              libX11.so.4`XGrabKeyboard
              libgdk-x11-2.0.so.0.400.9`gdk_keyboard_grab+0x6c
...

More Complex Examples:

Now let's look at a complex example involving two processes.  Suppose, we want to know what happens in one processs when another process calls some function. The script trace2processes.d takes 3 arguments--the process id of the two processes and the function to key off of.  For example, if I want to know what the Xserver is doing when metacity calls XMoveWindow(), I would execute:

# ./trace2processes.d `pgrep Xnest` `pgrep metacity` XMoveWindow
metacity: XMoveWindow: enters
metacity: XMoveWindow: returns
Xnest: xnestGetImage: return = 1
Xnest: WriteToClient: entering
Xnest: WriteToClient: return = 2400
Xnest: DoGetImage: return = 0
Xnest: ProcGetImage: return = 0
Xnest: FlushAllOutput: entering
...

In my example, I am using the Xnest server since I was demo'ing this via a VNC session to engineers in Ireland and India and had Xnest running in VNC.

Here's another example, xscope in DTrace:

xscope.d

This shows how to use some of the Xserver probes to implement a simple DTrace version of the X debugging tool called xscope. Xscope is a tool for viewing the X protocol between client and server.

It's a pretty complex example.

First, I need to run DTrace with -C option so that it uses the preprocessor to parse the #include lines.  Then, I need include X11 header files.  However, I can't include X11/Xlib.h because there is a structure which conflicts with DTrace  So, not all Xlib structures can be used in DTrace. Unfortunately, the most important structure that you can't access is the Display structure. The xscope.d script shows an example of how to cast structures in DTrace such as casting the xEvent structure to show the component fields of an XEvent. The output of xscope is detailed in an earlier blog here.

Handy DTrace scripts from the DTrace Toolkit at:

http://www.brendangregg.com/dtrace.html#DTraceToolkit

I've used:

execsnoop - Traces execs of all processes.

dtruss - Truss written in DTrace  Runs much faster than truss so it can be very useful when truss is too slow.

Also:

memleak.d - from http://blogs.sun.com/sanjeevb/.  Lists memory leaks using DTrace.  Much faster than libumem and good when dbx access checking fails.

But, mostly, I modify one-liners from:
http://www.brendangregg.com/DTrace/dtrace_oneliners.txt

Sorry, I don't know of any way to detect memory corruption using DTrace.  

Posted at 09:59PM Nov 14, 2007 by uejio in Sun  | 

request-start: from client=21 (), request = X_CreateWindow
request-done: from client=21 (), request = X_ChangeWindowAttributes, resultCode = 0
request-start: from client=21 (), request = X_ChangeWindowAttributes
client-auth: client=21, from local pid=7209 (/usr/openwin/bin/xlogo)
request-done: from client=21 (/usr/openwin/bin/xlogo), request = X_ChangeWindowAttributes, resultCode = 0

send-event: to client = 21 (/usr/openwin/bin/xlogo), event type =  PropertyNotify (28)
PropertyNotify: window=0xa80001, atom=0x27, state=0, time=381056109

Found the following USB devices:
Enter the number of your choice:

     3. Logical Node: /dev/rdsk/c4t0d0p0
        Physical Node: /pci@0,0/pci1025,57@10,3/storage@3/disk@0,0
        Connected Device: Kingston DataTraveler 2.0 PMAP
        Device Type: Removable

# svcadm disable volfs
# fdisk -B /dev/rdsk/c4t0d0p0
# format -e /dev/rdsk/c4t0d0p0