dtrace discuss - Jul 2009 - printf() giving unsigned int, when it is signed

Hi,

I hope this is something simple, but I''ve looked at the docs and I just
can''t find anything that tells me what I''m doing wrong.

I have a USDT provider in memcached which is defined as either a positive value
returned or -1 if there is no result.  From my DTrace script, the value returned
seems to be 4294967295 when I''m expecting a -1 so it seems to be
treating it as unsigned.  The value is defined as an int in the USDT probe and
the program, and isainfo -b returns 64, though I am working with a 32-bit
binary.

I tried a couple of things to fix this.  First, I tried adding to the probe
definition "signed" in front of the int in the probe definition (in
memcached_dtrace.d as included in the source included from memcached.org):
-   probe command__get(int connid, const char *key, int keylen, int size,
int64_t casid);
+   probe command__get(int connid, const char *key, int keylen, signed int size,
int64_t casid);

This had no effect.

If I add a cast to the script, I get the expected behavior when the probe fires:

memcached*::command-*
{
  printf("key is %s, length is %d\n", copyinstr(arg1), (signed int)
arg3);
}

Why should this be necessary in this case?

Thanks in advance,

- Matt

p.s.: I did check with Trond (the author) already on this, and the only thing he
could think of is that the macro defining this in the source is confusing the
dtrace compiler.
-- 
This message posted from opensolaris.org

On Tue, Jul 21, 2009 at 2:52 AM, Matt Ingenthron<mingenthron at acm.org>
wrote:
>
> I have a USDT provider in memcached which is defined as either a positive
value returned or -1 if there is no result. ?From my DTrace script, the value
returned seems to be 4294967295 when I''m expecting a -1 so it seems to
be treating it as unsigned. ?The value is defined as an int in the USDT probe
and the program, and isainfo -b returns 64, though I am working with a 32-bit
binary.
[ ... ]
>
> If I add a cast to the script, I get the expected behavior when the probe
fires:
>
> memcached*::command-*
> {
> ?printf("key is %s, length is %d\n", copyinstr(arg1), (signed
int) arg3);
> }
>
> Why should this be necessary in this case?
The types for arg0, arg1, etc., are int64_t.  In your case, you''re
trying to print a negative 32-bit value, which is a positive 64-bit
value, thus the need for the cast.

Chad

Thanks Chad.
> The types for arg0, arg1, etc., are int64_t.  In your
> case, you''re
> trying to print a negative 32-bit value, which is a
> positive 64-bit
> value, thus the need for the cast.
The args are always int64_t?  Even if the probe definition clearly states what
the type is?  Or in my case, even if I cast it inside the probe definition?

I see that now in the documentation for Variables, but I guess I''d
never run into it before.  I''ve used the args many times, but generally
as strings.

Thanks, 

- Matt
-- 
This message posted from opensolaris.org

On Tue, Jul 21, 2009 at 07:25:58AM -0400, Chad Mynhier
wrote:
> On Tue, Jul 21, 2009 at 2:52 AM, Matt Ingenthron<mingenthron at
acm.org> wrote:
> >
> > I have a USDT provider in memcached which is defined as either a
positive value returned or -1 if there is no result. ?From my DTrace script, the
value returned seems to be 4294967295 when I''m expecting a -1 so it
seems to be treating it as unsigned. ?The value is defined as an int in the USDT
probe and the program, and isainfo -b returns 64, though I am working with a
32-bit binary.
> [ ... ]
> >
> > If I add a cast to the script, I get the expected behavior when the
probe fires:
> >
> > memcached*::command-*
> > {
> > ?printf("key is %s, length is %d\n", copyinstr(arg1),
(signed int) arg3);
> > }
> >
> > Why should this be necessary in this case?
> 
> The types for arg0, arg1, etc., are int64_t.  In your case, you''re
> trying to print a negative 32-bit value, which is a positive 64-bit
> value, thus the need for the cast.
To be more particular, in order to get the types from the provider, you must
use the args[] array, not the arg? variables.  Try doing:

	printf("key is %s, length is %d\n", copyinstr(arg1), args[3]);

Cheers,
- jonathan

> To be more particular, in order to get the types from
> the provider, you must
> use the args[] array, not the arg? variables.  Try
> doing:
> 
> printf("key is %s, length is %d\n", copyinstr(arg1),
> , args[3]);
The DTrace script doesn''t seem to be correct in that case.  I get the
following:

$ pfexec ./keysflowing.d 
dtrace: failed to compile script ./keysflowing.d: line 11: args[ ] may not be
referenced because probe description :memcached*::command-get matches an
unstable set of probes

     7	memcached*::command-get
     8	/ (signed int) arg3 != -1 /
     9	{
    10	  printf("get %s, FOUND KEY\n", copyinstr(arg1));
    11	  printf("another approach %d", args[3]);
    12	}

