dtrace discuss - Jan 2007 - ustack() wrong in pid return probes?

I have a test program which has a call sequence of
a(), b(), c(), d().

	When I place a pid return probe on d(), I get a ustack that
looks like this:

               a.out`d+0x19
               a.out`b+0xd
               a.out`a+0xd
               a.out`main+0x3c
               a.out`_start+0x7a

	The c() method appears to be missing.

	I did some poking around and noticed that pid return probes
fire after the instruction being instrumented has executed.

	It seems to me that after a "ret", we''re actually in
method c() now, not d(). However, there is this comment and code
in fasttrap_isa.c :

/*
  * Set the program counter to the address of the traced
  * instruction so that it looks right in ustack()
  * output. We had previously set it to the end of the
  * instruction to simplify %rip-relative addressing.
  */
rp->r_pc = pc;

	Is this correct? It seems like the correct ustack()
output would be if the pc was set to "new_pc". Does that break
invariants elsewhere in the code?

	I''ve included a ustackTest.c & ustack.d that demonstrates
what I''m seeing.

	James M

--------------------- ustackTest.c --------------------------

#include <stdio.h>
#include <unistd.h>

void d(int arg) {
         printf("Got arg of %d\n", arg);
}

void c(int arg) {
         d(arg+1);
}

void b(int arg) {
         c(arg+1);
}

void a(int arg) {
         b(arg+1);
}

int main(void)
{
   int value = 0;

   printf("PID is %u\n", getpid());

   while(1) {
     a(value++);
     sleep(1);
   }
}

------------------------- ustack.d -----------------------

pid$target::d:entry
{
         printf("entry stack...\n");
         ustack();
}

pid$target::d:return
{
         printf("return stack...\n");
         ustack();
}

In a return probe, a user might reasonably expect one of several results
from the ustack() action:

  1) the full call chain (a->b->c->d)
  2) the state of the stack after returning from the function (a->b->c)
  3) the result of naively walking the stack (a->b->d)

(2) seems confusing since the function associated with the probe
wouldn''t
be present in the output. While (1) would be ideal, we implement (3) because
we can''t, in the general case, determine if we''re in leaf
context or not
(that is, if we''re in a part of the function where a stack frame has
been
pushed).

Entry probes for the pid provider produce (1) because we implement a hack in
which the pid provider adds a hint to the ustack code that we''re in
leaf
context. We could easily do the same for return probes which would solve
this problem in that case, but the result for offset probes will vary
(compare the output of ustack() in pid123::main:entry and pid123:::main:0)

Feel free to file an RFE if you think return probes should use the same
hack as entry probes.

Adam

On Sat, Jan 20, 2007 at 06:32:12PM -0800, James McIlree
wrote:
> 	I have a test program which has a call sequence of
> a(), b(), c(), d().
> 
> 	When I place a pid return probe on d(), I get a ustack that
> looks like this:
> 
>               a.out`d+0x19
>               a.out`b+0xd
>               a.out`a+0xd
>               a.out`main+0x3c
>               a.out`_start+0x7a
> 
> 	The c() method appears to be missing.
> 
> 	I did some poking around and noticed that pid return probes
> fire after the instruction being instrumented has executed.
> 
> 	It seems to me that after a "ret", we''re actually in
> method c() now, not d(). However, there is this comment and code
> in fasttrap_isa.c :
> 
> /*
>  * Set the program counter to the address of the traced
>  * instruction so that it looks right in ustack()
>  * output. We had previously set it to the end of the
>  * instruction to simplify %rip-relative addressing.
>  */
> rp->r_pc = pc;
> 
> 	Is this correct? It seems like the correct ustack()
> output would be if the pc was set to "new_pc". Does that break
> invariants elsewhere in the code?
> 
> 	I''ve included a ustackTest.c & ustack.d that demonstrates
> what I''m seeing.
> 
> 	James M
> 
> --------------------- ustackTest.c --------------------------
> 
> #include <stdio.h>
> #include <unistd.h>
> 
> void d(int arg) {
>         printf("Got arg of %d\n", arg);
> }
> 
> void c(int arg) {
>         d(arg+1);
> }
> 
> void b(int arg) {
>         c(arg+1);
> }
> 
> void a(int arg) {
>         b(arg+1);
> }
> 
> int main(void)
> {
>   int value = 0;
> 
>   printf("PID is %u\n", getpid());
> 
>   while(1) {
>     a(value++);
>     sleep(1);
>   }
> }
> 
> ------------------------- ustack.d -----------------------
> 
> pid$target::d:entry
> {
>         printf("entry stack...\n");
>         ustack();
> }
> 
> pid$target::d:return
> {
>         printf("return stack...\n");
>         ustack();
> }
> 
> 
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl

