[dtrace-discuss] LatencyTop

[Colin Burgess]

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                                   Count        Maximum
Average 
  mutex lock                                 10        80 usec        30
usec 
  Reading from file                         450     22822 usec      1900
usec 

  Cause                                   Count        Maximum
Average 
  mutex lock                                  2        11 usec        10
usec 
  Reading from file                         474     26716 usec      1836
usec 

  Cause                                   Count        Maximum
Average 
  mutex lock                                  2        85 usec        48
usec 
  Reading from file                         392     29972 usec      2312
usec 

  Cause                                   Count        Maximum
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                                   Count        Maximum
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); 

        printf("  %-32s %12s %14s %14s\n", "Cause", "Count", "Maximum", 
            "Average"); 
        printa("  %-32s %@12d %@9d usec %@9d usec\n", @lcount, @lmax,
@lavg); 
        printf("\n"); 

        trunc(@lcount); 
        trunc(@lmax); 
        trunc(@lavg); 
} 
-------------------------------------------------------------- 

I'll add some more later - I have other work to be doing right now. :) 
If anyone would like to work on some of the other metrics, please do and 
post the bits here. 

> (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...) 

Yes, not that impressive.  Although getting customers to look and think 
about latency is certainly worthwhile, and the start of the road to DTrace. 

Brendan 

-- 
Brendan 
[CA, USA] 


-- 

cburgess at qnx.com <mailto:cburgess at qnx.com>