What does it take to make it stable?  :)  Here is the probe definition.

   188	   /**
   189	    * Fired for a get-command
   190	    * @param connid connection id
   191	    * @param key requested key
   192	    * @param keylen lenght of the key
   193	    * @param size size of the key''s data (or -1 if not found)
   194	    * @param casid the casid for the item
   195	    */
   196	   probe command__get(int connid, const char *key, int keylen, signed int
size, int64_t casid);

The original had just int, I added ''signed'' to arg3.

Thanks for the help!

- Matt
-- 
This message posted from opensolaris.org

On Tue, Jul 21, 2009 at 12:37 PM, Matt Ingenthron<mingenthron at acm.org>
wrote:
>> To be more particular, in order to get the types from
>> the provider, you must
>> use the args[] array, not the arg? variables. ?Try
>> doing:
>>
>> printf("key is %s, length is %d\n", copyinstr(arg1),
>> , args[3]);
>
> The DTrace script doesn''t seem to be correct in that case. ?I get
the following:
>
> $ pfexec ./keysflowing.d
> dtrace: failed to compile script ./keysflowing.d: line 11: args[ ] may not
be referenced because probe description :memcached*::command-get matches an
unstable set of probes
>
> ? ? 7 ?memcached*::command-get
> ? ? 8 ?/ (signed int) arg3 != -1 /
> ? ? 9 ?{
> ? ?10 ? ?printf("get %s, FOUND KEY\n", copyinstr(arg1));
> ? ?11 ? ?printf("another approach %d", args[3]);
> ? ?12 ?}
>
> What does it take to make it stable? ?:) ?Here is the probe definition.
>
You''re trying to use the args[] array with a USDT provider.  DTrace
doesn''t (yet) have the ability to pull type information out of
processes, so you don''t get the args[] array for anything but
kernel-based probes.  (The kernel contains CTF information that it
uses to map types to arguments.)

Chad

I have to deal with an environment where sudo is set up to enable access 
to specific
commands and since lockstat wasn''t listed as one of those commands, I 
thought I''d cheat a bit
and use lockstat -V -I -i 997 to generate a script to feed to DTrace 
(which can be used).

Out comes this code...

# /usr/sbin/lockstat -V -I -i 997 sleep 10
lockstat: vvvv D program vvvv
profile:::profile-997
{
    @avg[56ULL, (uintptr_t)curthread->t_cpu +
        curthread->t_cpu->cpu_profile_pil, (uintptr_t)arg0] = avg(arg2);
}

lockstat: ^^^^ D program ^^^^

This is most interesting as ''arg2'' is not documented in the
DTrace
user''s guide.
Examining S10 source code would imply this is the ''lateness''
of the
interrupt probe
firing. The source code makes it clear that this was chosen with malice 
aforethought
but doesn''t discuss why I would care about that if I''m doing
profiling...

The simplistic approach (IMHO) would have been to do a simple count();

Enlightenment, please?

# cat /etc/release
                       Solaris 10 10/08 s10x_u6wos_07b X86
           Copyright 2008 Sun Microsystems, Inc.  All Rights Reserved.
                        Use is subject to license terms.
                            Assembled 27 October 2008


Thanks,
Jim Litchfield

Most of this is now clear...

when avg() is used as an aggregating function, DTrace keeps the data as
a count and a running total. The average value is calculated when the
aggregation is presented to the user. That way only one expensive divide
is needed. lockstat can reach behind the scenes and pull out the number
of calls to avg() for each element and present that as the counts since
it deals with the raw aggregation data.

Whether the delay is interesting is another question....

Jim
---
James Litchfield wrote:
> I have to deal with an environment where sudo is set up to enable 
> access to specific
> commands and since lockstat wasn''t listed as one of those
commands, I
> thought I''d cheat a bit
> and use lockstat -V -I -i 997 to generate a script to feed to DTrace 
> (which can be used).
>
> Out comes this code...
>
> # /usr/sbin/lockstat -V -I -i 997 sleep 10
> lockstat: vvvv D program vvvv
> profile:::profile-997
> {
>    @avg[56ULL, (uintptr_t)curthread->t_cpu +
>        curthread->t_cpu->cpu_profile_pil, (uintptr_t)arg0] =
avg(arg2);
> }
>
> lockstat: ^^^^ D program ^^^^
>
> This is most interesting as ''arg2'' is not documented in
the DTrace
> user''s guide.
> Examining S10 source code would imply this is the
''lateness'' of the
> interrupt probe
> firing. The source code makes it clear that this was chosen with 
> malice aforethought
> but doesn''t discuss why I would care about that if I''m
doing profiling...
>
> The simplistic approach (IMHO) would have been to do a simple count();
>
> Enlightenment, please?
>
> # cat /etc/release
>                       Solaris 10 10/08 s10x_u6wos_07b X86
>           Copyright 2008 Sun Microsystems, Inc.  All Rights Reserved.
>                        Use is subject to license terms.
>                            Assembled 27 October 2008
>
>
> Thanks,
> Jim Litchfield
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
>