dtrace discuss - Jul 2009 - getting extra characters with printf(copyin(a, b))

Hi, 

I have a situation where a DTrace script is printing out extra characters,
despite the copyin() call giving a specific length.  Can anyone think of why
this might be?  It''s fine the first time all of the probes fire, but on
a second run of my generating operations, I get junk in there.  For example:

set setop length 5, FOUND KEY, STORED
set setop length 5, FOUND KEY, STORED
get setop, FOUND KEY
get nothere, NOT FOUND
add addop, NOT FOUND
add addop, NOT FOUND
set replaceop length 9, FOUND KEY, STORED
replace replaceop, FOUND KEY
set anumber length 7, FOUND KEY, STORED
incr anumber, FOUND KEY, 101
decr anumber, FOUND KEY, 100

set setopceoreplaceop length 5, FOUND KEY, STORED
set setop length 5, FOUND KEY, STORED
get setop, FOUND KEY
get nothere, NOT FOUND
add addop, NOT FOUND
add addop, NOT FOUND
set replaceopnumber length 9, FOUND KEY, STORED
replace replaceop, FOUND KEY
set anumber length 7, FOUND KEY, STORED
incr anumber, FOUND KEY, 101
decr anumber, FOUND KEY, 100

I should see exactly the same output, but for some reason... even though the
length is 5 on that first set the second time through, I get far more than 5
characters.  If I stop and restart the DTrace script, I get good output the
first time.  This is on OpenSolaris 2009.06.

This is quite easy to reproduce.

The script is the following, where arg1 is not a string but a pointer to the key
from the command and arg2 is the length of that key.

memcached*::command-get
/ (signed int) arg3 != -1 /
{
  printf("get %s, FOUND KEY\n", stringof(copyin(arg1, arg2)));
}

memcached*::command-get
/ (signed int) arg3 == -1 /
{
  printf("get %s, NOT FOUND\n", stringof(copyin(arg1, arg2)));
}


memcached*::command-add
/ (signed int) arg3 != -1 /
{
  printf("add %s, FOUND KEY\n", stringof(copyin(arg1, arg2)));
}

memcached*::command-add
/ (signed int) arg3 == -1 /
{
  printf("add %s, NOT FOUND\n", stringof(copyin(arg1, arg2)));
}

memcached*::command-replace
/ (signed int) arg3 != -1 /
{ 
  printf("replace %s, FOUND KEY\n", stringof(copyin(arg1, arg2)));
}

memcached*::command-replace 
/ (signed int) arg3 == -1 /
{ 
  printf("replace %s, NOT FOUND\n", stringof(copyin(arg1, arg2)));
}

memcached*::command-set
/ (signed int) arg3 != -1 /
{ 
  printf("set %s length %d, FOUND KEY, STORED\n", 
          stringof(copyin(arg1, arg2)), arg2);
}

memcached*::command-set
/ (signed int) arg3 == -1 /
{ 
  printf("set %s, NOT FOUND, STORED\n", stringof(copyin(arg1, arg2)));
}

memcached*::command-incr
{
  printf("incr %s, FOUND KEY, %d\n", stringof(copyin(arg1, arg2)),
arg3);
}

memcached*::command-decr
{ 
  printf("decr %s, FOUND KEY, %d\n", stringof(copyin(arg1, arg2)),
arg3);
}


Thanks in advance!

- Matt
-- 
This message posted from opensolaris.org

On Fri, Jul 24, 2009 at 4:50 PM, Matt Ingenthron<mingenthron at acm.org>
wrote:
> Hi,
>
> I have a situation where a DTrace script is printing out extra characters,
despite the copyin() call giving a specific length. ?Can anyone think of why
this might be?
[ ... ]
>
> memcached*::command-get
> / (signed int) arg3 != -1 /
> {
> ?printf("get %s, FOUND KEY\n", stringof(copyin(arg1, arg2)));
> }
It doesn''t look like you''re copying in a null character, which
seems
likely if arg2 == 5 for "setopt".  You''re doing the copyin()
the
second time around to a buffer that''s not been zeroed, and stringof()
is just looking for the first null character it finds in that buffer.
It finds it after the original (if longer) string.

Chad

