[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <20090325114720.GA9762@elte.hu>
Date: Wed, 25 Mar 2009 12:47:20 +0100
From: Ingo Molnar <mingo@...e.hu>
To: Jens Axboe <jens.axboe@...cle.com>
Cc: Li Zefan <lizf@...fujitsu.com>,
Arnaldo Carvalho de Melo <acme@...hat.com>,
Steven Rostedt <rostedt@...dmis.org>,
Frederic Weisbecker <fweisbec@...il.com>,
LKML <linux-kernel@...r.kernel.org>
Subject: Re: [PATCH 3/3] blktrace: fix the original blktrace
* Jens Axboe <jens.axboe@...cle.com> wrote:
> On Wed, Mar 25 2009, Ingo Molnar wrote:
> >
> > * Li Zefan <lizf@...fujitsu.com> wrote:
> >
> > > Currently the original blktrace, which is using relay and is used
> > > via ioctl, is broken. You can use ftrace to see the output of
> > > blktrace, but user-space blktrace is unusable.
> >
> > good catch, thanks Li!
> >
> > Jens, Arnaldo, do these fixes look good to you too?
>
> Look fine, but I'm very worried about the state of the current
> code. I mean, this last round of fixes got the timestamp correct
> and made blktrace work again. [...]
Correct. I tested it on a 16way box (see the blkparse output below).
If you can see any sort of anomaly please let us know so we can fix
it.
> [...] Those are something that should have been caught even before
> the whole thing was posted, let alone merged. When do you plan on
> pushing this upstream? Looks like 2.6.31 to me, it's clearly not
> ready for 2.6.30 by any stretch.
Well, apparently nobody tried ioctl based blktrace+blkparse on -tip
or linux-next in the past ~1 month. The relayfs portion was (meant
to be) kept largely untouched but this bug still crept in.
Li started looking into it and found the bug. I tested the ftrace
plugin side regularly, but you are right that this bug took too long
to find (over a month) - from now on i'll check the ioctl side more
regularly too, for all tracing and relayfs changes as well.
Ingo
---------------->
8,0 13 1 0.000000000 6219 A R 20475199 + 128 <- (8,1) 20475136
8,0 13 2 0.000000721 6219 Q R 20475199 + 128 [cc1]
8,0 13 3 0.000008680 6219 G R 20475199 + 128 [cc1]
8,0 13 4 0.000010792 6219 P N [cc1]
8,0 13 5 0.000012401 6219 I R 20475199 + 128 [cc1]
8,0 13 6 0.000016097 6219 U N [cc1] 1
8,0 13 7 0.000023499 6219 D R 20475199 + 128 [cc1]
8,0 10 1 0.018127785 0 C R 20475199 + 128 [0]
8,0 10 2 0.347266011 1059 A W 20423 + 8 <- (8,1) 20360
8,0 10 3 0.347266724 1059 Q W 20423 + 8 [kjournald]
8,0 10 4 0.347271298 1059 G W 20423 + 8 [kjournald]
8,0 10 5 0.347273197 1059 P N [kjournald]
8,0 10 6 0.347274678 1059 I W 20423 + 8 [kjournald]
8,0 10 7 0.347315501 1059 A W 20431 + 8 <- (8,1) 20368
8,0 10 8 0.347315665 1059 Q W 20431 + 8 [kjournald]
[...]
8,0 10 17481 16.338721149 1059 M W 22047 + 8 [kjournald]
8,0 10 17482 16.338721545 1059 A W 22055 + 8 <- (8,1) 21992
8,0 10 17483 16.338721701 1059 Q W 22055 + 8 [kjournald]
8,0 10 17484 16.338721887 1059 M W 22055 + 8 [kjournald]
8,0 10 17485 16.338722389 1059 A W 22063 + 8 <- (8,1) 22000
8,0 10 17486 16.338722551 1059 Q W 22063 + 8 [kjournald]
8,0 10 17487 16.338722810 1059 M W 22063 + 8 [kjournald]
8,0 10 17488 16.338723586 1059 A W 22071 + 8 <- (8,1) 22008
8,0 10 17489 16.338723764 1059 Q W 22071 + 8 [kjournald]
8,0 10 17490 16.338723989 1059 M W 22071 + 8 [kjournald]
8,0 10 17491 16.338724547 1059 A W 22079 + 8 <- (8,1) 22016
8,0 10 17492 16.338724724 1059 Q W 22079 + 8 [kjournald]
8,0 10 17493 16.338724989 1059 M W 22079 + 8 [kjournald]
8,0 10 17494 16.338725489 1059 A W 22087 + 8 <- (8,1) 22024
8,0 10 17495 16.338725656 1059 Q W 22087 + 8 [kjournald]
8,0 10 17496 16.338725863 1059 M W 22087 + 8 [kjournald]
8,0 10 17497 16.338726383 1059 A W 22095 + 8 <- (8,1) 22032
8,0 10 17498 16.338726540 1059 Q W 22095 + 8 [kjournald]
8,0 10 17499 16.338726819 1059 M W 22095 + 8 [kjournald]
8,0 10 17500 16.338727300 1059 A W 22103 + 8 <- (8,1) 22040
8,0 10 17501 16.338727448 1059 Q W 22103 + 8 [kjournald]
8,0 10 17502 16.338727651 1059 M W 22103 + 8 [kjournald]
8,0 10 17503 16.338728145 1059 A W 22111 + 8 <- (8,1) 22048
8,0 10 17504 16.338728304 1059 Q W 22111 + 8 [kjournald]
8,0 10 17505 16.338728568 1059 M W 22111 + 8 [kjournald]
8,0 10 17506 16.338729100 1059 A W 22119 + 8 <- (8,1) 22056
8,0 10 17507 16.338729251 1059 Q W 22119 + 8 [kjournald]
8,0 10 17508 16.338729469 1059 M W 22119 + 8 [kjournald]
8,0 10 17509 16.338729980 1059 A W 22127 + 8 <- (8,1) 22064
8,0 10 17510 16.338730133 1059 Q W 22127 + 8 [kjournald]
8,0 10 17511 16.338730381 1059 M W 22127 + 8 [kjournald]
8,0 10 17512 16.338731606 1059 U N [kjournald] 1
8,0 10 17513 16.338740396 1059 D W 21679 + 456 [kjournald]
8,0 10 17514 16.341011279 7516 C W 21679 + 456 [0]
8,0 10 17515 16.341075110 1059 A W 22135 + 8 <- (8,1) 22072
8,0 10 17516 16.341075415 1059 Q W 22135 + 8 [kjournald]
8,0 10 17517 16.341077704 1059 G W 22135 + 8 [kjournald]
8,0 10 17518 16.341079074 1059 P N [kjournald]
8,0 10 17519 16.341079897 1059 I W 22135 + 8 [kjournald]
8,0 10 17520 16.341082865 1059 U N [kjournald] 1
8,0 10 17521 16.341088012 1059 D W 22135 + 8 [kjournald]
8,0 10 17522 16.341507489 7516 C W 22135 + 8 [0]
8,0 0 1 16.849527724 6225 U N [distccd] 0
CPU0 (sda):
Reads Queued: 0, 0KiB Writes Queued: 0, 0KiB
Read Dispatches: 0, 0KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 1 Timer unplugs: 0
CPU1 (sda):
Reads Queued: 0, 0KiB Writes Queued: 0, 0KiB
Read Dispatches: 0, 0KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 2 Timer unplugs: 0
CPU5 (sda):
Reads Queued: 0, 0KiB Writes Queued: 0, 0KiB
Read Dispatches: 0, 0KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 1 Timer unplugs: 0
CPU6 (sda):
Reads Queued: 0, 0KiB Writes Queued: 0, 0KiB
Read Dispatches: 0, 0KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 3 Timer unplugs: 0
CPU8 (sda):
Reads Queued: 0, 0KiB Writes Queued: 0, 0KiB
Read Dispatches: 0, 0KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 8 Timer unplugs: 0
CPU9 (sda):
Reads Queued: 1, 4KiB Writes Queued: 0, 0KiB
Read Dispatches: 1, 4KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 20 Timer unplugs: 0
CPU10 (sda):
Reads Queued: 1, 24KiB Writes Queued: 5,647, 22,588KiB
Read Dispatches: 1, 24KiB Write Dispatches: 160, 22,588KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 4, 108KiB Writes Completed: 184, 22,684KiB
Read Merges: 0, 0KiB Write Merges: 5,487, 21,948KiB
Read depth: 1 Write depth: 32
IO unplugs: 35 Timer unplugs: 0
CPU11 (sda):
Reads Queued: 0, 0KiB Writes Queued: 24, 96KiB
Read Dispatches: 0, 0KiB Write Dispatches: 24, 96KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 1 Timer unplugs: 0
CPU12 (sda):
Reads Queued: 0, 0KiB Writes Queued: 0, 0KiB
Read Dispatches: 0, 0KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 3 Timer unplugs: 0
CPU13 (sda):
Reads Queued: 2, 80KiB Writes Queued: 0, 0KiB
Read Dispatches: 2, 80KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 15 Timer unplugs: 0
CPU15 (sda):
Reads Queued: 0, 0KiB Writes Queued: 0, 0KiB
Read Dispatches: 0, 0KiB Write Dispatches: 0, 0KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 1 Write depth: 32
IO unplugs: 3 Timer unplugs: 0
Total (sda):
Reads Queued: 4, 108KiB Writes Queued: 5,671, 22,684KiB
Read Dispatches: 4, 108KiB Write Dispatches: 184, 22,684KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 4, 108KiB Writes Completed: 184, 22,684KiB
Read Merges: 0, 0KiB Write Merges: 5,487, 21,948KiB
IO unplugs: 92 Timer unplugs: 0
Throughput (R/W): 6KiB/s / 1,346KiB/s
Events (sda): 17,723 entries
Skips: 0 forward (0 - 0.0%)
Input file sda.blktrace.0 added
Input file sda.blktrace.1 added
Input file sda.blktrace.5 added
Input file sda.blktrace.6 added
Input file sda.blktrace.8 added
Input file sda.blktrace.9 added
Input file sda.blktrace.10 added
Input file sda.blktrace.11 added
Input file sda.blktrace.12 added
Input file sda.blktrace.13 added
Input file sda.blktrace.15 added
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists