Re: [Patch] blkiomon: repost with some fixes and improvements

["Alan D. Brunelle" <Alan.Brunelle@hp.com>]

[-- Attachment #1: Type: text/plain, Size: 2904 bytes --]

Török Edwin wrote:
> On 2008-07-18 13:31, Martin Peschke wrote:
>> recent changes:
>> - added man page
>> - beautified human-readable output
>> - fixed an x86 compile error caused by incomplete endianess handling
>> - fixed some x86 __u64 vs. unsigned long compiler warnings
>> - fixed checking of a command line argument
>>
>>
>> blkiomon periodicaly generates per devive request size and request latency
>> statistics from blktrace data. It provides histograms as well as data that
>>   
> 
> Does it also measure latency caused by the request queues being full?
> (which happens around here):
> blk-core.c:get_request:
> /*
>                      * The queue is full and the allocating
>                      * process is not a "batcher", and not
>                      * exempted by the IO scheduler
>                      */
>                     goto out;
> 
> That would be very useful to trace some high latencies I am seeing, see
> discussion here:
> http://lkml.org/lkml/2008/7/12/104
> 
> Best regards,
> --Edwin

Hi Edwin -

If you could try this, it might provide some more data. This is very
hastily thrown together, so it may need some work. Basically: I wrote a
Python script which chains together blktrace | blkparse and takes the
output looking for sleep requests, and then a successful get request on
that same device. It then outputs min/avg/max as in:

   1 sleepers                         0.142157151
   1 sleepers                         0.174224178
   3 sleepers min=  0.027375521 avg=  0.048117339 max=  0.075909947
   1 sleepers                         0.132267452
   1 sleepers                         0.030572955
   2 sleepers min=  0.060603135 avg=  0.071087077 max=  0.081571020
   1 sleepers                         0.002082554
   1 sleepers                         0.033337675
   1 sleepers                         0.010796369

(with 1 sleeper, I leave off the min/max stuff). The values are in
seconds (so above I'm seeing 0.01 to 0.17+ seconds of sleeping...)

To run it (as root):

# ./qsg.py <device> [<device> ...]

So, for me:

# ./qsg.py /dev/sda

This will produce output only when sleeps-for-requests occur. (I think
other logic in the block I/O layer will put off other potential
requesters - I'm looking into how to measure that next.)

For now the script just assumes that the debugfs stuff is mounted at
/sys/kernel/debug...

Let me know if this needs some tweaking...

BTW: I can't seem to reproduce your problem (I do see the sleeps from my
script, but the system seems responsive otherwise). I have a 4-core
(dual-socket) Xeon box w/ 8GB RAM plus 5 SAS drives. I'm using Ubuntu
8.04 w/ an Ext3 FS for root (where I was running the test). I tried
bumping the dd' counts (large amount of RAM), but that didn't make a
difference.

I will try some more dd's just in case...

Alan

[-- Attachment #2: qsg.py --]
[-- Type: text/x-python, Size: 2828 bytes --]

#! /usr/bin/env python
"""
qsg.py [dev...]
"""

#
#  (C) Copyright 2008 Hewlett-Packard Development Company, L.P.
#
#  This program is free software; you can redistribute it and/or modify
#  it under the terms of the GNU General Public License as published by
#  the Free Software Foundation; either version 2 of the License, or
#  (at your option) any later version.
#
#  This program is distributed in the hope that it will be useful,
#  but WITHOUT ANY WARRANTY; without even the implied warranty of
#  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
#  GNU General Public License for more details.
#
#  You should have received a copy of the GNU General Public License
#  along with this program; if not, write to the Free Software
#  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
#

import os, sys

#
# Crazy stuff to get unbuffered output flowing through the pipeline -
# not a Python wiz, there are probably better ways...
#
def start_tracer(devs):
	(r, w) = os.pipe()
	pid = os.fork()
	if pid == 0:
		os.close(r)

		cmd = '/usr/local/bin/blktrace -o - -n 8 -b 512'
		for dev in devs: cmd = '%s -d %s' % (cmd, dev)
		cmd = cmd.split(None)

		fw = os.fdopen(w, 'w', 0)
		os.dup2(fw.fileno(), sys.stdout.fileno())

		os.execvp(cmd[0], cmd)
		sys.exit(1)
	else:
		os.close(w)
		return (pid, r)

def start_parser(devs):
	(trace_pid, tr) = start_tracer(devs)

	(r, w) = os.pipe()
	pid = os.fork()
	if pid == 0:
		os.close(r)

		fmt = '%D %a %T.%t\n'
		cmd = [ '/usr/local/bin/blkparse', '-q', '-i', '-', '-f', fmt ]
		print cmd

		os.dup2(tr, sys.stdin.fileno())
		fw = os.fdopen(w, 'w', 0)
		os.dup2(fw.fileno(), sys.stdout.fileno())

		os.execvp(cmd[0], cmd)
		sys.exit(1)
	else:
		os.close(w)
		fr = os.fdopen(r, 'r', 0)
		return (trace_pid, pid, fr)

def parse_line(line):
	fields = line.split(None)
	return fields[0], fields[1], float(fields[2])

if __name__ == '__main__':
	if len(sys.argv) < 2:
		print __doc__
		sys.exit(1)

	sleepers = {}
	devs = sys.argv[1:]

	(trace_pid, parse_pid, fi) = start_parser(devs)
	for line in fi:
		(dev, act, ts) = parse_line(line.rstrip())

		if not act in ['S', 'G']: continue
		if act == 'S':
			if not sleepers.has_key(dev):	sleepers[dev] = [ts]
			else:				sleepers[dev].append(ts)
			continue
		elif not sleepers.has_key(dev): continue

		mn = mx = None
		tot = 0.0
		nsleepers = 0
		for sleeper in sleepers[dev]:
			if ts < sleeper: continue

			nsleepers += 1
			dt = ts - sleeper
			if mn == None or dt < mn: mn = dt
			if mx == None or dt > mx: mx = dt
			tot += dt
		del sleepers[dev]

		if nsleepers == 0:
			continue

		print '%4d sleepers' % nsleepers,
		if nsleepers == 1:
			print '    %13s     %13.9f' % ('', tot)
		else:
			print 'min=%13.9f' % mn,
			print 'avg=%13.9f' % (tot / float(nsleepers)),
			print 'max=%13.9f' % mx