DTrace Examples

This page contains a quick-start guide to DTrace and some useful examples of how to use DTrace to instrument your kernel for performance or functional analysis.

This script simply samples time spent in callout handlers and builds a histogram with the results so that you can quickly see if there are long-running callouts to investigate.

callout_execute:::callout_start
{
        self->cstart = timestamp;
}

callout_execute:::callout_end
{

        @length = quantize(timestamp - self->cstart);
}

Submitted by RobertWatson.

cinnamon-freebsd# dtrace -s d.d
dtrace: script 'd.d' matched 2 probes
^C

           value  ------------- Distribution ------------- count    
               1 |                                         0        
               2 |                                         7        
               4 |                                         9        
               8 |                                         14       
              16 |                                         20       
              32 |                                         34       
              64 |                                         44       
             128 |@                                        69       
             256 |@                                        99       
             512 |@                                        112      
            1024 |@                                        133      
            2048 |@                                        131      
            4096 |@@@@                                     377      
            8192 |@@@@@@@@@@@@                             1322     
           16384 |@@@@@@                                   689      
           32768 |@@@@                                     416      
           65536 |@@@                                      362      
          131072 |@@@                                      304      
          262144 |@                                        124      
          524288 |                                         22       
         1048576 |                                         7        
         2097152 |                                         2        
         4194304 |                                         1        
         8388608 |                                         3        
        16777216 |                                         1        
        33554432 |                                         0        

This script is loosely based on a similar one from OpenSolaris's sdt Provider page, but due to slight differences in types and probe naming, we can't use theirs verbatim:

#pragma D option quiet

callout_execute:::callout_start
{
        self->cstart = timestamp;
}

callout_execute:::callout_end
{

        @callouts[((struct callout *)arg0)->c_func] = sum(timestamp -
            self->cstart);
}

tick-1sec
{
        printa("%40a %10@d\n", @callouts);
        clear(@callouts);
        printf("\n");
}

BEGIN
{
        printf("%40s | %s\n", "function", "nanoseconds per second");
}

Submitted by RobertWatson.

This script works by measuring the time at the start of a callout, then again on termination and billing that time incrementally to the callout function that ran. Once a second, we print the results and reset the counters.

cinnamon-freebsd# dtrace -s d.d
                                function | nanoseconds per second
                      kernel`ipport_tick      19215
                        kernel`nd6_timer      21521
                   kernel`lance_watchdog      31848
             kernel`kbdmux_kbd_intr_timo      34418
                       kernel`logtimeout     106167
                       kernel`pffasttimo     149003
                       kernel`scrn_timer     157988
                     kernel`tcp_isn_tick     161720
                       kernel`pfslowtimo     201723
                    kernel`dcons_timeout     309218
                              0xc42deeb0     443589
                           kernel`lim_cb     584293
                    kernel`atkbd_timeout     789599
                              0xc42d34f0     807851
                   kernel`sleepq_timeout    4198977

^C

===Measure total time spent in non-MPSAFE callouts over 10-second intervals == The same as the previous script, but only include callouts that use Giant as their lock:

#pragma D option quiet
#pragma D option dynvarsize=64m

callout_execute:::callout_start
/(((struct callout *)arg0)->c_lock == &`Giant.lock_object)/
{
        self->start = timestamp;
}

callout_execute:::callout_end
/self->start/
{

        @callouts[((struct callout *)arg0)->c_func] = sum(timestamp -
            self->start);
        self->start = 0;
}

tick-10sec
{
        normalize(@callouts, 10);
        printa("%40a %10@d\n", @callouts);
        printf("\n");
        clear(@callouts);
}

BEGIN
{
        printf("%40s | %s\n", "function", "nanoseconds per second");
}

Submitted by RobertWatson

As before, except that only callouts using Giant are measured. Note the “`” before Giant in order to name a kernel global variable.

This script captures an array of counters, one for each stack trace leading to a non-zero return from priv_check_cred() using the fbt provider:

fbt::priv_check_cred:return
/arg1 != 0/
{
        @traces[stack()] = count();
}

Submitted by RobertWatson

Interestingly, fbt on my test box only appears to have an entry event for priv_check() and no return.