S Richardson
2007-Nov-16 22:58 UTC
[dtrace-discuss] DTrace syscall::write and buffer size mismatch
SunOS griffin 5.10 Generic_118833-17 sun4u sparc SUNW,Netra-T4
I''ve attached a script that attempts to capture the fd, size, and
buffer contents for the write() system call.
I also capture the return code (i.e. number of bytes read) and the
errno value (which should be 0, if healthy).
Most of the output looks to be as expected, but some writes show
buffer contents that is noticeably smaller than
the passed in size value.
Below is some good and bad DTrace output and a copy of the DTrace
script.
Any clue as to what I''m doing wrong would be much appreciated. DTrace
rocks!
Thanks
---------------------------------------
First, some good output where size matches the size of the buffer
contents:
2007 Nov 16 20:15:36: FmMain(PID:1004) called write(rc=1, errno=0)
with fd=8, size=1, and
buf="-"
2007 Nov 16 20:15:36: FmMain(PID:1004) called write(rc=81, errno=0)
with fd=7, size=81, and
buf="ALWAYS:2007/11/16 20:15:36.880351 FmMain.cpp:189(fm:1) ifconfig
down iad-logical
"
---------------------------------------
Now, some bad output where the buffer contents is smalle
r than the returned size by write(),
or where the end of the buffer looks messed up (e.g. no trailing
double-quote delimiter):
2007 Nov 16 20:15:36: init(PID:1004) called write(rc=372, errno=0)
with fd=4, size=372, and
buf="su"
2007 Nov 16 20:15:36: ifconfig(PID:1011) called write(rc=10, errno=0)
with fd=2, size=10, and
buf="ifconfig: lV?
2007 Nov 16 20:15:38: gzip(PID:1023) called write(rc=1683, errno=0)
with fd=3, size=1683, and
buf!:>G"
2007 Nov 16 20:15:38: gzip(PID:1029) called write(rc=5146, errno=0)
with fd=3, size=5146, and
buf?;>G"
2007 Nov 16 20:15:44: ifconfig(PID:1053) called write(rc=1235,
errno=0) with fd=1, size=1235, and
buf="lo0:
flags=2001000849<UP,LOOPBACK,RUNNING,MULTICAST,IPv4,VIRTUAL>
mtu 8232 index 1
inet 127.0.0.1 netmask ff000000
eri0: flags=1000843<UP,BROADCAST,RUNNING,MULTICAST,IPv4> mtu 1500
index 2
inet 10.160.139.74 netmask ffffff00 broadcast 10.160.139.255
et"
----------------------------------------------
#!/usr/sbin/dtrace -qs
#pragma D option quiet
/* Traces all write system calls executed by $1 input argument. */
/* INPUTS: $1 is the name of the process to trace
*/
BEGIN /* The BEGIN probe fires once when tracing starts */
{
printf("%Y: %s BEGIN\n", walltimestamp, $0);
}
syscall::write:entry
/pid != $pid && (execname == $$1 || ($$1 == "" &&
execname !"dtrace"))/
{
self->desc = arg0; /* file descriptor passed to write() */
self->bufp = arg1; /* buffer pointer passed to write() */
self->size = arg2; /* size, in bytes passed to write() */
}
syscall::write:return
/pid != $pid && (execname == $$1 || ($$1 == "" &&
execname !"dtrace"))/
{
printf("%Y: ", walltimestamp);
printf("%s(PID:%d) called %s(rc=%d, errno=%d) with fd=%d, size%d,
and \nbuf=\"%s\"\n\n",
execname, pid, probefunc, arg0, errno, self->desc,
self->size, stringof(copyin(self->bufp, self->size)));
self->desc = 0;
self->bufp = 0;
self->size = 0;
}
END /* The END probe fires once when tracing is completed */
{
printf("%Y: %s END\n", walltimestamp, $0);
}
--
This message posted from opensolaris.org
Chip Bennett
2007-Nov-17 02:33 UTC
[dtrace-discuss] DTrace syscall::write and buffer size mismatch
Each probe clause''s output length has to be pinned down at D compile time to a fixed value, so that every time the probe clause is executed it passes the same length record to the switch buffer. Your write buffer varies in length, so we need to pin down when that would get fixed. The copyin function is allowed to generate a scratch buffer of any length based on the length value. The stringof operator doesn''t actually copy the string (I don''t think), but just casts the char * pointer to be treated like a D string. However, once the output of this expression appeared in a printf, D has to pick a fixed length. The default length of strings in D is 256, so I''d guess that D is going to limit the output from the copyin function to 256 characters. (I know it doesn''t limit that whole printf to 256 characters because I''ve done some experiments to prove that wrong. I''m pretty sure that the kernel resident clause passes all of the printf arguments to the switch buffer, and the userland D command does the printf formatting.) One more thing: once you cast the the scratch buffer from copyin into a string, and printed it using %s, you said "Stop printing at the first \0 character", just like C. strsize is a compile time option that can be used to change the default string size. (Assuming I''m right that D is using that to determine the expression size for the printf.) You can change it with a pragma or a command line option (see the manual). However, if you specify really large sizes, you''re going to fill up the switch buffer really fast. Chip S Richardson wrote:> SunOS griffin 5.10 Generic_118833-17 sun4u sparc SUNW,Netra-T4 > > I''ve attached a script that attempts to capture the fd, size, and > buffer contents for the write() system call. > I also capture the return code (i.e. number of bytes read) and the > errno value (which should be 0, if healthy). > > Most of the output looks to be as expected, but some writes show > buffer contents that is noticeably smaller than > the passed in size value. > > Below is some good and bad DTrace output and a copy of the DTrace > script. > > Any clue as to what I''m doing wrong would be much appreciated. DTrace > rocks! > > Thanks > > --------------------------------------- > First, some good output where size matches the size of the buffer > contents: > > 2007 Nov 16 20:15:36: FmMain(PID:1004) called write(rc=1, errno=0) > with fd=8, size=1, and > buf="-" > > 2007 Nov 16 20:15:36: FmMain(PID:1004) called write(rc=81, errno=0) > with fd=7, size=81, and > buf="ALWAYS:2007/11/16 20:15:36.880351 FmMain.cpp:189(fm:1) ifconfig > down iad-logical > " > > --------------------------------------- > Now, some bad output where the buffer contents is smalle > r than the returned size by write(), > or where the end of the buffer looks messed up (e.g. no trailing > double-quote delimiter): > > 2007 Nov 16 20:15:36: init(PID:1004) called write(rc=372, errno=0) > with fd=4, size=372, and > buf="su" > > 2007 Nov 16 20:15:36: ifconfig(PID:1011) called write(rc=10, errno=0) > with fd=2, size=10, and > buf="ifconfig: lV? > > 2007 Nov 16 20:15:38: gzip(PID:1023) called write(rc=1683, errno=0) > with fd=3, size=1683, and > buf!:>G" > > 2007 Nov 16 20:15:38: gzip(PID:1029) called write(rc=5146, errno=0) > with fd=3, size=5146, and > buf?;>G" > > 2007 Nov 16 20:15:44: ifconfig(PID:1053) called write(rc=1235, > errno=0) with fd=1, size=1235, and > buf="lo0: flags=2001000849<UP,LOOPBACK,RUNNING,MULTICAST,IPv4,VIRTUAL> > mtu 8232 index 1 > inet 127.0.0.1 netmask ff000000 > eri0: flags=1000843<UP,BROADCAST,RUNNING,MULTICAST,IPv4> mtu 1500 > index 2 > inet 10.160.139.74 netmask ffffff00 broadcast 10.160.139.255 > et" > > ---------------------------------------------- > #!/usr/sbin/dtrace -qs > #pragma D option quiet > > /* Traces all write system calls executed by $1 input argument. */ > /* INPUTS: $1 is the name of the process to trace > */ > > BEGIN /* The BEGIN probe fires once when tracing starts */ > { > printf("%Y: %s BEGIN\n", walltimestamp, $0); > > } > > syscall::write:entry > /pid != $pid && (execname == $$1 || ($$1 == "" && execname !> "dtrace"))/ > { > self->desc = arg0; /* file descriptor passed to write() */ > self->bufp = arg1; /* buffer pointer passed to write() */ > self->size = arg2; /* size, in bytes passed to write() */ > > } > > syscall::write:return > /pid != $pid && (execname == $$1 || ($$1 == "" && execname !> "dtrace"))/ > { > printf("%Y: ", walltimestamp); > > printf("%s(PID:%d) called %s(rc=%d, errno=%d) with fd=%d, size> %d, and \nbuf=\"%s\"\n\n", > execname, pid, probefunc, arg0, errno, self->desc, > self->size, stringof(copyin(self->bufp, self->size))); > > self->desc = 0; > self->bufp = 0; > self->size = 0; > > } > > END /* The END probe fires once when tracing is completed */ > { > printf("%Y: %s END\n", walltimestamp, $0); > } > > > -- > This message posted from opensolaris.org > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org