dtrace discuss - Aug 2005 - How to trace results from clock_gettime?

I am trying to trace the results from the clock_gettime function.
At first I tried dereferencing the pointer in arg1, but got the old
invalid address message, so I started doing copyin calls, but I am
gettin bogus numbers.  Any ideas?

Here is what I ahve now:

pid7231::clock_gettime:entry
{
         self->cgtarg1 = arg1;
}

pid7231::clock_gettime:return
/self->cgtarg1/
{
         this->tspec = (timespec_t *)copyin(self->cgtarg1,sizeof(struct 
timespec));
         printf(" %ld
%ld",this->tspec->tv_sec,this->tspec->tv_nsec);
         self->cgtarg1 = 0;
}

This compiles, but it is printing out the wrong numbers. What am
I doing wrong?

-- 
blu

Remember when SOX compliant meant they were both the same color?
----------------------------------------------------------------------
Brian Utterback - OP/N1 RPE, Sun Microsystems, Inc.
Ph:877-259-7345, Em:brian.utterback-at-ess-you-enn-dot-kom

On Thu, Aug 11, 2005 at 01:43:51PM -0400, Brian Utterback
wrote:
> I am trying to trace the results from the clock_gettime function.
> At first I tried dereferencing the pointer in arg1, but got the old
> invalid address message, so I started doing copyin calls, but I am
> gettin bogus numbers.  Any ideas?
> 
> Here is what I ahve now:
> 
> pid7231::clock_gettime:entry
> {
>         self->cgtarg1 = arg1;
> }
> 
> pid7231::clock_gettime:return
> /self->cgtarg1/
> {
>         this->tspec = (timespec_t
*)copyin(self->cgtarg1,sizeof(struct
> timespec));
>         printf(" %ld
%ld",this->tspec->tv_sec,this->tspec->tv_nsec);
>         self->cgtarg1 = 0;
> }
> 
> This compiles, but it is printing out the wrong numbers. What am
> I doing wrong?
Is this is a 32-bit process on a 64-bit kernel?  If so, that needs
to be a timespec32_t...  (You can look at curpsinfo->pr_dmodel and compare
that to PR_MODEL_ILP32 and PR_MODEL_LP64 to determine if it''s a 32-bit
or 64-bit process, respectively.)

	- Bryan

--------------------------------------------------------------------------
Bryan Cantrill, Solaris Kernel Development.       http://blogs.sun.com/bmc

P.S.  May this response beat Jonathan''s...

Bryan Cantrill wrote:
>>This compiles, but it is printing out the wrong numbers. What am
>>I doing wrong?
> 
> 
> Is this is a 32-bit process on a 64-bit kernel?  If so, that needs
> to be a timespec32_t...  (You can look at curpsinfo->pr_dmodel and
compare
> that to PR_MODEL_ILP32 and PR_MODEL_LP64 to determine if it''s a
32-bit
> or 64-bit process, respectively.)
That was it, sort of. I switched to using timespec32_t and now I get
the correct output, but I have something weird going on.

I wrote a program that does clock_gettime in a loop to test the D
script, and now on each loop, the D script prints out the value
of the loop before.

In my actual program that I am diagnosing, I get a valid looking
number only every third call to clock_gettime. The other two times
I get zeros or garbage.

I suspect that on each time through, I am getting the values at exit
of the values in the timespec struct upon entry, but I don''t know
why or what to do about it.

Here is the script and the D script:

#include <stdio.h>
#include <time.h>
#include <stdlib.h>
int
main(int argc, char **argv) {
     struct timespec tp;
     int res;
     char buf[1024];
     while (1) {
         gets(buf);
         res = clock_gettime(CLOCK_REALTIME,&tp);
         if (res < 0) {
	     perror("clock_gettime");
	     exit(1);
         }
         printf("%ld %ld\n",tp.tv_sec,tp.tv_nsec);
    }
}


#!/usr/sbin/dtrace -s

#pragma D option flowindent

pid7765::clock_gettime:entry
{
         self->cgtarg1 = arg1;
}

pid7765::clock_gettime:return
/self->cgtarg1/
{
         this->tspec = (timespec32_t 
*)copyin(self->cgtarg1,sizeof(struct timespec32));
         printf(" %d
%d",this->tspec->tv_sec,this->tspec->tv_nsec);
         self->cgtarg1 = 0;
}


-- 
blu

Remember when SOX compliant meant they were both the same color?
----------------------------------------------------------------------
Brian Utterback - OP/N1 RPE, Sun Microsystems, Inc.
Ph:877-259-7345, Em:brian.utterback-at-ess-you-enn-dot-kom

Looks like the old tail-call strikes again.
I believe in this case the return probe is hit just before the call is made. 
It explains some of what you see.

disassembly for /usr/lib/librt.so

section	.text
clock_gettime()
    clock_gettime:          82 10 00 0f  mov          %o7, %g1
    clock_gettime+0x4:      40 00 4e fb  call         
    clock_gettime+0x8:      9e 10 00 01  mov          %g1, %o7



Brian Utterback writes:
 > Bryan Cantrill wrote:
 > 
 > >>This compiles, but it is printing out the wrong numbers. What am
 > >>I doing wrong?
 > > 
 > > 
 > > Is this is a 32-bit process on a 64-bit kernel?  If so, that needs
 > > to be a timespec32_t...  (You can look at curpsinfo->pr_dmodel and
compare
 > > that to PR_MODEL_ILP32 and PR_MODEL_LP64 to determine if
it''s a 32-bit
 > > or 64-bit process, respectively.)
 > 
 > That was it, sort of. I switched to using timespec32_t and now I get
 > the correct output, but I have something weird going on.
 > 
 > I wrote a program that does clock_gettime in a loop to test the D
 > script, and now on each loop, the D script prints out the value
 > of the loop before.
 > 
 > In my actual program that I am diagnosing, I get a valid looking
 > number only every third call to clock_gettime. The other two times
 > I get zeros or garbage.
 > 
 > I suspect that on each time through, I am getting the values at exit
 > of the values in the timespec struct upon entry, but I don''t know
 > why or what to do about it.
 > 
 > Here is the script and the D script:
 > 
 > #include <stdio.h>
 > #include <time.h>
 > #include <stdlib.h>
 > int
 > main(int argc, char **argv) {
 >      struct timespec tp;
 >      int res;
 >      char buf[1024];
 >      while (1) {
 >          gets(buf);
 >          res = clock_gettime(CLOCK_REALTIME,&tp);
 >          if (res < 0) {
 > 	     perror("clock_gettime");
 > 	     exit(1);
 >          }
 >          printf("%ld %ld\n",tp.tv_sec,tp.tv_nsec);
 >     }
 > }
 > 
 > 
 > #!/usr/sbin/dtrace -s
 > 
 > #pragma D option flowindent
 > 
 > pid7765::clock_gettime:entry
 > {
 >          self->cgtarg1 = arg1;
 > }
 > 
 > pid7765::clock_gettime:return
 > /self->cgtarg1/
 > {
 >          this->tspec = (timespec32_t 
 > *)copyin(self->cgtarg1,sizeof(struct timespec32));
 >          printf(" %d
%d",this->tspec->tv_sec,this->tspec->tv_nsec);
 >          self->cgtarg1 = 0;
 > }
 > 
 > 
 > -- 
 > blu
 > 
 > Remember when SOX compliant meant they were both the same color?
 > ----------------------------------------------------------------------
 > Brian Utterback - OP/N1 RPE, Sun Microsystems, Inc.
 > Ph:877-259-7345, Em:brian.utterback-at-ess-you-enn-dot-kom
 > _______________________________________________
 > dtrace-discuss mailing list
 > dtrace-discuss at opensolaris.org