dtrace discuss - May 2009 - pid provider to trace all function calls from a particular function

Hi, 
We have a c++ application and I want to time all function calls, called from
within a function. For Ex:
Lets say there is a function funcA and it calls funcB funC etc.. 
Now other functions can also call funcB and funcC, but I only want to trace them
when they are called from within funcA.
My psuedocode snippet :

pid$target::<MANGLED FUNCA>:entry
{
 self->go_in = 1;
 self->ts[probefunc] = timestamp;
}
pid$target:::entry
/self->go_in/
{
  self->ts[probefunc] = timestamp;
}
pid$target:::return
/self->go_in/
{
 this->tmp = timestamp - self->ts[probefunc];
 this->tmp =0;
}
pid$target::<MANGLED FUNCA>:return
{
 this->tmp = timestamp - self->ts[probefunc];
 self->go_in = 0;
 this->tmp = 0;
}


This doesnt seem to work and ends up matching and printing all function calls. 
Can you please help me and see what I am doing wrong. 

Thanks
Mohnish
-- 
This message posted from opensolaris.org

mohnish wrote:
> Hi, 
> We have a c++ application and I want to time all function calls, called
from within a function. For Ex:
> Lets say there is a function funcA and it calls funcB funC etc.. 
> Now other functions can also call funcB and funcC, but I only want to trace
them when they are called from within funcA.
> My psuedocode snippet :
>
> pid$target::<MANGLED FUNCA>:entry
> {
>  self->go_in = 1;
>  self->ts[probefunc] = timestamp;
> }
> pid$target:::entry
> /self->go_in/
> {
>   self->ts[probefunc] = timestamp;
> }
> pid$target:::return
> /self->go_in/
> {
>  this->tmp = timestamp - self->ts[probefunc];
>  this->tmp =0;
> }
> pid$target::<MANGLED FUNCA>:return
> {
>  this->tmp = timestamp - self->ts[probefunc];
>  self->go_in = 0;
>  this->tmp = 0;
> }
>
>
> This doesnt seem to work and ends up matching and printing all function
calls.
> Can you please help me and see what I am doing wrong. 
>   
You are not seeing any timing information because you are  recording the 
timing information in a associative array and
these arrays are not printed when you terminate the D script.

Here''s an attempt to rectify your script, keeping in mind that one of 
the functions called from <func a> can be called
multiple times.

#!/usr/sbin/dtrace -s

pid$target::<MANGLED FUNCA>:entry
{
   self->in = 1;
   self->depth = 0;
}

pid$target:::entry
/self->in/
{
        self->ts[self->depth++] = timestamp;
}

pid$target:::return
/self->in  && self->ts[--self->depth] != 0/
{
        @a[probefunc] = avg(timestamp - self->ts[self->depth]);
        @calls[probefunc] = count();
        self->ts[self->depth] = 0;
}

pid$target::<MANGLED_FUNCA>:return
/self->in/
{
   printf("TIMESTAMP");
   printa("%s -> %@d\n", @a);

   printf("FUNC_CALLS");
   printa("%s -> %@d\n", @calls);

}

Pramod
> Thanks
> Mohnish
>