I looked at trying to implement the same style of hack for return
probes, but it seems like it may grow a bit more involved. There is no
way to find the pc for "c()" unless it is squirreled away somewhere
other than the stack. If it''s a "ret" instruction, you could
hope that
the
data just below $sp was still valid, but if the return probe is firing  
because
of another control flow mechanism, there may not be any data to
fetch.

	In my mind, a->b->c is a more understandable than a->b->d.
The former is incomplete, the latter is actually wrong.

	Especially when I was first investigating this, I had several
"but you just can''t get to D from B!" moments.

	I''ll file a RFE :-).

	James M

On Jan 20, 2007, at 6:49 PM, Adam Leventhal wrote:
> In a return probe, a user might reasonably expect one of several  
> results
> from the ustack() action:
>
>   1) the full call chain (a->b->c->d)
>   2) the state of the stack after returning from the function (a->b- 
> >c)
>   3) the result of naively walking the stack (a->b->d)
>
> (2) seems confusing since the function associated with the probe  
> wouldn''t
> be present in the output. While (1) would be ideal, we implement (3)  
> because
> we can''t, in the general case, determine if we''re in leaf
context or
> not
> (that is, if we''re in a part of the function where a stack frame
has
> been
> pushed).
>
> Entry probes for the pid provider produce (1) because we implement a  
> hack in
> which the pid provider adds a hint to the ustack code that we''re
in
> leaf
> context. We could easily do the same for return probes which would  
> solve
> this problem in that case, but the result for offset probes will vary
> (compare the output of ustack() in pid123::main:entry and  
> pid123:::main:0)
>
> Feel free to file an RFE if you think return probes should use the  
> same
> hack as entry probes.
>
> Adam
>
> On Sat, Jan 20, 2007 at 06:32:12PM -0800, James McIlree wrote:
>> 	I have a test program which has a call sequence of
>> a(), b(), c(), d().
>>
>> 	When I place a pid return probe on d(), I get a ustack that
>> looks like this:
>>
>>               a.out`d+0x19
>>               a.out`b+0xd
>>               a.out`a+0xd
>>               a.out`main+0x3c
>>               a.out`_start+0x7a
>>
>> 	The c() method appears to be missing.
>>
>> 	I did some poking around and noticed that pid return probes
>> fire after the instruction being instrumented has executed.
>>
>> 	It seems to me that after a "ret", we''re actually
in
>> method c() now, not d(). However, there is this comment and code
>> in fasttrap_isa.c :
>>
>> /*
>>  * Set the program counter to the address of the traced
>>  * instruction so that it looks right in ustack()
>>  * output. We had previously set it to the end of the
>>  * instruction to simplify %rip-relative addressing.
>>  */
>> rp->r_pc = pc;
>>
>> 	Is this correct? It seems like the correct ustack()
>> output would be if the pc was set to "new_pc". Does that
break
>> invariants elsewhere in the code?
>>
>> 	I''ve included a ustackTest.c & ustack.d that demonstrates
>> what I''m seeing.
>>
>> 	James M
>>
>> --------------------- ustackTest.c --------------------------
>>
>> #include <stdio.h>
>> #include <unistd.h>
>>
>> void d(int arg) {
>>         printf("Got arg of %d\n", arg);
>> }
>>
>> void c(int arg) {
>>         d(arg+1);
>> }
>>
>> void b(int arg) {
>>         c(arg+1);
>> }
>>
>> void a(int arg) {
>>         b(arg+1);
>> }
>>
>> int main(void)
>> {
>>   int value = 0;
>>
>>   printf("PID is %u\n", getpid());
>>
>>   while(1) {
>>     a(value++);
>>     sleep(1);
>>   }
>> }
>>
>> ------------------------- ustack.d -----------------------
>>
>> pid$target::d:entry
>> {
>>         printf("entry stack...\n");
>>         ustack();
>> }
>>
>> pid$target::d:return
>> {
>>         printf("return stack...\n");
>>         ustack();
>> }
>>
>>
>> _______________________________________________
>> dtrace-discuss mailing list
>> dtrace-discuss at opensolaris.org
>
> -- 
> Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl

You''re right that it''s going to be tricky to discover the
location of the
return address once the stack frame has already been popped. I''m really
not
a fan of having ustack() reflect the state of the system ostensibly after
the probe has fired. To me, that''s a very confusing metaphor. I may
assume
incorrectly, that people are knowledgeable of leaf contexts and would
make the leap that there''s actually an intervening function call. You
can end up in a similar situation in the presence of tail-calls -- and
there''s no way to account for that.

Adam

On Sat, Jan 20, 2007 at 07:31:03PM -0800, James McIlree
wrote:
> 
> 	I looked at trying to implement the same style of hack for return
> probes, but it seems like it may grow a bit more involved. There is no
> way to find the pc for "c()" unless it is squirreled away
somewhere
> other than the stack. If it''s a "ret" instruction, you
could hope that
> the
> data just below $sp was still valid, but if the return probe is firing  
> because
> of another control flow mechanism, there may not be any data to
> fetch.
> 
> 	In my mind, a->b->c is a more understandable than a->b->d.
> The former is incomplete, the latter is actually wrong.
> 
> 	Especially when I was first investigating this, I had several
> "but you just can''t get to D from B!" moments.
> 
> 	I''ll file a RFE :-).
> 
> 	James M
> 
> On Jan 20, 2007, at 6:49 PM, Adam Leventhal wrote:
> 
> >In a return probe, a user might reasonably expect one of several  
> >results
> >from the ustack() action:
> >
> >  1) the full call chain (a->b->c->d)
> >  2) the state of the stack after returning from the function (a->b-
> >>c)
> >  3) the result of naively walking the stack (a->b->d)
> >
> >(2) seems confusing since the function associated with the probe  
> >wouldn''t
> >be present in the output. While (1) would be ideal, we implement (3)  
> >because
> >we can''t, in the general case, determine if we''re in
leaf context or
> >not
> >(that is, if we''re in a part of the function where a stack
frame has
> >been
> >pushed).
> >
> >Entry probes for the pid provider produce (1) because we implement a  
> >hack in
> >which the pid provider adds a hint to the ustack code that
we''re in
> >leaf
> >context. We could easily do the same for return probes which would  
> >solve
> >this problem in that case, but the result for offset probes will vary
> >(compare the output of ustack() in pid123::main:entry and  
> >pid123:::main:0)
> >
> >Feel free to file an RFE if you think return probes should use the  
> >same
> >hack as entry probes.
> >
> >Adam
> >
> >On Sat, Jan 20, 2007 at 06:32:12PM -0800, James McIlree wrote:
> >>	I have a test program which has a call sequence of
> >>a(), b(), c(), d().
> >>
> >>	When I place a pid return probe on d(), I get a ustack that
> >>looks like this:
> >>
> >>              a.out`d+0x19
> >>              a.out`b+0xd
> >>              a.out`a+0xd
> >>              a.out`main+0x3c
> >>              a.out`_start+0x7a
> >>
> >>	The c() method appears to be missing.
> >>
> >>	I did some poking around and noticed that pid return probes
> >>fire after the instruction being instrumented has executed.
> >>
> >>	It seems to me that after a "ret", we''re
actually in
> >>method c() now, not d(). However, there is this comment and code
> >>in fasttrap_isa.c :
> >>
> >>/*
> >> * Set the program counter to the address of the traced
> >> * instruction so that it looks right in ustack()
> >> * output. We had previously set it to the end of the
> >> * instruction to simplify %rip-relative addressing.
> >> */
> >>rp->r_pc = pc;
> >>
> >>	Is this correct? It seems like the correct ustack()
> >>output would be if the pc was set to "new_pc". Does that
break
> >>invariants elsewhere in the code?
> >>
> >>	I''ve included a ustackTest.c & ustack.d that
demonstrates
> >>what I''m seeing.
> >>
> >>	James M
> >>
> >>--------------------- ustackTest.c --------------------------
> >>
> >>#include <stdio.h>
> >>#include <unistd.h>
> >>
> >>void d(int arg) {
> >>        printf("Got arg of %d\n", arg);
> >>}
> >>
> >>void c(int arg) {
> >>        d(arg+1);
> >>}
> >>
> >>void b(int arg) {
> >>        c(arg+1);
> >>}
> >>
> >>void a(int arg) {
> >>        b(arg+1);
> >>}
> >>
> >>int main(void)
> >>{
> >>  int value = 0;
> >>
> >>  printf("PID is %u\n", getpid());
> >>
> >>  while(1) {
> >>    a(value++);
> >>    sleep(1);
> >>  }
> >>}
> >>
> >>------------------------- ustack.d -----------------------
> >>
> >>pid$target::d:entry
> >>{
> >>        printf("entry stack...\n");
> >>        ustack();
> >>}
> >>
> >>pid$target::d:return
> >>{
> >>        printf("return stack...\n");
> >>        ustack();
> >>}
> >>
> >>
> >>_______________________________________________
> >>dtrace-discuss mailing list
> >>dtrace-discuss at opensolaris.org
> >
> >-- 
> >Adam Leventhal, Solaris Kernel Development      
http://blogs.sun.com/ahl
-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl