dtrace discuss - Oct 2005 - FBT and -Z tracing is expensive??

Hi experts,
   I am using fbt tracing to trace steps executed by clustering software 
during recovery from a crashed cluster node and timing it. Also included 
in the same script, are some pid probes for userland function tracing. I 
have specified -Z option to dtrace so that, some function which are in 
libraries, loaded later, can be traced. All the probes are of following 
nature.

fbt:module name: function name:entry/return
{
    printf("[ENTRY/RET], %s, %d", probefunc, timestamp/1000);
}

or

pid$1::function name:entry/return
{
    printf("[ENTRY/RET], %s, %d", probefunc, timestamp/1000);
}

With all the needed probes specified, dtrace matches 84 probes and a 
particular function (say foo) takes following timings starting from a 
defined tracing milestone.

foo:entry = 35.25 Sec
foo:return = 43.35 sec

This was totally unexpected. So keeping the environment as it is, I 
enabled only 4 probes. 2 for milestone entry:return and 2 for foo  
entry:return. With the reduced no of probes I got following timings.

foo:entry = 27:38 sec
foo:return = 32.47 sec

This is within expectations. To eliminate any undesirable spikes, I did 
10 runs of each of the two scenarios and still got same timings. Now 
here are the questions:

1) Is every fbt probe induces considerable amount of processing delay? 
If it is true, using many fbt probes in critical production environment 
is not desirable.
2) Is tracing kernel code and userland code with the same script a bad 
idea?
3) Specifying -Z option re-evaluates the probes after libraries are 
loaded, is that considerably expensive?

Regards,
-Atul

Atul Vidwansa - Sun Microsystems - Bangalore India writes:
 > Hi experts,
 >    I am using fbt tracing to trace steps executed by clustering software 
 > during recovery from a crashed cluster node and timing it. Also included 
 > in the same script, are some pid probes for userland function tracing. I 
 > have specified -Z option to dtrace so that, some function which are in 
 > libraries, loaded later, can be traced. All the probes are of following 
 > nature.
 > 
 > fbt:module name: function name:entry/return
 > {
 >     printf("[ENTRY/RET], %s, %d", probefunc, timestamp/1000);
 > }
 > 
 > or
 > 
 > pid$1::function name:entry/return
 > {
 >     printf("[ENTRY/RET], %s, %d", probefunc, timestamp/1000);
 > }
 > 
 > With all the needed probes specified, dtrace matches 84 probes and a 
 > particular function (say foo) takes following timings starting from a 
 > defined tracing milestone.
 > 
 > foo:entry = 35.25 Sec
 > foo:return = 43.35 sec
 > 
 > This was totally unexpected. So keeping the environment as it is, I 
 > enabled only 4 probes. 2 for milestone entry:return and 2 for foo  
 > entry:return. With the reduced no of probes I got following timings.
 > 
 > foo:entry = 27:38 sec
 > foo:return = 32.47 sec
 > 

I see (timestamp/1000) and then your numbers in seconds. I
trust you did the conversion yourself between the

	timestamp: nanosec
	timestamp/1000: microsec
	foo:entry: sec

I normally use (timestamp>>10) to get to microseconds. It''s
slightly off but that''s fine and maybe the integer division is
costly ?

 > This is within expectations. To eliminate any undesirable spikes, I did 
 > 10 runs of each of the two scenarios and still got same timings. Now 
 > here are the questions:
 > 
 > 1) Is every fbt probe induces considerable amount of processing delay? 

that depends a lot on what''s in a probe. For a simple
printf() with not too many arguments, I''ve measured
something like 10 usec (a long time ago).

 > If it is true, using many fbt probes in critical production environment 
 > is not desirable.

I would not say it that way (if you solve the problem it
does not matter the number of probes that you enabled). But
yes, don''t enable probes for no reason and don''t assume that 
there are no effects on timing.

 > 2) Is tracing kernel code and userland code with the same script a bad 
 > idea?

Should be no problems.

 > 3) Specifying -Z option re-evaluates the probes after libraries are 
 > loaded, is that considerably expensive?

I don''t know, may well be. Does it trip your cluster  ?

-r

Hi Rob,
    The conversion from Microsec to Seconds is done in post-processing 
dtrace output. I am not sure if integer division is costlier than 
shifting bits. I will try to repeat the runs with shifting bits instead 
of integer division.

Regards,
-Atul

