Using the sdt
Provider
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
in the system, as shown in the following output:
# dtrace -s ./callout.d
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
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
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
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/ { /* * This case focusses interval timeout(9F)s that * are short. Therefore, perform 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
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
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
ohci 0
value ------------- Distribution ------------- count
8192 | 0
16384 | 3
32768 | 1
65536 |@@@ 143
131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1368
262144 | 0