Examples

The following example is a script to observe callout behavior on a per-second basis:

#pragma D option quiet

sdt:::callout-start
{
    @callouts[((callout_t *)arg0)->c_func] = count();
}

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

Running this example reveals the frequent users of timeout(9F) in the system, as shown in the following output:

# dtrace -s ./callout.d
                                    FUNC      COUNT
                            TS`ts_update          1
              uhci`uhci_cmd_timeout_hdlr          3
                          genunix`setrun          5
                     genunix`schedpaging          5
                         ata`ghd_timeout         10
 uhci`uhci_handle_root_hub_status_change        309

                                    FUNC      COUNT
              ip`tcp_time_wait_collector          1
                            TS`ts_update          1
              uhci`uhci_cmd_timeout_hdlr          3
                     genunix`schedpaging          4
                          genunix`setrun          8
                         ata`ghd_timeout         10
 uhci`uhci_handle_root_hub_status_change        300

                                    FUNC      COUNT
              ip`tcp_time_wait_collector          0
                        iprb`mii_portmon          1
                            TS`ts_update          1
              uhci`uhci_cmd_timeout_hdlr          3
                     genunix`schedpaging          4
                          genunix`setrun          7
                         ata`ghd_timeout         10
 uhci`uhci_handle_root_hub_status_change        300

The timeout(9F) interface only produces a single timer expiration. Consumers of timeout() requiring interval timer functionality typically reinstall their timeout from their timeout() handler. The following example shows this behavior:

#pragma D option quiet

sdt:::callout-start
{
    self->callout = ((callout_t *)arg0)->c_func;
}

fbt::timeout:entry
/self->callout && arg2 <= 100/
{
    /*
     * In this case, we are most interested in interval timeout(9F)s that
     * are short.  We therefore do a linear quantization from 0 ticks to
     * 100 ticks.  The system clock's frequency — set by the variable
     * "hz" — defaults to 100, so 100 system clock ticks is one second. 
     */
    @callout[self->callout] = lquantize(arg2, 0, 100);
}

sdt:::callout-end
{
    self->callout = NULL;
}

END
{
    printa("%a\n%@d\n\n", @callout);
}

Running this script and waiting several seconds before typing Control-C results in output similar to the following example:

# dtrace -s ./interval.d
^C
genunix`schedpaging

           value  ------------- Distribution ------------- count    
              24 |                                         0        
              25 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 20       
              26 |                                         0        


ata`ghd_timeout

           value  ------------- Distribution ------------- count    
               9 |                                         0        
              10 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 51       
              11 |                                         0        


uhci`uhci_handle_root_hub_status_change

           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1515     
               2 |                                         0

The output shows that uhci_handle_root_hub_status_change() in the uhci(7D) driver represents the shortest interval timer on the system: it is called every system clock tick.

The interrupt-start probe can be used to understand interrupt activity. The following example shows how to quantize the time spent executing an interrupt handler by driver name:

interrupt-start
{
    self->ts = vtimestamp;
}

interrupt-complete
/self->ts/
{
    this->devi = (struct dev_info *)arg0;
    @[stringof(`devnamesp[this->devi->devi_major].dn_name),
        this->devi->devi_instance] = quantize(vtimestamp - self->ts);
}

Running this script results in output similar to the following example:

# dtrace -s ./intr.d
dtrace: script './intr.d' matched 2 probes
^C
 isp                                                       0
           value  ------------- Distribution ------------- count    
            8192 |                                         0        
           16384 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1        
           32768 |                                         0        

  pcf8584                                                   0
           value  ------------- Distribution ------------- count    
              64 |                                         0        
             128 |                                         2        
             256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@         157      
             512 |@@@@@@                                   31       
            1024 |                                         3        
            2048 |                                         0        

  pcf8584                                                   1
           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          154      
            8192 |@@@@@@@                                  37       
           16384 |                                         2        
           32768 |                                         0        

  qlc                                                       0
           value  ------------- Distribution ------------- count    
           16384 |                                         0        
           32768 |@@                                       9        
           65536 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      126      
          131072 |@                                        5        
          262144 |                                         2        
          524288 |                                         0        

  hme                                                       0
           value  ------------- Distribution ------------- count    
            1024 |                                         0        
            2048 |                                         6        
            4096 |                                         2        
            8192 |@@@@                                     89       
           16384 |@@@@@@@@@@@@@                            262      
           32768 |@                                        37       
           65536 |@@@@@@@                                  139      
          131072 |@@@@@@@@                                 161      
          262144 |@@@                                      73       
          524288 |                                         4        
         1048576 |                                         0        
         2097152 |                                         1        
         4194304 |                                         0        

  ohci                                                      0
           value  ------------- Distribution ------------- count    
            8192 |                                         0        
           16384 |                                         3        
           32768 |                                         1        
           65536 |@@@                                      143      
          131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     1368     
          262144 |                                         0