Roch Bourbonnais - Performance Engineering wrote:
>Atul Vidwansa - Sun Microsystems - Bangalore India writes:
> > Hi experts,
> >    I am using fbt tracing to trace steps executed by clustering
software
> > during recovery from a crashed cluster node and timing it. Also
included
> > in the same script, are some pid probes for userland function tracing.
I
> > have specified -Z option to dtrace so that, some function which are in
> > libraries, loaded later, can be traced. All the probes are of
following
> > nature.
> > 
> > fbt:module name: function name:entry/return
> > {
> >     printf("[ENTRY/RET], %s, %d", probefunc,
timestamp/1000);
> > }
> > 
> > or
> > 
> > pid$1::function name:entry/return
> > {
> >     printf("[ENTRY/RET], %s, %d", probefunc,
timestamp/1000);
> > }
> > 
> > With all the needed probes specified, dtrace matches 84 probes and a 
> > particular function (say foo) takes following timings starting from a 
> > defined tracing milestone.
> > 
> > foo:entry = 35.25 Sec
> > foo:return = 43.35 sec
> > 
> > This was totally unexpected. So keeping the environment as it is, I 
> > enabled only 4 probes. 2 for milestone entry:return and 2 for foo  
> > entry:return. With the reduced no of probes I got following timings.
> > 
> > foo:entry = 27:38 sec
> > foo:return = 32.47 sec
> > 
>
>I see (timestamp/1000) and then your numbers in seconds. I
>trust you did the conversion yourself between the
>
>	timestamp: nanosec
>	timestamp/1000: microsec
>	foo:entry: sec
>
>I normally use (timestamp>>10) to get to microseconds. It''s
>slightly off but that''s fine and maybe the integer division is
>costly ?
>
> > This is within expectations. To eliminate any undesirable spikes, I
did
> > 10 runs of each of the two scenarios and still got same timings. Now 
> > here are the questions:
> > 
> > 1) Is every fbt probe induces considerable amount of processing delay?
>
>that depends a lot on what''s in a probe. For a simple
>printf() with not too many arguments, I''ve measured
>something like 10 usec (a long time ago).
>
> > If it is true, using many fbt probes in critical production
environment
> > is not desirable.
>
>I would not say it that way (if you solve the problem it
>does not matter the number of probes that you enabled). But
>yes, don''t enable probes for no reason and don''t assume
that
>there are no effects on timing.
>
> > 2) Is tracing kernel code and userland code with the same script a bad
> > idea?
>
>Should be no problems.
>
> > 3) Specifying -Z option re-evaluates the probes after libraries are 
> > loaded, is that considerably expensive?
>
>I don''t know, may well be. Does it trip your cluster  ?
>
>-r
>
>_______________________________________________
>dtrace-discuss mailing list
>dtrace-discuss at opensolaris.org
>  
>

Atul,
>  > Hi experts,
>  >    I am using fbt tracing to trace steps executed by clustering
software
>  > during recovery from a crashed cluster node and timing it. Also
included
>  > in the same script, are some pid probes for userland function
tracing. I
>  > have specified -Z option to dtrace so that, some function which are
in
>  > libraries, loaded later, can be traced. All the probes are of
following
>  > nature.
>  > 
>  > fbt:module name: function name:entry/return
>  > {
>  >     printf("[ENTRY/RET], %s, %d", probefunc,
timestamp/1000);
>  > }
>  > 
>  > or
>  > 
>  > pid$1::function name:entry/return
>  > {
>  >     printf("[ENTRY/RET], %s, %d", probefunc,
timestamp/1000);
>  > }
Why the added tracing of "probefunc"?  That might be nice for output,
but
it''s increasing your enabled probe effect substantially:  you are
copying
a string (which defaults to be 256 bytes in length) for every entry/return.
Instead, just trace the timestamp; DTrace knows the probe function based
on the enabled probe ID (EPID), and it will print it out if you don''t
run
with the "quiet" option.  As Roch mentioned, the integer divide
isn''t
exactly making anything faster either, so if you want to have this enabled
much of the time in production, I would reduce the clause body to:

	probe-description
	{
		trace(timestamp);
	}

And definitely re-read Roch''s general advice:
> I would not say it that way (if you solve the problem it
> does not matter the number of probes that you enabled). But
> yes, don''t enable probes for no reason and don''t assume
that
> there are no effects on timing.
DTrace _does_ induce additional work, so you will need to take some care
in crafting your enablings if you want to induce the smallest amount of
work possible.

	- Bryan

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