Pramod Batni wrote:
> mohnish wrote:
>> Hi, We have a c++ application and I want to time all function calls, 
>> called from within a function. For Ex:
>> Lets say there is a function funcA and it calls funcB funC etc.. Now 
>> other functions can also call funcB and funcC, but I only want to 
>> trace them when they are called from within funcA. My psuedocode 
>> snippet :
>>
>> pid$target::<MANGLED FUNCA>:entry
>> {
>>  self->go_in = 1;
>>  self->ts[probefunc] = timestamp;
>> }
>> pid$target:::entry
>> /self->go_in/
>> {
>>   self->ts[probefunc] = timestamp;
>> }
>> pid$target:::return
>> /self->go_in/
>> {
>>  this->tmp = timestamp - self->ts[probefunc];
>>  this->tmp =0;
>> }
>> pid$target::<MANGLED FUNCA>:return
>> {
>>  this->tmp = timestamp - self->ts[probefunc];
>>  self->go_in = 0;
>>  this->tmp = 0;
>> }
>>
>>
>> This doesnt seem to work and ends up matching and printing all 
>> function calls. Can you please help me and see what I am doing wrong.
>
> You are not seeing any timing information because you are  recording 
> the timing information in a associative array and
> these arrays are not printed when you terminate the D script.
>
> Here''s an attempt to rectify your script, keeping in mind that one
of
> the functions called from <func a> can be called
> multiple times.
>
> #!/usr/sbin/dtrace -s
>
> pid$target::<MANGLED FUNCA>:entry
> {
>   self->in = 1;
>   self->depth = 0;
> }
>
> pid$target:::entry
> /self->in/
> {
>        self->ts[self->depth++] = timestamp;
> }
>
> pid$target:::return
> /self->in  && self->ts[--self->depth] != 0/
> {
>        @a[probefunc] = avg(timestamp - self->ts[self->depth]);
>        @calls[probefunc] = count();
>        self->ts[self->depth] = 0;
> }
>
> pid$target::<MANGLED_FUNCA>:return
> /self->in/
> {
>   printf("TIMESTAMP");
>   printa("%s -> %@d\n", @a);
>
>   printf("FUNC_CALLS");
>   printa("%s -> %@d\n", @calls);
    /* returning from the function of interest, set self->in to zero to 
stop collecting information */

       self->in = 0;
>
> }
>

Thanks Pramod, 
I will try this out and see how it goes.  


Mohnish Kodnani

EMC CORPORATION
Ph: 925-600-6067

-----Original Message-----
From: Pramod.Batni at Sun.COM [mailto:Pramod.Batni at Sun.COM] 
Sent: Saturday, May 09, 2009 00:08
To: Kodnani, Mohnish
Cc: dtrace-discuss at opensolaris.org
Subject: Re: [dtrace-discuss] pid provider to trace all function calls
from aparticular function

Pramod Batni wrote:
> mohnish wrote:
>> Hi, We have a c++ application and I want to time all function calls, 
>> called from within a function. For Ex:
>> Lets say there is a function funcA and it calls funcB funC etc.. Now 
>> other functions can also call funcB and funcC, but I only want to 
>> trace them when they are called from within funcA. My psuedocode 
>> snippet :
>>
>> pid$target::<MANGLED FUNCA>:entry
>> {
>>  self->go_in = 1;
>>  self->ts[probefunc] = timestamp;
>> }
>> pid$target:::entry
>> /self->go_in/
>> {
>>   self->ts[probefunc] = timestamp;
>> }
>> pid$target:::return
>> /self->go_in/
>> {
>>  this->tmp = timestamp - self->ts[probefunc];
>>  this->tmp =0;
>> }
>> pid$target::<MANGLED FUNCA>:return
>> {
>>  this->tmp = timestamp - self->ts[probefunc];
>>  self->go_in = 0;
>>  this->tmp = 0;
>> }
>>
>>
>> This doesnt seem to work and ends up matching and printing all 
>> function calls. Can you please help me and see what I am doing wrong.
>
> You are not seeing any timing information because you are  recording 
> the timing information in a associative array and
> these arrays are not printed when you terminate the D script.
>
> Here''s an attempt to rectify your script, keeping in mind that one
of
> the functions called from <func a> can be called
> multiple times.
>
> #!/usr/sbin/dtrace -s
>
> pid$target::<MANGLED FUNCA>:entry
> {
>   self->in = 1;
>   self->depth = 0;
> }
>
> pid$target:::entry
> /self->in/
> {
>        self->ts[self->depth++] = timestamp;
> }
>
> pid$target:::return
> /self->in  && self->ts[--self->depth] != 0/
> {
>        @a[probefunc] = avg(timestamp - self->ts[self->depth]);
>        @calls[probefunc] = count();
>        self->ts[self->depth] = 0;
> }
>
> pid$target::<MANGLED_FUNCA>:return
> /self->in/
> {
>   printf("TIMESTAMP");
>   printa("%s -> %@d\n", @a);
>
>   printf("FUNC_CALLS");
>   printa("%s -> %@d\n", @calls);
    /* returning from the function of interest, set self->in to zero to 
stop collecting information */

       self->in = 0;
>
> }
>