When I run the following D script:
profile:::tick-5sec
{
}
simultaneously from three different windows, too my surprise, the trace
output _doesn''t_ seem to appear in each window at the same time. Since
there is only one probe, and the CPU utilization (it''s a one CPU
system)
is less than 1%, I would have thought that the difference in time
between the display in each window would have been imperceptible.
So to prove that it''s not a network issue (my "putty" windows
are
connected through the Internet), I also ran the following script from
one window:
#!/bin/sh
while :
do
echo xxx
echo xxx > /dev/pts/2
echo xxx > /dev/pts/3
sleep 5
done
where the redirections are to the other two windows. The output to each
window is so close together, that it appears to be simultaneous.
The time differential, when testing this with the dtrace script, is
sometimes as great as a half a second, although this varies.
Interestingly though, it doesn''t vary on one run, but on different
runs. In other words, when I start the three scripts, a rhythm is
established, and it pretty much stays the same for that run. If I stop
all of the scripts and restart them, I get a little different rhythm
pattern, but it stays the same for the whole run.
Also, while the test is running, if I open a fourth window, and run "yes
> /dev/null", it has no impact on the rhythm in the other three
windows.
Anybody know what''s going on in the buffer enqueue/dequeue process that
would cause this phenomenon?
Thanks,
Chip
G''Day Chip, On Sun, 30 Jul 2006, Chip Bennett wrote:> When I run the following D script: > > profile:::tick-5sec > { > } > > simultaneously from three different windows, too my surprise, the trace > output _doesn''t_ seem to appear in each window at the same time. Since > there is only one probe, and the CPU utilization (it''s a one CPU system) > is less than 1%, I would have thought that the difference in time > between the display in each window would have been imperceptible.The /usr/sbin/dtrace consumer by default reads the kernel buffer at 1 Hertz, and does so relative to when the process began running. I would imagine that while your probes are firing at the same time, the userland consumer is dumping the output offset to when they began running. I''d test it further using, # dtrace -x switchrate=10 -n ''BEGIN,tick-5sec { trace(timestamp); }'' To both bump up the switchrate of /usr/sbin/dtrace to 10 Hertz, and to see some numerical timestamps for comparison. That multiple DTrace consumers multiplex onto single instances of profile probes is interesting. When I fist saw the profile provider, I would have thought that a new cyclic timer was created with each consumer instance. The way it does work skips duplicating some overheads... [...]> The time differential, when testing this with the dtrace script, is > sometimes as great as a half a second, although this varies. > Interestingly though, it doesn''t vary on one run, but on different > runs. In other words, when I start the three scripts, a rhythm is > established, and it pretty much stays the same for that run. If I stop > all of the scripts and restart them, I get a little different rhythm > pattern, but it stays the same for the whole run.Great - that does sound like /usr/sbin/dtrace switchrate rhythms.. no worries, Brendan
Hi Brendan, I had read how increasing the switch rate reduces the likelihood of buffer overflow, but I guess I never thought about why: because the consumer empties the entire inactive buffer and then has to wait for the other one to become inactive. Thanks! Chip Brendan Gregg wrote:> G''Day Chip, > > On Sun, 30 Jul 2006, Chip Bennett wrote: > > >> When I run the following D script: >> >> profile:::tick-5sec >> { >> } >> >> simultaneously from three different windows, too my surprise, the trace >> output _doesn''t_ seem to appear in each window at the same time. Since >> there is only one probe, and the CPU utilization (it''s a one CPU system) >> is less than 1%, I would have thought that the difference in time >> between the display in each window would have been imperceptible. >> > > The /usr/sbin/dtrace consumer by default reads the kernel buffer at 1 > Hertz, and does so relative to when the process began running. I would > imagine that while your probes are firing at the same time, the userland > consumer is dumping the output offset to when they began running. I''d test > it further using, > > # dtrace -x switchrate=10 -n ''BEGIN,tick-5sec { trace(timestamp); }'' > > To both bump up the switchrate of /usr/sbin/dtrace to 10 Hertz, and to see > some numerical timestamps for comparison. > > That multiple DTrace consumers multiplex onto single instances of profile > probes is interesting. When I fist saw the profile provider, I would have > thought that a new cyclic timer was created with each consumer instance. > The way it does work skips duplicating some overheads... > > [...] > >> The time differential, when testing this with the dtrace script, is >> sometimes as great as a half a second, although this varies. >> Interestingly though, it doesn''t vary on one run, but on different >> runs. In other words, when I start the three scripts, a rhythm is >> established, and it pretty much stays the same for that run. If I stop >> all of the scripts and restart them, I get a little different rhythm >> pattern, but it stays the same for the whole run. >> > > Great - that does sound like /usr/sbin/dtrace switchrate rhythms.. > > no worries, > > Brendan > >