Michael Ernest
2011-Jan-05 17:46 UTC
[dtrace-discuss] Understand the dtrace quantize output (RAMASUBRAMANIAN Srikant)
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>
Angelo Rajadurai
2011-Jan-05 17:53 UTC
[dtrace-discuss] Understand the dtrace quantize output (RAMASUBRAMANIAN Srikant)
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-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. > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org-------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20110105/89e4cc2e/attachment.html>
RAMASUBRAMANIAN Srikant
2011-Jan-05 18:15 UTC
[dtrace-discuss] Understand the dtrace quantize output (RAMASUBRAMANIAN Srikant)
Angelo and Michael, Thank you very much , The results are much better now , don''t see the absurd numbers as before , The thread scoping was the problem . Got mislead by the absurd numbers and was not able to comprehend the dtrace output. As a matter of fact the machine I ran on is a multiprocessor machine . Thanks Again 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. From: dtrace-discuss-bounces at opensolaris.org [mailto:dtrace-discuss-bounces at opensolaris.org] On Behalf Of Angelo Rajadurai Sent: Wednesday, January 05, 2011 12:53 PM To: Michael Ernest Cc: dtrace-discuss at opensolaris.org Subject: Re: [dtrace-discuss] Understand the dtrace quantize output (RAMASUBRAMANIAN Srikant) 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-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 <http://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/0 c91ef92/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/0 c91ef92/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/0 c91ef92/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. _______________________________________________ dtrace-discuss mailing list dtrace-discuss at opensolaris.org -------------- next part -------------- An HTML attachment was scrubbed... URL: <http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20110105/4eb8be8e/attachment-0001.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/4eb8be8e/attachment-0001.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/4eb8be8e/attachment-0001.bin>