Michael Ernest
2011-01-05 17:46:31 UTC
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
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
Send dtrace-discuss mailing list submissions to
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
You can reach the person managing the list at
When replying, please edit your Subject line so it is more specific
than "Re: Contents of dtrace-discuss digest..."
1. Understand the dtrace quantize output (RAMASUBRAMANIAN Srikant)
----------------------------------------------------------------------
Message: 1
Date: Wed, 5 Jan 2011 17:47:24 +0100
Subject: [dtrace-discuss] Understand the dtrace quantize output
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
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
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/>
Loading Image...
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: <
Loading Image...
-------------- 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
End of dtrace-discuss Digest, Vol 69, Issue 2
*********************************************
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
You can reach the person managing the list at
When replying, please edit your Subject line so it is more specific
than "Re: Contents of dtrace-discuss digest..."
1. Understand the dtrace quantize output (RAMASUBRAMANIAN Srikant)
----------------------------------------------------------------------
Message: 1
Date: Wed, 5 Jan 2011 17:47:24 +0100
Subject: [dtrace-discuss] Understand the dtrace quantize output
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
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
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/>
Loading Image...
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: <
Loading Image...
-------------- 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
End of dtrace-discuss Digest, Vol 69, Issue 2
*********************************************
--
Michael Ernest
Inkling Research, Inc.
--
Michael Ernest
Inkling Research, Inc.
Michael Ernest
Inkling Research, Inc.
--
Michael Ernest
Inkling Research, Inc.