dtrace discuss - Apr 2009 - dtrace script affects write performance?

Hi Experts,

While testing we found some strange results, according to which if we use the
dtrace tool and run our programs we see that writes happen slowly and if we run
our program without dtrace then the writes are faster. Is there a possibility
that dtrace affects performance?
I have attached the dtrace script which we have used to get the statistics for a
threaded program. Please see, if this d-script is fine?
-- 
This message posted from opensolaris.org
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dscript.d
Type: application/octet-stream
Size: 1106 bytes
Desc: not available
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090415/af7d3baf/attachment.obj>

Hi Renil,

Renil Thomas wrote:
> Hi Experts,
>
> While testing we found some strange results, according to which if we use
the dtrace tool and run our programs we see that writes happen slowly and if we
run our program without dtrace then the writes are faster. Is there a
possibility that dtrace affects performance?
> I have attached the dtrace script which we have used to get the statistics
for a threaded program. Please see, if this d-script is fine?
>   
One way to (possibly) speed the script up is to use probefunc instead of
"strings" in your aggregates.
So for instance, instead of

@data["_write"] = quantize(timestamp - self->timestamp_);

use

@data[probefunc] = quantize(timestamp-self->timestamp_);

But, I don''t think this will make a huge difference.
max

Hello!

Thanks for the response, is their any loophole in this d-script or any additions
that can be done here.
-- 
This message posted from opensolaris.org

On 04/16/09 00:13, Renil Thomas wrote:
> Hello!
> 
> Thanks for the response, is their any loophole in this d-script or any
> additions that can be done here.
you should be able to simplify:

alloccgblk:return
/self->traceme && self->timestamp_alloccgblk/
{

to

alloccgblk:return
/self->timestamp_alloccgblk/
{

(the first condition is implicit, isn''t it?)

same for mapsearch:return

one thing you could do to find out which D construct is influencing 
performance is to remove pieces bit by bit (after you''ve replaced all 
strings in the aggregations, which I think *will* give you some 
improvement) and watch for changes (or to start simple and add bits ...).

HTH
Michael
-- 
Michael Schuster 	http://blogs.sun.com/recursion
Recursion, n.: see ''Recursion''

On Wed, Apr 15, 2009 at 11:11:12PM -0700, Renil Thomas
wrote:
> Hi Experts,
> 
> While testing we found some strange results, according to which if we
> use the dtrace tool and run our programs we see that writes happen
> slowly and if we run our program without dtrace then the writes are
> faster. Is there a possibility that dtrace affects performance?
>
> I have attached the dtrace script which we have used to get the
> statistics for a threaded program. Please see, if this d-script is
> fine?
The first two enablings in your script are:

pid$1::_write:entry
/pid == $1 && tid == 3/
{
        self->timestamp_ = timestamp;
        self->traceme = 1;
}

pid$1::_write:return
/self->timestamp_/
{
        self->traceme = 0; 
        @data["_write"] = quantize(timestamp - self->timestamp_);
        @dataavg["_write"] = avg(timestamp - self->timestamp_);
}


Since these are pid provider probes, every time you do a write, the following
sequence of events happen:

1*  trap into kernel for _write:entry
2*  return back to usermode, execute a couple instructions, then
3.  trap into kernel for write system call
4.  return back to usermode, execute a couple instructions, then
5*  trap into kernel for _write:return
6*  return back to usermode, and continue

(the stars are extra work, above what is normally necessary)

Each of those user-kernel-user transitions is expensive.  If you re-cast those
enablings in terms of "syscall" provider probes:

syscall::write:entry
/pid == $1 && tid == 3/
{
        self->timestamp_ = timestamp;
        self->traceme = 1;
}

syscall::write:return
/self->timestamp_/
{
        self->traceme = 0; 
        @data["_write"] = quantize(timestamp - self->timestamp_);
        @dataavg["_write"] = avg(timestamp - self->timestamp_);
}

the overhead will be significantly less, because you''re already
in-kernel by
the time the syscall::write: probes fire.

Cheers,
- jonathan

Hello!

Thanks for your suggestion, I will incorporate these changes and update results
soon.
-- 
This message posted from opensolaris.org

Hi,

Thank you! for this suggestion, it was helpful.

Thanks & Regards,
Renil Thomas
-- 
This message posted from opensolaris.org