One of the scripts in the DTrace manual contains a bug. (I searched
the archives for this list but didn''t find any previous mention of
this.)
In the chapter for the sched provider, this script is presented as a
way to measure CPU latency:
--------------------------------------------------------------------------------
sched:::enqueue
{
self->ts = timestamp;
}
sched:::dequeue
/self->ts/
{
@[args[2]->cpu_id] = quantize(timestamp - self->ts);
self->ts = 0;
}
--------------------------------------------------------------------------------
The example shows some outliers in the one-second range, and the text
even remarks on this fact. The bug in the script is the use of
self->ts. The enqueue and dequeue probes aren''t guaranteed to fire
in
the same thread. This can be seen using the following script:
--------------------------------------------------------------------------------
#!/usr/sbin/dtrace -qs
sched:::enqueue
{
a[args[0]->pr_lwpid, args[1]->pr_pid, args[2]->cpu_id]
curthread->t_did;
}
sched:::dequeue
/ a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] &&
(a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] !=
curthread->t_did) /
{
printf("BINGO!\n");
a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] = 0;
}
--------------------------------------------------------------------------------
The correct version of the script in the documentation is the
following, which tracks the timestamp based on the PID and LWPID of
the thread being queued and the CPU on which it''s being queued. (And
tracking the CPU is probably redundant in this case, too.) :
--------------------------------------------------------------------------------
sched:::enqueue
{
a[args[0]->pr_lwpid, args[1]->pr_pid, args[2]->cpu_id]
timestamp;
}
sched:::dequeue
/ a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] /
{
@[args[2]->cpu_id] = quantize(timestamp -
a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id]);
a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] = 0;
}
--------------------------------------------------------------------------------
I''ll update the wiki for this, but I''ll wait until someone
else points
out my own bugs before doing so. :-)
Chad
Doh! I''ll point out my own bug: On Thu, Dec 11, 2008 at 11:27 AM, Chad Mynhier <cmynhier at gmail.com> wrote:> > The example shows some outliers in the one-second range, and the text > even remarks on this fact. The bug in the script is the use of > self->ts. The enqueue and dequeue probes aren''t guaranteed to fire in > the same thread. This can be seen using the following script: > > -------------------------------------------------------------------------------- > > #!/usr/sbin/dtrace -qs > > sched:::enqueue > { > a[args[0]->pr_lwpid, args[1]->pr_pid, args[2]->cpu_id] > curthread->t_did; > } > > sched:::dequeue > / a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] && > (a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] != curthread->t_did) / > { > printf("BINGO!\n"); > a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] = 0; > } > > --------------------------------------------------------------------------------This script should actually be the following: -------------------------------------------------------------------------------- #!/usr/sbin/dtrace -qs sched:::enqueue { self->ts = timestamp; a[args[0]->pr_lwpid, args[1]->pr_pid, args[2]->cpu_id] curthread->t_did; } sched:::dequeue / self->ts && (a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] != curthread->t_did) / { printf("BINGO!\n"); a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] = 0; self->ts = 0; } -------------------------------------------------------------------------------- The script needs to grab a thread-local variable for comparison in order to demonstrate that the dequeue probe isn''t necessarily firing in the same probe. Chad
On Thu, Dec 11, 2008 at 11:53 AM, Chad Mynhier <cmynhier at gmail.com> wrote:> Doh! I''ll point out my own bug: > > This script should actually be the following: > > -------------------------------------------------------------------------------- > > #!/usr/sbin/dtrace -qs > > sched:::enqueue > { > self->ts = timestamp; > a[args[0]->pr_lwpid, args[1]->pr_pid, args[2]->cpu_id] > curthread->t_did; > } > > sched:::dequeue > / self->ts && > (a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] != curthread->t_did) / > { > printf("BINGO!\n"); > a[args[0]->pr_lwpid,args[1]->pr_pid,args[2]->cpu_id] = 0; > self->ts = 0; > } > > -------------------------------------------------------------------------------- > > The script needs to grab a thread-local variable for comparison in > order to demonstrate that the dequeue probe isn''t necessarily firing > in the same probe.That should read "firing in the same thread." I probably also should have made it explicit that the bug didn''t invalidate the analysis. The script in the documentation (aka /usr/demo/dtrace/qtime.d) is still wrong. If nobody has any objections, I''ll update the wiki sometime in the next few days. I''ll also submit a bug to get /usr/demo/dtrace/qtime.d fixed. Chad