Thanks again for the help Chad,
> >
> > memcached*::command-get
> > / (signed int) arg3 != -1 /
> > {
> > ?printf("get %s, FOUND KEY\n",
> stringof(copyin(arg1, arg2)));
> > }
> 
> It doesn''t look like you''re copying in a null
> character, which seems
> likely if arg2 == 5 for "setopt".  You''re doing the
> copyin() the
> second time around to a buffer that''s not been
> zeroed, and stringof()
> is just looking for the first null character it finds
> in that buffer.
> It finds it after the original (if longer) string.

I guess I''d assumed that the %s would have been treated as a clause
local variable, but it appears that''s not the case.  From what
you''re saying, it appears it''s a global which I can''t
really reference in the way I''d used it?  That''s rather
confusing... but I can deal with it.

Looking at some other examples of similar situations, it appears the best thing
to do is create a clause local, then call stringof() on it when doing the
printf, then zeroing it out before the next call.  Does that sound like the
right approach?

Thanks again,

- Matt
-- 
This message posted from opensolaris.org

On Sun, Jul 26, 2009 at 3:35 PM, Matt Ingenthron<mingenthron at acm.org>
wrote:
> Thanks again for the help Chad,
>
>> >
>> > memcached*::command-get
>> > / (signed int) arg3 != -1 /
>> > {
>> > ?printf("get %s, FOUND KEY\n",
>> stringof(copyin(arg1, arg2)));
>> > }
>>
>> It doesn''t look like you''re copying in a null
>> character, which seems
>> likely if arg2 == 5 for "setopt". ?You''re doing the
>> copyin() the
>> second time around to a buffer that''s not been
>> zeroed, and stringof()
>> is just looking for the first null character it finds
>> in that buffer.
>> It finds it after the original (if longer) string.
>
>
> I guess I''d assumed that the %s would have been treated as a
clause local variable, but it appears that''s not the case. ?From what
you''re saying, it appears it''s a global which I can''t
really reference in the way I''d used it? ?That''s rather
confusing... but I can deal with it.
It''s actually the copyin() more than the %s that''s at play
here.  The
target memory for copyin() is scratch space.  Unused space (if any) in
the principal buffer is used for scratch space.  It''s not global,
it''s
per-cpu, but it''s not zeroed after use, so you can''t make any
assumptions about what''s there.
>
> Looking at some other examples of similar situations, it appears the best
thing to do is create a clause local, then call stringof() on it when doing the
printf, then zeroing it out before the next call. ?Does that sound like the
right approach?
If the memory pointed to by arg1 is a null-terminated string, you
could just do this:

printf("%s\n", copyinstr(arg1));

If not, then something like this should work:

        this->foo = (char *)alloca(arg2 + 1);
        copyinto(arg1, arg2, this->foo);
        this->foo[arg2 + 1] = ''\0'';
        printf("%s\n", stringof(this->foo));

Chad

> 
> If the memory pointed to by arg1 is a null-terminated
> string, you
> could just do this:
> 
> printf("%s\n", copyinstr(arg1));
Unfortunately, it''s not.  I can probably modify the USDT provider to do
that, and perhaps I should since this would make the use of these probes much
easier.

> If not, then something like this should work:
> 
>         this->foo = (char *)alloca(arg2 + 1);
> copyinto(arg1, arg2, this->foo);
>         this->foo[arg2 + 1] = ''\0'';
> printf("%s\n", stringof(this->foo));

Makes sense.  Is there significant overhead for doing that alloca() every time
though?  Is there any benefit in doing it global or thread-local?  In my use
case, there will only be one ''command'' probe firing for each
thread at any given time, so I think I could do the alloca() at command start
and zero it out at command end with a thread local.  I don''t know if
there are any DTrace overhead benefits for this, but it may make for a more
readable script.

The problem is I won''t know the size until later.  I could just define
a maximum and be okay for this use case.

- Matt
-- 
This message posted from opensolaris.org

