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^Cgenunix`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.ddtrace: script './intr.d' matched 2 probes^Cisp 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