Re: [dtrace-discuss] LatencyTop
I don't think anyone disagrees that measuring latency is a bad idea. Note Brendan's comments in http://osnews.com/permalink?296801 http://osnews.com/permalink?296801 Encouraging customers to look at latencies for performance analysis is really important. ... If this tool does get customers to think more carefully about latency metrics, then that will certainly be valuable. All roads lead to DTrace. However forcing people to patch their kernel to do it is not going to attract neophytes, no matter how simply the user space tool is. That's the beauty of dynamic tracing systems. You can answer questions that the original designers of the OS didn't anticipate (or had time to think about) that you would ask. Cheers, Colin Aubrey Li wrote: On Jan 19, 2008 10:30 AM, Roman Shaposhnik mailto:[EMAIL PROTECTED] [EMAIL PROTECTED] wrote: On Fri, 2008-01-18 at 16:33 -0500, Colin Burgess wrote: I see Intel has released a new tool. Oh, it requires some patches to the kernel to record latency times. Good thing people don't mind patching their kernels, eh? So who can write the equivalent latencytop.d the fastest? ;-) http://www.latencytop.org/ http://www.latencytop.org/ What I find interesting about these projects that Intel spawns for Linux (PowerTOP, LatencyTOP and couple of others) is that regardless of internal implementation they are very useful end user tools. Here at Sun we seem to be missing interest in creating such things. Which is a bit of a shame. They are ideal vehicles for disseminating DTrace knowledge and exposing neophytes to the raw power of DTrace. To be fair Greg's DTrace toolkit helps in that respect, but still it sets the bar pretty high for anybody who would like to use it. It is easy to poke fun at LatencyTOP, but asking the right question could sometimes be even more important than being able to deliver the answer. Just my 2c. Thanks, Roman. P.S. I was able to extend the battery time of my Linux laptop 1.5x using PowerTOP. Can the same thing be done with DTrace? Perhaps it can, but I don't think I can code it up. Solaris PowerTOP is almost done. http://www.opensolaris.org/os/project/tesla/Work/Powertop/ http://www.opensolaris.org/os/project/tesla/Work/Powertop/ -Aubrey Intel OpenSolaris Team -- [EMAIL PROTECTED] mailto:[EMAIL PROTECTED] ___ dtrace-discuss mailing list dtrace-discuss@opensolaris.org
Re: [dtrace-discuss] LatencyTop
On Jan 19, 2008 9:04 AM, Colin Burgess [EMAIL PROTECTED] wrote: Well I see that Brendan did reply to the OSNews link to this. He basically shot them down at hardcoding the instrumentation - as he should have! :-) Shame on Intel - they should know better! Colin I'm not a member of the linux LatencyTOP team. I haven't gotten a chance to see how is this tool implemented. But I totally disagree with you about it's a shame. Regardless of internal implementation, It's interesting and be very useful. At least, for end users, it helps to visualize system latencies. -Aubrey Intel OpenSolaris Team ___ dtrace-discuss mailing list dtrace-discuss@opensolaris.org
Re: [dtrace-discuss] LatencyTop
G'Day Folks,
On Fri, Jan 18, 2008 at 04:52:58PM -0500, Bryan Cantrill wrote:
On Fri, Jan 18, 2008 at 04:33:17PM -0500, Colin Burgess wrote:
I see Intel has released a new tool. Oh, it requires some patches to
the kernel to record
latency times. Good thing people don't mind patching their kernels, eh?
So who can write the equivalent latencytop.d the fastest? ;-)
Brendan, I'm sure -- if he hasn't by the time I'm writing this...
Aw, come on - I've barely had half an hour since I saw the message -
couldn't you have waited a bit longer before tempting me to reply? :)
It has about 40 statically defined trace points and I've coded 8 so far.
A bunch of these are specific to Linux, so I'd need to think of what was
the closest useful match for Solaris.
Anyway, here's where I'm at:
# ./latencytop.d
Tracing... Hit Ctrl-C to end.
Cause CountMaximumAverage
mutex lock 1080 usec30 usec
Reading from file 450 22822 usec 1900 usec
Cause CountMaximumAverage
mutex lock 211 usec10 usec
Reading from file 474 26716 usec 1836 usec
Cause CountMaximumAverage
mutex lock 285 usec48 usec
Reading from file 392 29972 usec 2312 usec
Cause CountMaximumAverage
mutex lock 19 1379 usec 574 usec
Writing to file 162 43011 usec 1655 usec
Reading from file 302 80847 usec 2945 usec
Cause CountMaximumAverage
mutex lock 1 8 usec 8 usec
Reading from file 468 22978 usec 1813 usec
[...]
Yes, I added a Count column since it proved of limited use without one.
Of course, bounding this to Count/Maximum/Average is also of limited use -
I'd really like to include distribution plots as well.
Source so far is (hot off the keyboard, so beware of typos):
--
#!/usr/sbin/dtrace -Cs
#pragma D option quiet
#define RW_READER 0x1
dtrace:::BEGIN
{
printf(Tracing... Hit Ctrl-C to end.\n);
}
/*
* Reading from file
* Writing to file
*/
io:::start
{
start[args[0]-b_edev, args[0]-b_blkno] = timestamp;
}
io:::done
/start[args[0]-b_edev, args[0]-b_blkno]/
{
this-delta = timestamp - start[args[0]-b_edev, args[0]-b_blkno];
this-cause = args[0]-b_flags B_READ ?
Reading from file : Writing to file;
@lcount[this-cause] = count();
@lmax[this-cause] = max(this-delta);
@lavg[this-cause] = avg(this-delta);
}
/*
* mutex lock
*/
lockstat:::adaptive-block
{
@lcount[mutex lock] = count();
@lmax[mutex lock] = max(arg1);
@lavg[mutex lock] = avg(arg1);
}
/*
* rwsem read lock
* rwsem write lock
*/
lockstat:::rw-block
{
this-cause = arg2 == RW_READER ?
rwsem read lock : rwsum write lock;
@lcount[this-cause] = count();
@lmax[this-cause] = max(arg1);
@lavg[this-cause] = avg(arg1);
}
/*
* Unlinking file
*/
syscall::unlink:entry
{
self-start_unlink = timestamp;
}
syscall::unlink:return
/self-start_unlink/
{
this-delta = timestamp - self-start_unlink;
@lcount[Unlink file] = count();
@lmax[Unlink file] = max(this-delta);
@lavg[Unlink file] = avg(this-delta);
self-start_unlink = 0;
}
/*
* sync system call
*/
syscall::syssync:entry
{
self-start_syssync = timestamp;
}
syscall::syssync:return
/self-start_syssync/
{
this-delta = timestamp - self-start_syssync;
@lcount[sync system call] = count();
@lmax[sync system call] = max(this-delta);
@lavg[sync system call] = avg(this-delta);
self-start_syssync = 0;
}
/*
* fsync system call
*/
syscall::fdsync:entry
{
self-start_fdsync = timestamp;
}
syscall::fdsync:return
/self-start_fdsync/
{
this-delta = timestamp - self-start_fdsync;
@lcount[fsync system call] = count();
@lmax[fsync system call] = max(this-delta);
@lavg[fsync system call] = avg(this-delta);
self-start_fdsync = 0;
}
/*
* Print output summary
*/
profile:::tick-1s,
dtrace:::END
{
normalize(@lmax, 1000);
normalize(@lavg, 1000);
printf( %-32s %12s %14s %14s\n, Cause, Count, Maximum,
Average);
printa( %-32s [EMAIL PROTECTED] [EMAIL PROTECTED] usec [EMAIL
PROTECTED] usec\n, @lcount, @lmax, @lavg);
printf(\n);
trunc(@lcount);
Re: [dtrace-discuss] LatencyTop
Well I see that Brendan did reply to the OSNews link to this. He basically shot them down at hardcoding the instrumentation - as he should have! :-) Shame on Intel - they should know better! Colin Bryan Cantrill wrote: On Fri, Jan 18, 2008 at 04:33:17PM -0500, Colin Burgess wrote: I see Intel has released a new tool. Oh, it requires some patches to the kernel to record latency times. Good thing people don't mind patching their kernels, eh? So who can write the equivalent latencytop.d the fastest? ;-) Brendan, I'm sure -- if he hasn't by the time I'm writing this... (Of course, that said it's a pretty lame tool. Isn't obvious that this is providing such paltry information that it's raising more questions than answers? Fine, better than nothing -- but not much better...) - Bryan -- Bryan Cantrill, Sun Microsystems Fishworks. http://blogs.sun.com/bmc http://blogs.sun.com/bmc -- [EMAIL PROTECTED] mailto:[EMAIL PROTECTED] ___ dtrace-discuss mailing list dtrace-discuss@opensolaris.org
Re: [dtrace-discuss] LatencyTop
On Fri, 2008-01-18 at 16:33 -0500, Colin Burgess wrote: I see Intel has released a new tool. Oh, it requires some patches to the kernel to record latency times. Good thing people don't mind patching their kernels, eh? So who can write the equivalent latencytop.d the fastest? ;-) http://www.latencytop.org/ What I find interesting about these projects that Intel spawns for Linux (PowerTOP, LatencyTOP and couple of others) is that regardless of internal implementation they are very useful end user tools. Here at Sun we seem to be missing interest in creating such things. Which is a bit of a shame. They are ideal vehicles for disseminating DTrace knowledge and exposing neophytes to the raw power of DTrace. To be fair Greg's DTrace toolkit helps in that respect, but still it sets the bar pretty high for anybody who would like to use it. It is easy to poke fun at LatencyTOP, but asking the right question could sometimes be even more important than being able to deliver the answer. Just my 2c. Thanks, Roman. P.S. I was able to extend the battery time of my Linux laptop 1.5x using PowerTOP. Can the same thing be done with DTrace? Perhaps it can, but I don't think I can code it up. ___ dtrace-discuss mailing list dtrace-discuss@opensolaris.org
Re: [dtrace-discuss] LatencyTop
LOL - you rock, Brendan.
You know, at the VERY least they could have used systemtap, I guess.
Colin
Brendan Gregg - Sun Microsystems wrote:
G'Day Folks,
On Fri, Jan 18, 2008 at 04:52:58PM -0500, Bryan Cantrill wrote:
On Fri, Jan 18, 2008 at 04:33:17PM -0500, Colin Burgess wrote:
I see Intel has released a new tool. Oh, it requires some patches to
the kernel to record
latency times. Good thing people don't mind patching their kernels, eh?
So who can write the equivalent latencytop.d the fastest? ;-)
Brendan, I'm sure -- if he hasn't by the time I'm writing this...
Aw, come on - I've barely had half an hour since I saw the message -
couldn't you have waited a bit longer before tempting me to reply? :)
It has about 40 statically defined trace points and I've coded 8 so far.
A bunch of these are specific to Linux, so I'd need to think of what was
the closest useful match for Solaris.
Anyway, here's where I'm at:
# ./latencytop.d
Tracing... Hit Ctrl-C to end.
Cause CountMaximum
Average
mutex lock 1080 usec30
usec
Reading from file 450 22822 usec 1900
usec
Cause CountMaximum
Average
mutex lock 211 usec10
usec
Reading from file 474 26716 usec 1836
usec
Cause CountMaximum
Average
mutex lock 285 usec48
usec
Reading from file 392 29972 usec 2312
usec
Cause CountMaximum
Average
mutex lock 19 1379 usec 574
usec
Writing to file 162 43011 usec 1655
usec
Reading from file 302 80847 usec 2945
usec
Cause CountMaximum
Average
mutex lock 1 8 usec 8
usec
Reading from file 468 22978 usec 1813
usec
[...]
Yes, I added a Count column since it proved of limited use without one.
Of course, bounding this to Count/Maximum/Average is also of limited use -
I'd really like to include distribution plots as well.
Source so far is (hot off the keyboard, so beware of typos):
--
#!/usr/sbin/dtrace -Cs
#pragma D option quiet
#define RW_READER 0x1
dtrace:::BEGIN
{
printf(Tracing... Hit Ctrl-C to end.\n);
}
/*
* Reading from file
* Writing to file
*/
io:::start
{
start[args[0]-b_edev, args[0]-b_blkno] = timestamp;
}
io:::done
/start[args[0]-b_edev, args[0]-b_blkno]/
{
this-delta = timestamp - start[args[0]-b_edev, args[0]-b_blkno];
this-cause = args[0]-b_flags B_READ ?
Reading from file : Writing to file;
@lcount[this-cause] = count();
@lmax[this-cause] = max(this-delta);
@lavg[this-cause] = avg(this-delta);
}
/*
* mutex lock
*/
lockstat:::adaptive-block
{
@lcount[mutex lock] = count();
@lmax[mutex lock] = max(arg1);
@lavg[mutex lock] = avg(arg1);
}
/*
* rwsem read lock
* rwsem write lock
*/
lockstat:::rw-block
{
this-cause = arg2 == RW_READER ?
rwsem read lock : rwsum write lock;
@lcount[this-cause] = count();
@lmax[this-cause] = max(arg1);
@lavg[this-cause] = avg(arg1);
}
/*
* Unlinking file
*/
syscall::unlink:entry
{
self-start_unlink = timestamp;
}
syscall::unlink:return
/self-start_unlink/
{
this-delta = timestamp - self-start_unlink;
@lcount[Unlink file] = count();
@lmax[Unlink file] = max(this-delta);
@lavg[Unlink file] = avg(this-delta);
self-start_unlink = 0;
}
/*
* sync system call
*/
syscall::syssync:entry
{
self-start_syssync = timestamp;
}
syscall::syssync:return
/self-start_syssync/
{
this-delta = timestamp - self-start_syssync;
@lcount[sync system call] = count();
@lmax[sync system call] = max(this-delta);
@lavg[sync system call] = avg(this-delta);
self-start_syssync = 0;
}
/*
* fsync system call
*/
syscall::fdsync:entry
{
self-start_fdsync = timestamp;
}
syscall::fdsync:return
/self-start_fdsync/
{
this-delta = timestamp - self-start_fdsync;
@lcount[fsync system call] = count();
@lmax[fsync system call] = max(this-delta);
@lavg[fsync system call] = avg(this-delta);
self-start_fdsync = 0;
}
/*
* Print output summary
*/
profile:::tick-1s,
dtrace:::END
{
normalize(@lmax, 1000);
normalize(@lavg, 1000);
