dtrace discuss - Dec 2009 - tracing recursive functions

When tracing user functions, how are recursive functions handled.  For
example, the following code processes the time spent within user
dynamic modules. The modules have user created dynamic libraries :
MyLib1.so, MyLib2.so, ... I would also like to know if there is
someting already in the dtrace toolkit that I can use.

{code}
pid$target:*.so::entry
{
    self->ts[probemod, probefunc] = timestamp;
}

pid$target:*.so::return
/self->ts[probemod, probefunc]/
{
    @funct_time[probemod, probefunc] = sum(timestamp -
self->ts[probemod, probefunc];
    self->ts[probemod, probefunc] = 0;
{code}

As can be seen, if recursive code is used, the self->ts gets reset to
timestamp with every entry, and the innermost exit causes a time to be
calculated and the ts to be reset. The rest of the returns within the
recursion will be ignored because of the conditional.

I would like to know if someone has already done this before I try to
reinvent the wheel or if there is a tool in the dtrace toolkit to do
this already.

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

Hi Sabba:

You can use the ustackdepth variable. This has the stack depth in the user land.
So use that as the array index.

-Angelo

On Dec 16, 2009, at 1:52 PM, Hillel (Sabba) Markowitz wrote:
> When tracing user functions, how are recursive functions handled.  For
> example, the following code processes the time spent within user
> dynamic modules. The modules have user created dynamic libraries :
> MyLib1.so, MyLib2.so, ... I would also like to know if there is
> someting already in the dtrace toolkit that I can use.
> 
> {code}
> pid$target:*.so::entry
> {
>    self->ts[probemod, probefunc] = timestamp;
> }
> 
> pid$target:*.so::return
> /self->ts[probemod, probefunc]/
> {
>    @funct_time[probemod, probefunc] = sum(timestamp -
> self->ts[probemod, probefunc];
>    self->ts[probemod, probefunc] = 0;
> {code}
> 
> As can be seen, if recursive code is used, the self->ts gets reset to
> timestamp with every entry, and the innermost exit causes a time to be
> calculated and the ts to be reset. The rest of the returns within the
> recursion will be ignored because of the conditional.
> 
> I would like to know if someone has already done this before I try to
> reinvent the wheel or if there is a tool in the dtrace toolkit to do
> this already.
> 
> -- 
>       Sabba     -          ??? ???        -     Hillel
> Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me
ashore"
> SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
> http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

On Wed, Dec 16, 2009 at 1:52 PM, Hillel (Sabba) Markowitz
<sabbahillel at gmail.com> wrote:
>
> As can be seen, if recursive code is used, the self->ts gets reset to
> timestamp with every entry, and the innermost exit causes a time to be
> calculated and the ts to be reset. The rest of the returns within the
> recursion will be ignored because of the conditional.
>
> I would like to know if someone has already done this before I try to
> reinvent the wheel or if there is a tool in the dtrace toolkit to do
> this already.
You''ll need to keep an array of timestamps indexed on ustackdepth.
Something like this (it appears that ustackdepth on entry doesn''t
actually match ustackdepth on return):

pid$target:*.so::entry
{
    self->ts[probemod, probefunc, ustackdepth] = timestamp;
}

pid$target:*.so::return
/ self->ts[probemod, probefunc, ustackdepth + 1] /
{
    @func_time[probemod, probefunc] = sum(timestamp -
self->ts[probemod, probefunc, ustackdepth + 1]);
    self->ts[probemod, probefunc, ustackdepth + 1] = 0;
}

Chad

On Wed, Dec 16, 2009 at 2:13 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> On Wed, Dec 16, 2009 at 1:52 PM, Hillel (Sabba) Markowitz
> <sabbahillel at gmail.com> wrote:
>>
>> As can be seen, if recursive code is used, the self->ts gets reset
to
>> timestamp with every entry, and the innermost exit causes a time to be
>> calculated and the ts to be reset. The rest of the returns within the
>> recursion will be ignored because of the conditional.
>>
>> I would like to know if someone has already done this before I try to
>> reinvent the wheel or if there is a tool in the dtrace toolkit to do
>> this already.
>
> You''ll need to keep an array of timestamps indexed on ustackdepth.
> Something like this (it appears that ustackdepth on entry doesn''t
> actually match ustackdepth on return):
>
> pid$target:*.so::entry
> {
> ? ?self->ts[probemod, probefunc, ustackdepth] = timestamp;
> }
>
> pid$target:*.so::return
> / self->ts[probemod, probefunc, ustackdepth + 1] /
> {
> ? ?@func_time[probemod, probefunc] = sum(timestamp -
> self->ts[probemod, probefunc, ustackdepth + 1]);
> ? ?self->ts[probemod, probefunc, ustackdepth + 1] = 0;
> }
>
> Chad
>
Thanks, this looks good. I will try it and see how it works.

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Wed, Dec 16, 2009 at 2:13 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> On Wed, Dec 16, 2009 at 1:52 PM, Hillel (Sabba) Markowitz
> <sabbahillel at gmail.com> wrote:
>>
>> As can be seen, if recursive code is used, the self->ts gets reset
to
>> timestamp with every entry, and the innermost exit causes a time to be
>> calculated and the ts to be reset. The rest of the returns within the
>> recursion will be ignored because of the conditional.
>>
>> I would like to know if someone has already done this before I try to
>> reinvent the wheel or if there is a tool in the dtrace toolkit to do
>> this already.
>
> You''ll need to keep an array of timestamps indexed on ustackdepth.
> Something like this (it appears that ustackdepth on entry doesn''t
> actually match ustackdepth on return):
>
> pid$target:*.so::entry
> {
> ? ?self->ts[probemod, probefunc, ustackdepth] = timestamp;
> }
>
> pid$target:*.so::return
> / self->ts[probemod, probefunc, ustackdepth + 1] /
> {
> ? ?@func_time[probemod, probefunc] = sum(timestamp -
> self->ts[probemod, probefunc, ustackdepth + 1]);
> ? ?self->ts[probemod, probefunc, ustackdepth + 1] = 0;
> }
>
> Chad
>
When running this test, it appears to have ustackdepth  set as the
actual depth in the stack rather than recursion. Thus if there is code
of the form

A(vars)
{
   B(vars);
   c(vars);
}

B(vars)
{
   c(vars);
}

C will appear as two different values of ustack depth.  In this
particular case, C is not recursive but is called at different points
in the code. What I am trying to look for is

A(vars)
{
     code
     if (end test)
         {
             finished = true;
         }
      else
         {
             finished = false;
         }
     if (!finished)
     {
        finished = A(vars);
     }
     code
     return finished
}

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Wed, Dec 16, 2009 at 2:17 PM, Hillel (Sabba) Markowitz
<sabbahillel at gmail.com> wrote:
> On Wed, Dec 16, 2009 at 2:13 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
>>
>> You''ll need to keep an array of timestamps indexed on
ustackdepth.
>> Something like this (it appears that ustackdepth on entry
doesn''t
>> actually match ustackdepth on return):
>>
>> pid$target:*.so::entry
>> {
>> ? ?self->ts[probemod, probefunc, ustackdepth] = timestamp;
>> }
>>
>> pid$target:*.so::return
>> / self->ts[probemod, probefunc, ustackdepth + 1] /
>> {
>> ? ?@func_time[probemod, probefunc] = sum(timestamp -
>> self->ts[probemod, probefunc, ustackdepth + 1]);
>> ? ?self->ts[probemod, probefunc, ustackdepth + 1] = 0;
>> }
>>
>> Chad
>>
>
> Thanks, this looks good. I will try it and see how it works.
Actually, there''s a bug in the above.  For this case:

-> A
    -> B
        -> C
        <- C
    <- B
<- A

The time for B will include the time spent in C, and the time for A
will include the entire time.

So what you''ll need to do is something more like this:

#define STACKDEPTHBASE 2

pid$target:::entry
/ ustackdepth == STACKDEPTHBASE /
{
       self->ts[ustackdepth] = timestamp;
       self->func[ustackdepth] = probefunc;
}

pid$target:::entry
/ ustackdepth > STACKDEPTHBASE && self->ts[ustackdepth - 1]/
{
       /*
        * Increment the time we just spent in the function that
        * called us.  Zero its time so we stop counting against it.
        */
       @profile[self->func[ustackdepth - 1]]            sum(timestamp -
self->ts[ustackdepth - 1]);
       self->ts[ustackdepth - 1] = 0;

       /*
        * Accounting for function we''re entering.
        */
       self->func[ustackdepth] = probefunc;
       self->ts[ustackdepth] = timestamp;
}

pid$target:::return
/ ustackdepth + 1 > STACKDEPTHBASE && self->ts[ustackdepth]/
{
       /*
        * Accounting for function we''re leaving.
        */
       @profile[self->func[ustackdepth + 1]]            sum(timestamp -
self->ts[ustackdepth + 1]);
       self->ts[ustackdepth + 1] = 0;
       self->func[ustackdepth + 1] = 0;

       /*
        * We''re about to re-enter the function that called us, so
        * set the timestamp for him.
        */
       self->ts[ustackdepth] = timestamp;
}

pid$target:::return
/ ustackdepth + 1 == STACKDEPTHBASE && self->ts[ustackdepth + 1] /
{
       @profile[self->func[ustackdepth + 1]]            sum(timestamp -
self->ts[ustackdepth + 1]);
       self->ts[ustackdepth + 1] = 0;
       self->func[ustackdepth + 1] = 0;
}


Chad

On Wed, Dec 16, 2009 at 2:44 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> Actually, there''s a bug in the above. ?For this case:
>
> -> A
> ? ?-> B
> ? ? ? ?-> C
> ? ? ? ?<- C
> ? ?<- B
> <- A
>
> The time for B will include the time spent in C, and the time for A
> will include the entire time.
Actually, the initial tests that I am running do want to show the
total time, including what is in the lower levels.  The second set of
tests would use the fix you just included.

However, what I am worried about is a set where

->A
  ->B
     ->C
     <-C
   <-B
<-A


->D
  ->C
 <-C
<-D

This would seem to not aggregate the C as the ustackdepth for the two
usages of C would be different. In this case, I do want to have the
counts aggregated.
What I want to handle is the case


->A
  ->A
    ->A
    <-A
   <-A
<-A

That is the case that actually wiped out what happened before. How do
I handle this? The fix that you just sent me would seem to handle it,
but how do I see the difference between the two cases?


-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Wed, Dec 16, 2009 at 3:19 PM, Hillel (Sabba) Markowitz
<sabbahillel at gmail.com> wrote:
>
> However, what I am worried about is a set where
>
> ->A
> ?->B
> ? ? ->C
> ? ? <-C
> ? <-B
> <-A
>
>
> ->D
> ?->C
> ?<-C
> <-D
>
> This would seem to not aggregate the C as the ustackdepth for the two
> usages of C would be different. In this case, I do want to have the
> counts aggregated.
The code I posted should aggregate the time spent in C.  Note that
@func_time is indexed by [probemod, probefunc] only, not including
ustackdepth.
> What I want to handle is the case
>
>
> ->A
> ?->A
> ? ?->A
> ? ?<-A
> ? <-A
> <-A
>
> That is the case that actually wiped out what happened before. How do
> I handle this? The fix that you just sent me would seem to handle it,
> but how do I see the difference between the two cases?
So here you want to see the exclusive time spent in A at each level of
recursion?  Then you''d need to add ustackdepth (or some variable of
your own that''s keeping track of recursion depth) as in index to your
aggregation.  (You might want an array to keep track of recursion
depth per function, in case you have the case A -> B -> A -> B.)

Chad

On Wed, Dec 16, 2009 at 4:01 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> So here you want to see the exclusive time spent in A at each level of
> recursion? ?Then you''d need to add ustackdepth (or some variable
of
> your own that''s keeping track of recursion depth) as in index to
your
> aggregation. ?(You might want an array to keep track of recursion
> depth per function, in case you have the case A -> B -> A -> B.)
>
> Chad
>
Thanks. I will have to study this.

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Wed, Dec 16, 2009 at 2:44 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:

> #define STACKDEPTHBASE 2
I don''t follow why this is set to 2. I included a syscall count to
also see how many times a function is entered and the initialization
function did not show up in the time. Shouldn''t the index be 0 based
so that the value should be 1?

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Wed, Dec 16, 2009 at 2:44 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> #define STACKDEPTHBASE 2
It appears that instead of doing this, I would have to set up

BEGIN
{
    self->startdepth = ustackdepth;
}

This would allow the depth to be whatever the actual base depth is.
The value used here is not the one that shows up in my tests.

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

In testing the code that you sent I did find a slight problem. It did
not work with the STACKDEPTHBASE definition. However, I defined a
variable

self->mydepth[probemod, ustackdepth] = ustackdepth;

This gets defined when self->func[probemod, ustackdepth] gets defined
and zeroed when self->func gets zeroed.

THen instead of testing the depth at ustackdepth == STACKDEPTHBASE
(or
>) I tested the appropriate level as
!self->mydepth[probemod, ustackdepth-1] to identify the first entry in
the list and

!self->mydepth[probemod, ustackdepth] to identify the return to the
top most level.

Similarly,

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Thu, Dec 17, 2009 at 3:08 PM, Hillel (Sabba) Markowitz
<sabbahillel at gmail.com> wrote:
> On Wed, Dec 16, 2009 at 2:44 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
>
>
>> #define STACKDEPTHBASE 2
>
> I don''t follow why this is set to 2. I included a syscall count to
> also see how many times a function is entered and the initialization
> function did not show up in the time. Shouldn''t the index be 0
based
> so that the value should be 1?
This was just an observation that ustackdepth showed up as 2 on entry
to main().  What I really should have done would be to set the base as
a thread-local variable in the pid$target::main:entry probe.

And this would only work for a single-threaded process.  For a
multi-threaded process, you''d want to set it for each thread based on
the initial function for that thread.

Chad

On Fri, Dec 18, 2009 at 1:12 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> This was just an observation that ustackdepth showed up as 2 on entry
> to main(). ?What I really should have done would be to set the base as
> a thread-local variable in the pid$target::main:entry probe.
>
> And this would only work for a single-threaded process. ?For a
> multi-threaded process, you''d want to set it for each thread based
on
> the initial function for that thread.
>
> Chad
>
I see. I created a simple hello world typ as follows (simplified)

int main(argc, argv)
{
     int i;
     for (i = 0; i < argc; i++)
     {
          printit(argc(i);
          printf(" ");
     }
    printf("\n");
}

void print(char *args)
{
    int i;
    for (i=0; i<strlen(args); i++)
    {
        printone(args[i]);
    }
}
void printone(char arg)
{
    printf("%c", arg)
}

The nest script uses the form

pid$target:hello:::entry

This is because in the real tests, I would not be able to use

pid$target:::entry because it would be trying to do too much.

As a result, the entries that I get (putting a printf into the probe)
from "./hello This is a test" gives me


_start:entry probemod = hello, probefunc =_start, ustackdepth = 1
printit:entry probemod = hello,  probefunc = printit, ustackdepth = 3
printone:entry probemod = hello, probefunc = printone, ustackdepth = 4


As you can see, the printit function winds up with a skipped
ustackdepth (the value 2). I tried to test it without the hello in the
probe definition and it did show me the full set of libraries.
However, it still gave me the same problem. I may have to use a
"mydepth" variable rather than ustackdepth.

Have you run into anything like this?

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Fri, Dec 18, 2009 at 1:12 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> On Thu, Dec 17, 2009 at 3:08 PM, Hillel (Sabba) Markowitz
> <sabbahillel at gmail.com> wrote:
>> On Wed, Dec 16, 2009 at 2:44 PM, Chad Mynhier <cmynhier at
gmail.com> wrote:
>>
>>
>>> #define STACKDEPTHBASE 2
>>
>> I don''t follow why this is set to 2. I included a syscall
count to
>> also see how many times a function is entered and the initialization
>> function did not show up in the time. Shouldn''t the index be 0
based
>> so that the value should be 1?
>
> This was just an observation that ustackdepth showed up as 2 on entry
> to main(). ?What I really should have done would be to set the base as
> a thread-local variable in the pid$target::main:entry probe.
>
> And this would only work for a single-threaded process. ?For a
> multi-threaded process, you''d want to set it for each thread based
on
> the initial function for that thread.
>
> Chad
>
When I tried to set up with a probe at

pid$target::main:entry with a printf inside it, I got no output.
However, I did get a main:return from

pid:target:hello::return

I do not understand why that is happening. As I said in my last post,
I do get a _start:entry at ustackdepth =1, but to main:entry at
ustackdepth =2.


-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Mon, Dec 21, 2009 at 8:47 AM, Hillel (Sabba) Markowitz
<sabbahillel at gmail.com> wrote:
>
> When I tried to set up with a probe at
>
> pid$target::main:entry with a printf inside it, I got no output.
> However, I did get a main:return from
>
> pid:target:hello::return
>
> I do not understand why that is happening. As I said in my last post,
> I do get a _start:entry at ustackdepth =1, but to main:entry at
> ustackdepth =2.
What update of Solaris 10 are you running?  I believe there was a bug
in earlier updates where main:entry wouldn''t show up.  I can''t
find a
bugid, though.

Chad

On Mon, Dec 21, 2009 at 9:45 AM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> On Mon, Dec 21, 2009 at 8:47 AM, Hillel (Sabba) Markowitz
> <sabbahillel at gmail.com> wrote:
>>
>> When I tried to set up with a probe at
>>
>> pid$target::main:entry with a printf inside it, I got no output.
>> However, I did get a main:return from
>>
>> pid:target:hello::return
>>
>> I do not understand why that is happening. As I said in my last post,
>> I do get a _start:entry at ustackdepth =1, but to main:entry at
>> ustackdepth =2.
>
> What update of Solaris 10 are you running? ?I believe there was a bug
> in earlier updates where main:entry wouldn''t show up. ?I
can''t find a
> bugid, though.
>
> Chad
>
OK thanks. I will probably have to work around it then and see if the
sys admins will be able to install updates.

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

On Thu, Dec 17, 2009 at 04:18:21PM -0500, Hillel (Sabba) Markowitz
wrote:
> On Wed, Dec 16, 2009 at 2:44 PM, Chad Mynhier <cmynhier at gmail.com>
wrote:
> 
> > #define STACKDEPTHBASE 2
> 
> It appears that instead of doing this, I would have to set up
> 
> BEGIN
> {
>     self->startdepth = ustackdepth;
> }
> 
> This would allow the depth to be whatever the actual base depth is.
> The value used here is not the one that shows up in my tests.
This won''t work;  the BEGIN probe isn''t executed in the
context of the
program.

On Tue, Dec 22, 2009 at 1:27 PM, Jonathan Adams <jonathan.adams at
sun.com> wrote:
> On Thu, Dec 17, 2009 at 04:18:21PM -0500, Hillel (Sabba) Markowitz wrote:
>> On Wed, Dec 16, 2009 at 2:44 PM, Chad Mynhier <cmynhier at
gmail.com> wrote:
>>
>> > #define STACKDEPTHBASE 2
>>
>> It appears that instead of doing this, I would have to set up
>>
>> BEGIN
>> {
>> ? ? self->startdepth = ustackdepth;
>> }
>>
>> This would allow the depth to be whatever the actual base depth is.
>> The value used here is not the one that shows up in my tests.
>
> This won''t work; ?the BEGIN probe isn''t executed in the
context of the
> program.
>
>
>
OK thanks. I will have to do something else then.

-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg

An interesting case occurred because of recursion.

for (i = 1; i<strlen(printarg); i++)
    {
        printone(printarg[i]);
    }

became optimised with strict recursion so that it never actually
returned to the calling function. As a result, ustackdepth never got
incremented and I needed to check the timestamp of the calling routine
to ensure that it was not 0 before setting trying to sum the time
spent in the calling routine. I also had to not reset the time
entering into the new function. Note that this has to be done in the
proper order or the count will be off.

pid$target:myapp::entry
/ self->mydepth[probemod, ustackdepth-1]  && !self-ts[probemod,
ustackdepth-1]/
{
    /* Just count the entry into the new function */
    @syscalls[probemod, probefunc] = count();
}


pid$target:myapp::entry
/ self->mydepth[probemod, ustackdepth-1]  && self-ts[probemod,
ustackdepth-1] /
{
    /* Close the timing for the calling routine */
    @total[probemod, ustackdepth-1] = sum(timestamp-self->ts[probemod,
ustackdepth-1]);
    ts[probemod, ustackdepth-1] = 0;

    /* Set up to start timing the current function */
     ......
}

If the return of the recursive function gets called in the for loop,
then the normal processing will handle matters.


-- 
       Sabba     -          ??? ???        -     Hillel
Hillel (Sabba) Markowitz | Said the fox to the fish, "Join me ashore"
 SabbaHillel at gmail.com | The fish are the Jews, Torah is our water
http://photos1.blogger.com/blogger/7637/544/640/SabbaHillel.jpg