Re: bad trace magic

[Martin Peschke <mpeschke@linux.vnet.ibm.com>]

On Wed, 2008-11-19 at 13:44 +0100, Jens Axboe wrote:
> How are you running blktrace?

blktrace -a issue -a drv_data -a complete -w 43200 -o
- /dev/sda ... /dev/sdz | blkiomon

> If you have the blktrace output files, you
> can inspect what it would have done next.

I am concerned about pdu_len being some random number then.
I don't think blktrace would find a valid trace after taking a random
number of bytes for a trace payload.

> > Sequence numbers appear to jump, from 183e8 to f1b1 in this case:
> > 
> > --- bad trace magic ---
> > magic    0x00000001
> > sequence 0x0001007a
> > time     0x000000000000fb40
> > sector   0x000000000005925e
> > bytes    0x65617407
> > action   0x0000f1b1
> > pid      0x00000773
> > device   0xec86baa8
> > cpu      0x00000000
> > error    0x007f
> > pdu_len  0x8430
> > 
> > 00000001 0001007a 00000000 0000fb40 00000000 0005925e 65617407 0000f1b1
> > 00000773 ec86baa8 00000000 007f8430
> 
> So that's interesting. What byte offset did this happen at? And what is
> your subbuffer size for blktrace?

see tip_subbuf output (from flush_subbuf_file()) below

--- bad trace magic ---
magic    0x00017000
sequence 0x40010011
time     0x0000346f04100080
sector   0x0000000100000018
bytes    0x00000001
action   0x00010080
pid      0x00000000
device   0x0000bbea
cpu      0x00000000
error    0x0014
pdu_len  0x8d98

00017000 40010011 0000346f 04100080 00000001 00000018
00000001 00010080 00000000 0000bbea 00000000 00148d98

bad trace in /sys/kernel/debug/block/sdy/trace1

ts->buf 0x2004c5027c0, ts->len 0x108, ts->max_len 0x80000,
offset 0x48, t 0x2004c502808

--- previous trace ---
magic    0x65617407
sequence 0x0001a232
time     0x00000e5bb87cd096
sector   0x0000000000843c08
bytes    0x00001000
action   0x40010011
pid      0x00003467
device   0x04100080
cpu      0x00000001
error    0x0000
pdu_len  0x0018

65617407 0001a232 00000e5b b87cd096 00000000 00843c08
00001000 40010011 00003467 04100080 00000001 00000018


--- bad trace magic ---
magic    0x00001000
sequence 0x09410007
time     0x00003469008000c0
sector   0x0000000000000000
bytes    0x65617407
action   0x0000fae2
pid      0x00000e44
device   0xbbefaa91
cpu      0x00000000
error    0x008f
pdu_len  0xd358

00001000 09410007 00003469 008000c0 00000000 00000000
65617407 0000fae2 00000e44 bbefaa91 00000000 008fd358

bad trace in /sys/kernel/debug/block/sdm/trace0

ts->buf 0x20060280910, ts->len 0xc00, ts->max_len 0x80000,
offset 0xf0, t 0x20060280a00

--- previous trace ---
magic    0x65617407
sequence 0x0000fadd
time     0x65617407000067d8
sector   0x00000d9ba13e3b74
bytes    0x00000000
action   0x00500030
pid      0x00001000
device   0x40010011
cpu      0x00003466
error    0x0080
pdu_len  0x00c0

65617407 0000fadd 65617407 000067d8 00000d9b a13e3b74
00000000 00500030 00001000 40010011 00003466 008000c0