From: Ingo Molnar <mingo@elte.hu>
To: Jens Axboe <jens.axboe@oracle.com>
Cc: Li Zefan <lizf@cn.fujitsu.com>,
Arnaldo Carvalho de Melo <acme@redhat.com>,
Steven Rostedt <rostedt@goodmis.org>,
Frederic Weisbecker <fweisbec@gmail.com>,
LKML <linux-kernel@vger.kernel.org>
Subject: Re: [PATCH 3/3] blktrace: fix the original blktrace
Date: Wed, 25 Mar 2009 12:47:20 +0100 [thread overview]
Message-ID: <20090325114720.GA9762@elte.hu> (raw)
In-Reply-To: <20090325101747.GL27476@kernel.dk>
* Jens Axboe <jens.axboe@oracle.com> wrote:
> On Wed, Mar 25 2009, Ingo Molnar wrote:
> >
> > * Li Zefan <lizf@cn.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
next prev parent reply other threads:[~2009-03-25 11:47 UTC|newest]
Thread overview: 19+ messages / expand[flat|nested] mbox.gz Atom feed top
2009-03-25 9:18 [PATCH 1/3] blktrace: fix timestamp in binary output Li Zefan
2009-03-25 9:19 ` [PATCH 2/3] blktrace: fix a race when creating blk_tree_root in debugfs Li Zefan
2009-03-25 11:54 ` [tip:tracing/blktrace] " Li Zefan
2009-03-25 9:21 ` [PATCH 3/3] blktrace: fix the original blktrace Li Zefan
2009-03-25 10:14 ` Ingo Molnar
2009-03-25 10:17 ` Jens Axboe
2009-03-25 11:47 ` Ingo Molnar [this message]
2009-03-25 13:51 ` Arnaldo Carvalho de Melo
2009-03-25 13:56 ` Jens Axboe
2009-03-25 14:07 ` Arnaldo Carvalho de Melo
2009-03-26 2:13 ` Li Zefan
2009-03-26 8:29 ` Jens Axboe
2009-03-26 13:37 ` Ingo Molnar
2009-03-26 15:14 ` Arnaldo Carvalho de Melo
2009-03-26 15:44 ` Jens Axboe
2009-03-26 17:07 ` Arnaldo Carvalho de Melo
2009-03-27 0:21 ` Li Zefan
2009-03-25 11:54 ` [tip:tracing/blktrace] " Li Zefan
2009-03-25 11:54 ` [tip:tracing/blktrace] blktrace: fix timestamp in binary output Li Zefan
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20090325114720.GA9762@elte.hu \
--to=mingo@elte.hu \
--cc=acme@redhat.com \
--cc=fweisbec@gmail.com \
--cc=jens.axboe@oracle.com \
--cc=linux-kernel@vger.kernel.org \
--cc=lizf@cn.fujitsu.com \
--cc=rostedt@goodmis.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox