[dtrace-discuss] Understand the dtrace quantize output (RAMASUBRAMANIAN Srikant)

Michael Ernest
2011-01-05T17:46:31Z

Hello Srikant -

Apologies for the first send, my browser fu went wrong.

A quantization distributes the results of your aggregation into ranges
ordered by a power-of-two. Presumably what you''d do in your script is
capture the inclusive elapsed time of each function call in your library,
then use this quantization to see how tightly-banded the times are. Perhaps
there''s some blocking I/O in some of your calls, for example, in which
case
you might expect a wide difference with functions that don''t.

I''ve annotated your code to show what you''re actually doing:


pid$1:libswduar::entry
{
       // Associative array indexing timestamps by function call
       duarEntry[probefunc] = timestamp;

       // Aggregation to count each function invoked

       @duarCount[probefunc] = count();
}

pid$1:libswduar::return
{
       // Compute elapsed time in milliseconds

       this->elapsed = (timestamp - duarEntry[probefunc])/1000000;

       // Quantize elapsed time per function call

       @totduarTime[probefunc] = quantize(this->elapsed);

       // Zero out array element
       duarEntry[probefunc] = 0;
}

That said, your output doesn''t make sense, unless you are in fact
waiting 2
billion-plus milliseconds on 21 of your LDAP searches. Or maybe you''re
using
ActiveDirectory. Joking aside, I''d guess the problem is that the trace
code
assumes a single-threaded, single-CPU model. A more general solution tracks
each function call by thread:

pid$1:libswduar::entry
{
       @duarCount[probefunc] = count();
       self->ts = timestamp;
}

pid$1:libswduar::entry
/ self->ts /
{
       @timeBand[probefunc] = quantize(timestamp - self->ts);
}

Note I have used a predicate in the return probe to ensure we''ve seen
the
current thread on entry. It''s quite possible with a running process to
capture the return only, which will give you some funky values.

I left out the reduction to milliseconds which you can certainly put back
in, although I think microseconds would make more sense on a first pass.
With microseconds you''ll clearly see a difference between in-memory ops
vs.
I/O ops instead of truncating the former to zeroes.

Hope this helps,

Michael

On Wed, Jan 5, 2011 at 8:48 AM, <dtrace-discuss-request at
opensolaris.org>wrote:

> Send dtrace-discuss mailing list submissions to
>        dtrace-discuss at opensolaris.org
>
> To subscribe or unsubscribe via the World Wide Web, visit
>        http://mail.opensolaris.org/mailman/listinfo/dtrace-discuss
> or, via email, send a message with subject or body ''help''
to
>        dtrace-discuss-request at opensolaris.org
>
> You can reach the person managing the list at
>        dtrace-discuss-owner at opensolaris.org
>
> When replying, please edit your Subject line so it is more specific
> than "Re: Contents of dtrace-discuss digest..."
>
>
> Today''s Topics:
>
>   1. Understand the dtrace quantize output (RAMASUBRAMANIAN Srikant)
>
>
> ----------------------------------------------------------------------
>
> Message: 1
> Date: Wed, 5 Jan 2011 17:47:24 +0100
> From: RAMASUBRAMANIAN Srikant <Srikant.RAMASUBRAMANIAN at swift.com>
> To: "dtrace-discuss at opensolaris.org" <dtrace-discuss at
opensolaris.org>
> Subject: [dtrace-discuss] Understand the dtrace quantize output
> Message-ID:
>
>  <1759DECB91276E4083D703A908840BE7E140DDED2A at
BE-EXCHANGE-10.swift.corp>
> Content-Type: text/plain; charset="us-ascii"
>
> Hi,
>
>
>
> I am kind of new to DTrace , I have written a script to time function calls
> in our application library ,
>
>
>
> Wanted to know how to interpret the output from quantize of the elapsed
> time
> in each function call  , here is a sample
>
>
>
> Here is the entry and return function for the library that is being traced
>
>
>
> pid$1:libswduar::entry
> {
>        duarEntry[probefunc] = timestamp;
>        @duarCount[probefunc] = count();
> }
>
> pid$1:libswduar::return
>
> {
>        this->elapsed = (timestamp - duarEntry[probefunc])/1000000;
>        @totduarTime[probefunc] = quantize(this->elapsed);
>        duarEntry[probefunc] = 0;
> }
>
>
>
> LdapSearchRequest
>
>
>
>           value  ------------- Distribution ------------- count
>
>              -1 |                                         0
>
>               0 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      147
>
>               1 |                                         0
>
>               2 |                                         0
>
>               4 |                                         0
>
>               8 |                                         0
>
>              16 |                                         0
>
>              32 |                                         0
>
>              64 |                                         0
>
>             128 |                                         0
>
>             256 |                                         0
>
>             512 |                                         0
>
>            1024 |                                         0
>
>            2048 |                                         0
>
>            4096 |                                         0
>
>            8192 |                                         0
>
>           16384 |                                         0
>
>           32768 |                                         0
>
>           65536 |                                         0
>
>          131072 |                                         0
>
>          262144 |                                         0
>
>          524288 |                                         0
>
>         1048576 |                                         0
>
>         2097152 |                                         0
>
>         4194304 |                                         0
>
>         8388608 |                                         0
>
>        16777216 |                                         0
>
>        33554432 |                                         0
>
>        67108864 |                                         0
>
>       134217728 |                                         0
>
>       268435456 |                                         0
>
>       536870912 |                                         0
>
>      1073741824 |                                         0
>
>      2147483648 |@@@@@                                    21
>
>      4294967296 |                                         0
>
>
>
> Thanks & Regards
>
> Srikant Ramasubramanian
> SWIFTNet Link
>
> Tel: + 1(703) - 365- 6117
>
> Fax: +  1(703) - 365 - 6410
>
> Company name (e.g. ''S.W.I.F.T. SCRL'' for users in BE)
>
>  <http://www.swiftcommunity.net/>
> http://www.swift.com/temp/63340/97961/swiftcommunitybutton.gif
>
> This e-mail and any attachments thereto may contain information which is
> confidential and/or proprietary and intended for the sole use of the
> recipient(s) named above. If you have received this e-mail in error, please
> immediately notify the sender and delete the mail. Thank you for your
> co-operation. SWIFT reserves the right to retain e-mail messages on its
> systems and, under circumstances permitted by applicable law, to monitor
> and
> intercept e-mail messages to and from its systems. Please visit
> www.swift.com for more information about SWIFT.
>
>
>
> -------------- next part --------------
> An HTML attachment was scrubbed...
> URL: <
>
http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20110105/0c91ef92/attachment.html
> >
> -------------- next part --------------
> A non-text attachment was scrubbed...
> Name: not available
> Type: image/gif
> Size: 5953 bytes
> Desc: not available
> URL: <
>
http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20110105/0c91ef92/attachment.gif
> >
> -------------- next part --------------
> A non-text attachment was scrubbed...
> Name: smime.p7s
> Type: application/x-pkcs7-signature
> Size: 5043 bytes
> Desc: not available
> URL: <
>
http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20110105/0c91ef92/attachment.bin
> >
>
> ------------------------------
>
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
>
> End of dtrace-discuss Digest, Vol 69, Issue 2
> *********************************************
>



--
Michael Ernest
Inkling Research, Inc.



--
Michael Ernest
Inkling Research, Inc.
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20110105/38daf900/attachment-0001.html>