On Sun, Jul 26, 2009 at 6:16 PM, Matt Ingenthron<mingenthron at acm.org>
wrote:
>
>> If not, then something like this should work:
>>
>> ? ? ? ? this->foo = (char *)alloca(arg2 + 1);
>> copyinto(arg1, arg2, this->foo);
>> ? ? ? ? this->foo[arg2 + 1] = ''\0'';
>> printf("%s\n", stringof(this->foo));
>
>
> Makes sense. ?Is there significant overhead for doing that alloca() every
time though? ?Is there any benefit in doing it global or thread-local? ?In my
use case, there will only be one ''command'' probe firing for
each thread at any given time, so I think I could do the alloca() at command
start and zero it out at command end with a thread local. ?I don''t know
if there are any DTrace overhead benefits for this, but it may make for a more
readable script.
>
There''s actually no real difference performance-wise between the above
and the following:

        this->foo = (char *)copyin(arg1, arg2);
        this->foo[arg2 + 1] = ''\0'';
        printf("%s\n", stringof(this->foo));

Both the copyin() and the alloca() allocate space out of scratch
space, and in fact, they share the same code path to do so.  The only
performance penalty being paid here is in doing this as two separate
subroutine calls rather than a single one.  The alloca() is safer,
though, because it covers that edge case where the copyin() would use
the remaining scratch space, making this->foo[arg2 + 1] an illegal
address.

Also, the space allocated by alloca() is only valid within that
clause, so it has to be clause-local.

Chad

On Jul 26, 2009, at 2:09 PM, Chad Mynhier wrote:
> If the memory pointed to by arg1 is a null-terminated string, you
> could just do this:
>
> printf("%s\n", copyinstr(arg1));

Even without the terminating null, you can use copyinstr() with its  
optional
second argument that specifies the length of the string being copied  
in. For
example, calls to write(2) obviously don''t need to use null-terminated
strings so the following takes this into account:

syscall::write:entry
{
	trace(copyinstr(arg1, arg2));
}

Adam

--
Adam Leventhal, Fishworks                        http://blogs.sun.com/ahl

> 
> There''s actually no real difference performance-wise
> between the above
> and the following:
> 
>         this->foo = (char *)copyin(arg1, arg2);
> this->foo[arg2 + 1] = ''\0'';
>         printf("%s\n", stringof(this->foo));
> e copyin() and the alloca() allocate space out of
> scratch
> space, and in fact, they share the same code path to
> do so.  The only
> performance penalty being paid here is in doing this
> as two separate
> subroutine calls rather than a single one.  The
> alloca() is safer,
> though, because it covers that edge case where the
> copyin() would use
> the remaining scratch space, making this->foo[arg2 +
> 1] an illegal
> address.
Makes sense...
> Also, the space allocated by alloca() is only valid
> within that
> clause, so it has to be clause-local.
Ooops.  I should have caught then when I read up on alloca().  Thanks.

Since I have all of your help here (and thanks much!).... what is your thought
on changing the provider to give DTrace a string to work with?  That would move
the overhead for that processing to be in the code path for the process when the
probe is enabled I gather, and the payoff is easier to use/read DTrace
providers.  Is this a recommended thing to do?

 - Matt
-- 
This message posted from opensolaris.org

> On Jul 26, 2009, at 2:09 PM, Chad Mynhier wrote:
> > If the memory pointed to by arg1 is a
> null-terminated string, you
> > could just do this:
> >
> > printf("%s\n", copyinstr(arg1));
> 
> 
> Even without the terminating null, you can use
> copyinstr() with its  
> optional
> second argument that specifies the length of the
> string being copied  
> in. For
> example, calls to write(2) obviously don''t need to
> use null-terminated
> strings so the following takes this into account:
> 
> syscall::write:entry
> {
> 	trace(copyinstr(arg1, arg2));
> }
Oh, that''ll make things much simpler.  I figured that had to be a
common requirement.

Having said that, I have to say the "Dynamic Tracing Guide"
doesn''t list that as a possible subroutine signature on docs.sun.com. 
It is there on wikis.sun.com.  It must have been added later to either DTrace or
the docs.

In either event, I''m not going to dispute it''s existence when
it''s coming from you!  :)

Thanks,

- Matt
-- 
This message posted from opensolaris.org

> Having said that, I have to say the "Dynamic Tracing Guide"
doesn''t
> list that as a possible subroutine signature on docs.sun.com.  It is  
> there on wikis.sun.com.  It must have been added later to either  
> DTrace or the docs.

The wiki is now the definitive source of documentation. It has taken  
all the
content in the original Dynamic Tracing Guide and been extended for new
functionality and various corrections.

Adam

--
Adam Leventhal, Fishworks                        http://blogs.sun.com/ahl