Hi
I encountered some weird phenomena in dtrace, in which printouts by the
same thread are mis-ordered. That seems like a bug to me, but I may be
missing something, so wanted to share my experience and see if anyone
saw anything similar to this.
The simplest script with which the problem occurred looks as follows:
#!/usr/sbin/dtrace -s
#pragma D option quiet
self count;
pid$target::foo:entry
{
printf("thread.seq %d %d\n", tid, self->count);
self->count++;
}
Here "foo" is some function that is called by all threads of the
traced
process, and the script simply print a message, with a per-thread serial
number, whenever a call to foo is traced. Thus, a normal output should
look for example:
thread.seq 2 0
thread.seq 2 1
thread.seq 2 2
thread.seq 1 0
thread.seq 1 1
thread.seq 2 3
thread.seq 2 4
thread.seq 0 0
thread.seq 1 2
thread.seq 1 3
...
However, when running the script with an executable that calls foo with
high enough frequency (~7000 calls/sec), I noticed that messages for a
few of the threads were mis-ordered, e.g.
prompt> fgrep "seq 16" dtrace.output
thread.seq 16 13
thread.seq 16 14
thread.seq 16 15
thread.seq 16 16
thread.seq 16 17
thread.seq 16 18
[snip]
thread.seq 16 103
thread.seq 16 104
thread.seq 16 105
thread.seq 16 0
thread.seq 16 1
thread.seq 16 2
thread.seq 16 3
thread.seq 16 4
thread.seq 16 5
thread.seq 16 6
thread.seq 16 7
thread.seq 16 8
thread.seq 16 9
thread.seq 16 10
thread.seq 16 11
thread.seq 16 12
prompt>
In all cases that I saw, all messages were eventually printed out.
Also, for most of the threads, the order was right --- only a few
messages for a few threads were out-of-order. The minimum number of
threads I encountered it with was 16 (where all are calling foo()), with
a total of ~ 3400 foo calls in a bit less than 500ms...
Did anyone encounter anything similar? Is this a bug, or that I''m
missing something about the way printouts work in dtrace? Is there a way
to avoid such mis-ordering?
Thanks,
Yossi