This is an old revision of the document!
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.
Histogram of time spent in each callout
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
Measure total time spent in each callout handler over 1-second intervals
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.
cinnamon-freebsd# dtrace -s d.d
dtrace: dynamic variable size lowered to 16m
function | nanoseconds per second
kernel`nd6_timer 19388
kernel`kbdmux_kbd_intr_timo 141079
kernel`scrn_timer 345507
kernel`logtimeout 418742
kernel`atkbd_timeout 574425
^C
Collect stack traces leading to failed priv_check_cred() calls
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.
dtrace: script 'd.d' matched 1 probe
^C
kernel`priv_check+0x3d
kernel`vn_stat+0x176
kernel`vn_statfile+0x121
kernel`devfs_stat_f+0x27
kernel`kern_fstat+0x7a
kernel`fstat+0x27
kernel`syscall+0x2d3
kernel`0xc0b18f50
2
kernel`fork1+0x35c
kernel`vfork+0x29
kernel`syscall+0x2d3
kernel`0xc0b18f50
2
kernel`vaccess+0x1de
kernel`ufs_access+0x1e6
kernel`VOP_ACCESS_APV+0xa5
kernel`ufs_lookup+0x804
kernel`VOP_CACHEDLOOKUP_APV+0xa5
kernel`vfs_cache_lookup+0xcc
kernel`VOP_LOOKUP_APV+0xa5
kernel`relookup+0xbe
kernel`ufs_rename+0xb0d
kernel`VOP_RENAME_APV+0xa5
kernel`kern_renameat+0x2b7
kernel`kern_rename+0x36
kernel`rename+0x29
kernel`syscall+0x2d3
kernel`0xc0b18f50
17
...
Histogram of time spent waiting on NFSv3 RPCs by system call
This script measures all time spent waiting on RPC replies for each system call, and then generates a histogram of those times sorted by system call name.
syscall:::entry
{
self->count = 0;
}
nfsclient:nfs3::start
{
self->timestamp = timestamp;
}
nfsclient:nfs3::done
{
self->count += (timestamp - self->timestamp);
}
syscall:::return
/self->count != 0/ {
@syscalls[probefunc] = quantize(self->count);
}
Submitted by RobertWatson
dtrace: script 'd.d' matched 1040 probes
dtrace: aggregation size lowered to 6m
^C
fstatfs
value ------------- Distribution ------------- count
131072 | 0
262144 |@@@@@@@@@@@@@ 2
524288 |@@@@@@@@@@@@@ 2
1048576 |@@@@@@@@@@@@@ 2
2097152 | 0
open
value ------------- Distribution ------------- count
4 | 0
8 |@ 3
16 | 1
32 |@ 2
64 | 1
128 | 0
256 | 0
512 | 0
1024 | 0
2048 | 1
4096 | 1
8192 | 0
16384 | 0
32768 | 0
65536 | 0
131072 | 0
262144 |@@@@@ 11
524288 |@@@@@@@@@@@@@@@@ 35
1048576 |@@@@@@@@@@@@ 26
2097152 |@ 3
4194304 |@ 2
8388608 | 0
lstat
value ------------- Distribution ------------- count
64 | 0
128 | 1
256 | 1
512 | 0
1024 | 1
2048 | 1
4096 | 0
8192 | 0
16384 | 1
32768 | 0
65536 | 0
131072 | 1
262144 |@@@@@ 15
524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 86
1048576 |@@@@@ 17
2097152 | 1
4194304 | 0
8388608 | 1
16777216 | 0