As part of tracking down an elusive problem, I wrote a DTrace script to
monitor writes to stdout, which in my case is redirected to a file, so
that file offsets are meaningful.
The script is simple. It catches the first write to descriptor 1 and
sets a global variable to turn on the remaining two clauses. Those
clauses report write results and any other system calls that the target
process makes, Here it is, followed by the first part of its output
(reformatted for compactness).
----------------------------------------------------------------
syscall::write:entry
/pid == $target && arg0 == 1/
{
interesting = 1;
printf("writing 0x%x bytes to stdout at 0x%x\n",
arg2, fds[1].fi_offset);
}
syscall::write:return
/pid == $target && interesting == 1/
{
printf("wrote 0x%x bytes\n", arg0);
}
syscall:::entry
/pid == $target && interesting == 1/
{
}
----------------------------------------------------------------
CPU ID FUNCTION:NAME
0 1408 write:entry writing 0x100000 bytes to stdout at 0x0
0 1408 write:entry
0 1409 write:return wrote 0x100000 bytes
0 1408 write:entry writing 0x100000 bytes to stdout at 0x100000
0 1408 write:entry
0 1409 write:return wrote 0x100000 bytes
0 1408 write:entry writing 0x100000 bytes to stdout at 0x100000
0 1408 write:entry
0 1694 lwp_cond_wait:entry
0 1409 write:return wrote 0x100000 bytes
0 1408 write:entry writing 0x100000 bytes to stdout at 0x100000
0 1408 write:entry
0 1409 write:return wrote 0x100000 bytes
0 1408 write:entry writing 0x100000 bytes to stdout at 0x100000
0 1408 write:entry
0 1409 write:return wrote 0x100000 bytes
----------------------------------------------------------------
The target process does a sequence of writes to stdout, which the
output excerpt confirms. The offset reported for the writes starts at
0 and increases to by the write size to 0x100000. But then it sticks
at 0x100000 and no longer increases by the size of subsequent writes.
This is certainly not what I expected!
The program''s output in this case is correct, so the file offsets must
have actually increased as expected. So there must be something wrong
with my script. But what? Can anybody help?
-- Glenn Skinner
On Thu, Jan 29, 2009 at 01:48:05PM -0800, Glenn Skinner wrote:> syscall::write:entry > /pid == $target && arg0 == 1/ > { > interesting = 1; > printf("writing 0x%x bytes to stdout at 0x%x\n", > arg2, fds[1].fi_offset); > } > > syscall::write:return > /pid == $target && interesting == 1/ > { > printf("wrote 0x%x bytes\n", arg0); > } > > syscall:::entry > /pid == $target && interesting == 1/ > { > }The last probe does very little. And the second one catches write() returns other than the ones you want. Perhaps you meant something like: syscall::write:entry /pid == $target && arg0 == 1/ { self->interesting = 1; printf("writing 0x%x bytes to stdout at 0x%x\n", arg2, fds[1].fi_offset); } syscall::write:return /pid == $target && self->interesting == 1/ { printf("wrote 0x%x bytes\n", arg0); } Nico --
Date: Thu, 29 Jan 2009 16:05:44 -0600
From: Nicolas Williams <Nicolas.Williams at sun.com>
Subject: Re: [dtrace-discuss] file offset monitoring weirdness
On Thu, Jan 29, 2009 at 01:48:05PM -0800, Glenn Skinner wrote:
> syscall::write:entry
> /pid == $target && arg0 == 1/
> {
> interesting = 1;
> printf("writing 0x%x bytes to stdout at 0x%x\n",
> arg2, fds[1].fi_offset);
> }
>
> syscall::write:return
> /pid == $target && interesting == 1/
> {
> printf("wrote 0x%x bytes\n", arg0);
> }
>
> syscall:::entry
> /pid == $target && interesting == 1/
> {
> }
The last probe does very little. And the second one catches
write() returns other than the ones you want.
Understood. I originally wrote it as you suggest, but then wanted to
verify that no other threads were making calls that could affect the
write sequence (e.g., lseek). Hence the last probe. Changing from
self->interesting to interesting does indeed make the second probe
catch more than desired, but it''s easy enough to screen out false
positives.
Perhaps you meant something like:
syscall::write:entry
/pid == $target && arg0 == 1/
{
self->interesting = 1;
printf("writing 0x%x bytes to stdout at 0x%x\n",
arg2, fds[1].fi_offset);
}
syscall::write:return
/pid == $target && self->interesting == 1/
{
printf("wrote 0x%x bytes\n", arg0);
}
But the central mystery remains. Why aren''t the file offsets
increasing? Am I misusing the fds array in some way?
-- Glenn