Alan Hargreaves' Blog

The ramblings of an Australian SaND TSC* Principal Field Technologist

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.


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/ we can find out what these instructions are.

# mdb /lib/ -
Loading modules: [ ]
> 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.


Written by Alan

July 14, 2004 at 3:01 am

Posted in Solaris Express

2 Responses

Subscribe to comments with RSS.

  1. Nice scripts. And I liked the depth trick for aggregating on all calls.

    Vlad Grama

    July 16, 2004 at 8:42 am

  2. It looks like in section 2 above I omitted a closing brace on the end of the line. I have corrected this.
    Thanks Dan Lacher for asking the question that pointed me to the error.

    Alan Hargreaves

    July 19, 2004 at 4:29 pm

Comments are closed.

%d bloggers like this: