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 300The 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 | 0The 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
