This might be nit picking but a small correction in Michael's solution. Because
"pid$1:libswduar::entry" will match with all the functions in the libswduar
library you may want to keep the thread local timestamp for each function. So
something like
pid$1:libswduar::entry
{
@duarCount[probefunc] = count();
self->ts[probefunc] = timestamp;
}
pid$1:libswduar::entry
/ self->ts[probefunc] /
{
@timeBand[probefunc] = quantize(timestamp - self->ts[probefunc]);
self->ts[probefunc]=0;
}
-Angelo
On Jan 5, 2011, at 12:46 PM, Michael Ernest wrote:
> 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-requ...@opensolaris.org>
> wrote:
> Send dtrace-discuss mailing list submissions to
> dtrace-discuss@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-requ...@opensolaris.org
>
> You can reach the person managing the list at
> dtrace-discuss-ow...@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.ramasubraman...@swift.com>
> To: "dtrace-discuss@opensolaris.org" <dtrace-discuss@opensolaris.org>
> Subject: [dtrace-discuss] Understand the dtrace quantize output
> Message-ID:
> <1759decb91276e4083d703a908840be7e140dde...@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@opensolaris.org
>
> End of dtrace-discuss Digest, Vol 69, Issue 2
> *********************************************
>
>
>
> --
> Michael Ernest
> Inkling Research, Inc.
>
>
>
> --
> Michael Ernest
> Inkling Research, Inc.
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss@opensolaris.org
_______________________________________________
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org
