* blkparse not displaying all events when tracing >1 devices?
@ 2010-09-15 22:29 Brett Russ
2010-09-16 11:54 ` Alan D. Brunelle
0 siblings, 1 reply; 2+ messages in thread
From: Brett Russ @ 2010-09-15 22:29 UTC (permalink / raw)
To: linux-btrace
Hello,
If I trace *2* block devices (I only tried 1 or 2, not > 2) using a
single blktrace command, then blkparse the resulting output file set, I
get an abridged display of events to only one of the devices.
If I instead launch two separate blktrace commands, each to a single
block device and unique output file, then blkparse the resulting output
files independently, I appear to get all the events on each device.
FWIW, the two block devices are actually two paths to the same HDD but I
doubt that is relevant to this problem.
I'm pasting in my notes below. This was done using a build from a clone
of the blktrace git repo taken this afternoon.
> spu0103# blktrace -V
> blktrace version 2.0.0
First tried the multi-device syntax shown in the PDF users guide:
> spu0103# blktrace /dev/sdbk /dev/sdam -o 5 &
This program initiates SCSI commands to both devices and reads to one of
them:
> spu0103# nzgeninventory > nzgi.5 2>&1
> spu0103# killall blktrace
Evidently blktrace captured everything:
> spu0103# == sdbk => CPU 0: 0 events, 0 KiB data
> CPU 1: 4 events, 1 KiB data
> CPU 2: 5 events, 1 KiB data
> CPU 3: 5 events, 1 KiB data
> CPU 4: 5 events, 1 KiB data
> CPU 5: 0 events, 0 KiB data
> CPU 6: 1 events, 1 KiB data
> CPU 7: 1 events, 1 KiB data
> Total: 21 events (dropped 0), 2 KiB data
> == sdam => CPU 0: 9 events, 1 KiB data
> CPU 1: 7 events, 1 KiB data
> CPU 2: 6 events, 1 KiB data
> CPU 3: 6 events, 1 KiB data
> CPU 4: 6 events, 1 KiB data
> CPU 5: 10 events, 1 KiB data
> CPU 6: 6 events, 1 KiB data
> CPU 7: 11 events, 1 KiB data
> Total: 61 events (dropped 0), 4 KiB data
>
> [1]+ Done blktrace /dev/sdbk /dev/sdam -o 5
But blkparse shows me only some events from one of the devices:
> spu0103# blkparse -q -i 5
> Input file 5.blktrace.1 added
> Input file 5.blktrace.2 added
> Input file 5.blktrace.3 added
> Input file 5.blktrace.4 added
> Input file 5.blktrace.6 added
> Input file 5.blktrace.7 added
> 66,96 1 1 0.000000000 3786 G N [nzgeninventory.]
> 66,96 1 2 0.000002043 3786 P N [nzgeninventory.]
> 66,96 3 1 0.000496874 0 C R (12 00 00 00 24 00 ..) [0]
> 66,96 3 2 0.000597626 3786 G N [nzgeninventory.]
> 66,96 3 3 0.000599460 3786 P N [nzgeninventory.]
> 66,96 2 1 0.001022051 0 C R (12 00 00 00 a4 00 ..) [0]
> 66,96 2 2 0.001094954 3786 G N [nzgeninventory.]
> 66,96 2 3 0.001096781 3786 P N [nzgeninventory.]
> 66,96 4 1 0.001705551 0 C R (12 01 83 00 fc 00 ..) [0]
> 66,96 4 2 0.002156748 3786 G N [nzgeninventory.]
> 66,96 4 3 0.002158788 3786 P N [nzgeninventory.]
Let's try two separate instances of blktrace?
> spu0103# blktrace /dev/sdbk -o 6a &
> spu0103# blktrace /dev/sdam -o 6b &
> spu0103# nzgeninventory > nzgi.6 2>&1
> spu0103# killall blktrace
Same # of events captured:
> spu0103# == sdbk => CPU 0: 1 events, 1 KiB data
> CPU 1: 0 events, 0 KiB data
> CPU 2: 1 events, 1 KiB data
> CPU 3: 0 events, 0 KiB data
> CPU 4: 4 events, 1 KiB data
> CPU 5: 5 events, 1 KiB data
> CPU 6: 5 events, 1 KiB data
> CPU 7: 5 events, 1 KiB data
> Total: 21 events (dropped 0), 2 KiB data
> == sdam => CPU 0: 10 events, 1 KiB data
> CPU 1: 9 events, 1 KiB data
> CPU 2: 7 events, 1 KiB data
> CPU 3: 9 events, 1 KiB data
> CPU 4: 6 events, 1 KiB data
> CPU 5: 6 events, 1 KiB data
> CPU 6: 6 events, 1 KiB data
> CPU 7: 8 events, 1 KiB data
> Total: 61 events (dropped 0), 4 KiB data
>
> [2]+ Done blktrace /dev/sdam -o 6b
> [1]+ Done blktrace /dev/sdbk -o 6a
But this time the blkparse output is what I expect:
> spu0103# blkparse -q -i 6a
> Input file 6a.blktrace.0 added
> Input file 6a.blktrace.2 added
> Input file 6a.blktrace.4 added
> Input file 6a.blktrace.5 added
> Input file 6a.blktrace.6 added
> Input file 6a.blktrace.7 added
> 67,224 4 1 0.000000000 4247 G N [(null)]
> 67,224 4 2 0.000002179 4247 P N [(null)]
> 67,224 4 3 0.000002361 4247 I R 36 (12 00 00 00 24 00 ..) [(null)]
> 67,224 4 4 0.000003055 4247 D R 36 (12 00 00 00 24 00 ..) [(null)]
> 67,224 6 1 0.000498033 0 C R (12 00 00 00 24 00 ..) [0]
> 67,224 6 2 0.000583480 4247 G N [(null)]
> 67,224 6 3 0.000585724 4247 P N [(null)]
> 67,224 6 4 0.000585880 4247 I R 164 (12 00 00 00 a4 00 ..) [(null)]
> 67,224 6 5 0.000586369 4247 D R 164 (12 00 00 00 a4 00 ..) [(null)]
> 67,224 5 1 0.000996791 0 C R (12 00 00 00 a4 00 ..) [0]
> 67,224 5 2 0.001057014 4247 G N [(null)]
> 67,224 5 3 0.001059622 4247 P N [(null)]
> 67,224 5 4 0.001059775 4247 I R 252 (12 01 83 00 fc 00 ..) [(null)]
> 67,224 5 5 0.001065073 4247 D R 252 (12 01 83 00 fc 00 ..) [(null)]
> 67,224 7 1 0.001683205 0 C R (12 01 83 00 fc 00 ..) [0]
> 67,224 7 2 0.001989782 4247 G N [(null)]
> 67,224 7 3 0.001991606 4247 P N [(null)]
> 67,224 7 4 0.001991753 4247 I R 252 (12 01 80 00 fc 00 ..) [(null)]
> 67,224 7 5 0.001992269 4247 D R 252 (12 01 80 00 fc 00 ..) [(null)]
> 67,224 0 1 0.002599310 0 C R (12 01 80 00 fc 00 ..) [0]
>
> spu0103# blkparse -q -i 6b
> Input file 6b.blktrace.0 added
> Input file 6b.blktrace.1 added
> Input file 6b.blktrace.2 added
> Input file 6b.blktrace.3 added
> Input file 6b.blktrace.4 added
> Input file 6b.blktrace.5 added
> Input file 6b.blktrace.6 added
> Input file 6b.blktrace.7 added
> 66,96 2 1 0.000000000 4247 G N [nzgeninventory.]
> 66,96 2 2 0.000002148 4247 P N [nzgeninventory.]
> 66,96 2 3 0.000002316 4247 I R 36 (12 00 00 00 24 00 ..) [nzgeninventory.]
> 66,96 2 4 0.000002955 4247 D R 36 (12 00 00 00 24 00 ..) [nzgeninventory.]
> 66,96 4 1 0.000419015 0 C R (12 00 00 00 24 00 ..) [0]
> 66,96 4 2 0.000490802 4247 G N [nzgeninventory.]
> 66,96 4 3 0.000493304 4247 P N [nzgeninventory.]
> 66,96 4 4 0.000493454 4247 I R 164 (12 00 00 00 a4 00 ..) [nzgeninventory.]
> 66,96 4 5 0.000493973 4247 D R 164 (12 00 00 00 a4 00 ..) [nzgeninventory.]
> 66,96 6 1 0.000909171 0 C R (12 00 00 00 a4 00 ..) [0]
> 66,96 6 2 0.000967297 4247 G N [nzgeninventory.]
> 66,96 6 3 0.000969818 4247 P N [nzgeninventory.]
> 66,96 6 4 0.000970016 4247 I R 252 (12 01 83 00 fc 00 ..) [nzgeninventory.]
> 66,96 6 5 0.000970634 4247 D R 252 (12 01 83 00 fc 00 ..) [nzgeninventory.]
> 66,96 5 1 0.001573121 0 C R (12 01 83 00 fc 00 ..) [0]
> 66,96 5 2 0.001883295 4247 G N [nzgeninventory.]
> 66,96 5 3 0.001885647 4247 P N [nzgeninventory.]
> 66,96 5 4 0.001885878 4247 I R 252 (12 01 80 00 fc 00 ..) [nzgeninventory.]
> 66,96 5 5 0.001886469 4247 D R 252 (12 01 80 00 fc 00 ..) [nzgeninventory.]
> 66,96 7 1 0.002486674 0 C R (12 01 80 00 fc 00 ..) [0]
> 66,96 7 2 0.002682738 4247 G N [nzgeninventory.]
> 66,96 7 3 0.002684715 4247 P N [nzgeninventory.]
> 66,96 7 4 0.002684877 4247 I R 252 (25 00 ..) [nzgeninventory.]
> 66,96 7 5 0.002685351 4247 D R 252 (25 00 ..) [nzgeninventory.]
> 66,96 0 1 0.003222215 0 C R (25 00 ..) [0]
> 66,96 0 2 0.003387279 4247 A R 2112 + 1 <- (66,97) 2049
> 66,96 0 3 0.003387516 4247 Q R 2112 + 1 [nzgeninventory.]
> 66,96 0 4 0.003388578 4247 G R 2112 + 1 [nzgeninventory.]
> 66,96 0 5 0.003389361 4247 P N [nzgeninventory.]
> 66,96 0 6 0.003389889 4247 I R 2112 + 1 [nzgeninventory.]
> 66,96 0 7 0.003390646 4247 U N [nzgeninventory.] 1
> 66,96 0 8 0.003391420 4247 D R 2112 + 1 [nzgeninventory.]
> 66,96 1 1 0.003547936 0 C R 2112 + 1 [0]
> 66,96 1 2 0.003743980 4247 A R 1197744189 + 1 <- (66,99) 2049
> 66,96 1 3 0.003744226 4247 Q R 1197744189 + 1 [nzgeninventory.]
> 66,96 1 4 0.003745333 4247 G R 1197744189 + 1 [nzgeninventory.]
> 66,96 1 5 0.003746269 4247 P N [nzgeninventory.]
> 66,96 1 6 0.003746782 4247 I R 1197744189 + 1 [nzgeninventory.]
> 66,96 1 7 0.003747532 4247 U N [nzgeninventory.] 1
> 66,96 1 8 0.003748303 4247 D R 1197744189 + 1 [nzgeninventory.]
> 66,96 3 1 0.003903074 0 C R 1197744189 + 1 [0]
> 66,96 3 2 0.004043041 4247 A R 1944782754 + 1 <- (66,100) 2049
> 66,96 3 3 0.004043263 4247 Q R 1944782754 + 1 [nzgeninventory.]
> 66,96 3 4 0.004044337 4247 G R 1944782754 + 1 [nzgeninventory.]
> 66,96 3 5 0.004045072 4247 P N [nzgeninventory.]
> 66,96 3 6 0.004045558 4247 I R 1944782754 + 1 [nzgeninventory.]
> 66,96 3 7 0.004046260 4247 U N [nzgeninventory.] 1
> 66,96 3 8 0.004047013 4247 D R 1944782754 + 1 [nzgeninventory.]
> 66,96 2 5 0.004201336 0 C R 1944782754 + 1 [0]
I tried the '-m' (show missing events) option shown in the PDF for
blkparse, but it doesn't appear to be a valid option. I don't think
that it was intended for this purpose anyway...
> spu0103# blkparse -q -m -i 7
> blkparse: invalid option -- 'm'
I also tried an alternate form of launching blktrace, this had no impact:
> spu0103# blktrace -d /dev/sdbk -d /dev/sdam -o 7 &
I assume the problem lies in blkparse. At least I have a workaround.
Thanks,
Brett
^ permalink raw reply [flat|nested] 2+ messages in thread
* Re: blkparse not displaying all events when tracing >1 devices?
2010-09-15 22:29 blkparse not displaying all events when tracing >1 devices? Brett Russ
@ 2010-09-16 11:54 ` Alan D. Brunelle
0 siblings, 0 replies; 2+ messages in thread
From: Alan D. Brunelle @ 2010-09-16 11:54 UTC (permalink / raw)
To: linux-btrace
Hm, well, the problem is (I believe) that with the "-o" option just
isn't designed to work with multiple devices.
Brett: The simplest thing to do for your example would be:
# blktrace /dev/sdbk /dev/sdam
...
# blkparse -q sdbk sdam
Basically, listing each device used on the blkparse line. [That's how I
(and presumably everyone else) has always done it.]
The technical reason why "-o" doesn't work with multiple devices is
because we use multiple threads of execution - one per device/CPU pair -
and each of them opens a file named "<prefix>.blktrace.<cpu>". With the
"-o" all of the "<prefix>" values are the same - so multiple threads
open the same file and try to do output. Not good. Without the "-o" we
get unique files named: "<device>.blktrace.<cpu>" - as the tuple
(<device>,<cpu>) is unique.
I suppose we could change the definition of "-o" to be:
"<prefix>.<device>.blktrace.<cpu>" - but I don't know what else this
would break. So, I think what I'll do is update the documentation to
just note that "-o" doesn't work with multiple devices.
Regards,
Alan
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2010-09-16 11:54 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2010-09-15 22:29 blkparse not displaying all events when tracing >1 devices? Brett Russ
2010-09-16 11:54 ` Alan D. Brunelle
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).