Alan Hargreaves' Weblog

Playing with dtrace in user space

In chapter 30 of the dtrace reference guid we look at user level tracing. There is only one example there, so I thought I'd write a few more, as I see this as being an extremely useful tool in user-space as well as the obvious kernel use.

Now, in the current build of Solaris Express, we cannot directly run a process from the dtrace command line, so we need to do it with truss. The sample command I will be using is a simple "ls -ls". You'll probably need two terminal sessions to do this. One to deal with the command and the other the dtrace script.

On running the truss command you'll get something like

$ truss -f -t\!all -U a.out:main ls -ls
3470/1@1:       -> main(0x2, 0xffbfe784, 0xffbfe790, 0x26000)

To restart the command again after you have the dtrace running, simply use prun.

$ prun 3470

For the dtrace commands that use aggregations you need to ctrl-c the command once the process has finished.

OK, to some commands.

1. Let's look how often we call each function within the lifetime of this process.

# dtrace -n 'pid3470:::entry { @funcs[probefunc] = count(); } END { printa(@funcs); }'
dtrace: description 'pid3470:::entry ' matched 2921 probes

CPU     ID                    FUNCTION:NAME
  2      2                             :END 
  pthread_rwlock_unlock                                             1
  _fflush_u                                                         1
  rwlock_lock                                                       1
  ...
  iflush_range                                                     90
  callable                                                        136
  elf_find_sym                                                    139
  _ti_bind_clear                                                  140
  rt_bind_clear                                                   140
  strcmp                                                          146

This shows us the "hot" functions in our code.

2. We might also be interested in how long we spend in these functions per call.

# dtrace -n 'BEGIN { depth = 1; } pid3497:::entry { self->start[depth++] = vtimestamp; } \
  pid3497:::return { @funcs[probefunc] = quantize(vtimestamp - self->start[depth-1]); \
  self->depth[depth--] = 0;}END { printa(@funcs);}'
dtrace: description 'BEGIN ' matched 5816 probes

This gives us some histograms of how long we spend in various functions.

e.g.

  strcmp                                            
           value  ------------- Distribution ------------- count    
            1024 |                                         0        
            2048 |@@@@@@@@@@@@@                            47       
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              98       
            8192 |                                         0        
           16384 |                                         0        
           32768 |                                         1        
           65536 |                                         0        

We could just have easily specified the functions we were interested in.

3. OK, suppose for arguments sake we were interested in strcmp (since I listed it already). How about we look at the codepath that we take through it?

# dtrace -n 'pid3486::strcmp: { trace(probename);}'
dtrace: description 'pid3511::strcmp: ' matched 256 probes

We get a really long list as we are looking at all calls to it (and we have a few). This may not be very useful. The last call looks like:

  2  47463                     strcmp:entry   entry                            
  2  47464                         strcmp:0   0                                
  2  47465                         strcmp:4   4                                
  2  47466                         strcmp:8   8                                
  2  47508                        strcmp:b0   b0                               
  2  47509                        strcmp:b4   b4                               
  2  47462                    strcmp:return   return

This list is actually a call flow through strcmp for all calls to that function. Looking at the full list could give us ideas about where we might optimise. This could be even more useful if we knew where the hot instructions within this code flow were.

4. We can do this by turning on probes for all instructions within strcmp (like above), but aggregating on the probename, which will be the function offset.

# dtrace -n 'pid3517::strcmp: { @hot[probename] = count();} END {printa(@hot);}'
dtrace: description 'pid3517::strcmp: ' matched 257 probes

The end of this list looks like

  b0                                                               74
  b4                                                               74
  c                                                                77
  18                                                               77
  14                                                               77
  10                                                               77
  2c                                                               82
  24                                                               82
  28                                                               82
  20                                                               82
  30                                                               82
  0                                                               146
  entry                                                           146
  8                                                               146
  return                                                          146
  4                                                               146

We can ignore the entry and returns as we already account for those. We can tell from them (however) that in this run we called strcmp 146 times.

4. Anyway, if we run up mdb on /lib/libc.so.1 we can find out what these instructions are.

# mdb /lib/libc.so.1 -
Loading modules: [ libc.so.1 ]
> strcmp::dis
strcmp:                         subcc     %o0, %o1, %o2
strcmp+4:                       be        +0xac         
strcmp+8:                       sethi     %hi(0x1010000), %o5
...

OK we would expect to execute these on each call, so what about the ones we hit 82 times?

strcmp+0x20:                    ldub      [%o1 + %o2], %o0
strcmp+0x24:                    ldub      [%o1], %g1
strcmp+0x28:                    subcc     %o0, %g1, %o0
strcmp+0x2c:                    bne       +0x1c4        
strcmp+0x30:                    addcc     %o0, %g1, %g0

strcmp is probably not the best example to use as it is a call that has already been very highly optimised, but I hope you get the idea. This is going to be very useful in finding bottlenecks and suboptimal codepaths in userspace.

Posted at 08:01PM Jul 14, 2004 by Alan Hargreaves in Solaris Express  |  Comments[2]