running iozone on bcache0 device yields wrongly read data

Hi all

I've spent some time on IRC today (thanks eegiks for input) but I fear the problem I encountered is not solved yet.

http://pastebin.com/t0di2MKi

has some kind of summary on which kind of machine I am running and what command lines switches I use for iozone. It seems I need to go at least to -s 1g to start triggering this issue (latest run output attached).

I've tried it with an almost vanilla 3.11.0 and a patched 3.11.1+bcache-for-3.11 kernel but both show this issue. A cross test on a similar host but only using an HDD did not show this issue.

Any clues/hints how to figure out if this is caused by the underlying hardware or if this is something internal to bcache? What else would you need as input? Shall I switch on debugging and what can I do to help you figure out what's wrong?

Cheers

Carsten

Dr. Carsten Aulbert - Max Planck Institute for Gravitational Physics
Callinstrasse 38, 30167 Hannover, Germany
phone/fax: +49 511 762-17185 / -17193
https://wiki.atlas.aei.uni-hannover.de/foswiki/bin/view/ATLAS/WebHome

Iozone: Performance Test of File I/O
Version $Revision: 3.397 $
Compiled for 64 bit mode.
Build: linux-AMD64

Contributors:William Norcott, Don Capps, Isom Crawford, Kirby Collins
Al Slater, Scott Rhine, Mike Wisner, Ken Goss Steve Landherr, Brad Smith, Mark Kelly, Dr. Alain CYR, Randy Dunlap, Mark Montague, Dan Million, Gavin Brebner, Jean-Marc Zucconi, Jeff Blomberg, Benny Halevy, Dave Boone, Erik Habbinga, Kris Strecker, Walter Wong, Joshua Root, Fabrice Bacchella, Zhenghua Xue, Qin Li, Darren Sawyer. Ben England.

Run began: Tue Sep 17 18:39:01 2013

Excel chart generation enabled
Include fsync in write timing
File size set to 2097152 KB

Machine = Linux cass1 3.11.1-atlas #3 SMP Tue Sep 17 18:26:12 CEST 2013 x86_64 Record Size 128 KB
Record Size 128 KB
Command line used: iozone -R -e -s 2g -t 32 -M -r 128k Output is in Kbytes/sec
Time Resolution = 0.000001 seconds.
Processor cache size set to 1024 Kbytes.
Processor cache line size set to 32 bytes.
File stride size set to 17 * record size. Throughput test with 32 processes
Each process writes a 2097152 Kbyte file in 128 Kbyte records

Children see throughput for 32 initial writers = 81557.54 KB/sec
Parent sees throughput for 32 initial writers = 79863.75 KB/sec
Min throughput per process = 2480.14 KB/sec
Max throughput per process = 2609.36 KB/sec
Avg throughput per process = 2548.67 KB/sec
Min xfer = 2011904.00 KB

Children see throughput for 32 rewriters = 79110.97 KB/sec
Parent sees throughput for 32 rewriters = 78721.56 KB/sec
Min throughput per process = 2440.14 KB/sec
Max throughput per process = 2573.24 KB/sec
Avg throughput per process = 2472.22 KB/sec
Min xfer = 2015616.00 KB

Children see throughput for 32 readers = 63335.91 KB/sec
Parent sees throughput for 32 readers = 63320.14 KB/sec
Min throughput per process = 1901.33 KB/sec
Max throughput per process = 2106.96 KB/sec
Avg throughput per process = 1979.25 KB/sec
Min xfer = 1892608.00 KB

Children see throughput for 32 re-readers = 66402.77 KB/sec
Parent sees throughput for 32 re-readers = 66381.13 KB/sec
Min throughput per process = 1966.24 KB/sec
Max throughput per process = 2207.88 KB/sec
Avg throughput per process = 2075.09 KB/sec
Min xfer = 1867776.00 KB

Children see throughput for 32 reverse readers = 28092.60 KB/sec
Parent sees throughput for 32 reverse readers = 28089.99 KB/sec
Min throughput per process = 810.85 KB/sec
Max throughput per process = 949.42 KB/sec
Avg throughput per process = 877.89 KB/sec
Min xfer = 1791360.00 KB

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff202000 Error in file: Position 1172054016
Record # 8942 Record size 128 kb
where 7ff9ff202000 loop 8192

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1156698112
Record # 8824 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20a000 Error in file: Position 1205641216
Record # 9198 Record size 128 kb
where 7ff9ff20a000 loop 40960

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1232588800
Record # 9403 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 920768512
Record # 7024 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 983289856
Record # 7501 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 876335104
Record # 6685 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20e000 Error in file: Position 990044160
Record # 7553 Record size 128 kb
where 7ff9ff20e000 loop 57344

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1110298624
Record # 8470 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20a000 Error in file: Position 898801664
Record # 6857 Record size 128 kb
where 7ff9ff20a000 loop 40960

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1036898304
Record # 7910 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1052495872
Record # 8029 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 996921344
Record # 7605 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff202000 Error in file: Position 967843840
Record # 7384 Record size 128 kb
where 7ff9ff202000 loop 8192

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff202000 Error in file: Position 1025777664
Record # 7826 Record size 128 kb
where 7ff9ff202000 loop 8192

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20a000 Error in file: Position 1110482944
Record # 8472 Record size 128 kb
where 7ff9ff20a000 loop 40960

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 925618176
Record # 7061 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff202000 Error in file: Position 1143873536
Record # 8727 Record size 128 kb
where 7ff9ff202000 loop 8192

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20e000 Error in file: Position 803135488
Record # 6127 Record size 128 kb
where 7ff9ff20e000 loop 57344

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1166135296
Record # 8896 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1035194368
Record # 7897 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff202000 Error in file: Position 1121460224
Record # 8556 Record size 128 kb
where 7ff9ff202000 loop 8192

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20a000 Error in file: Position 1036951552
Record # 7911 Record size 128 kb
where 7ff9ff20a000 loop 40960

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1088147456
Record # 8301 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 1208602624
Record # 9220 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20a000 Error in file: Position 972333056
Record # 7418 Record size 128 kb
where 7ff9ff20a000 loop 40960

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 970182656
Record # 7401 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20a000 Error in file: Position 1054908416
Record # 8048 Record size 128 kb
where 7ff9ff20a000 loop 40960

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20a000 Error in file: Position 890150912
Record # 6791 Record size 128 kb
where 7ff9ff20a000 loop 40960

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 983945216
Record # 7506 Record size 128 kb
where 7ff9ff21d000 loop 118784

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff20a000 Error in file: Position 825532416
Record # 6298 Record size 128 kb
where 7ff9ff20a000 loop 40960

Error in file: Found ?6d? Expecting ?6d6d6d6d6d6d6d6d? addr 7ff9ff21d000 Error in file: Position 710004736
Record # 5416 Record size 128 kb
where 7ff9ff21d000 loop 118784

Children see throughput for 32 stride readers = 0.00 KB/sec
Parent sees throughput for 32 stride readers = 0.00 KB/sec
Min throughput per process = 0.00 KB/sec
Max throughput per process = 0.00 KB/sec
Avg throughput per process = 0.00 KB/sec
Min xfer = 0.00 KB
iozone.DUMMY.30: No such file or directory
iozone.DUMMY.28: No such file or directory
iozone.DUMMY.20: No such file or directory
iozone.DUMMY.19: No such file or directory
iozone.DUMMY.26: No such file or directory
iozone.DUMMY.0: No such file or directory
iozone.DUMMY.21: No such file or directory
iozone.DUMMY.18: No such file or directory
iozone.DUMMY.1: No such file or directory
iozone.DUMMY.22: No such file or directory
iozone.DUMMY.16: No such file or directory
iozone.DUMMY.2: No such file or directory
iozone.DUMMY.3: No such file or directory
iozone.DUMMY.23: No such file or directory
iozone.DUMMY.17: No such file or directory
iozone.DUMMY.4: No such file or directory
iozone.DUMMY.5: No such file or directory
iozone.DUMMY.24: No such file or directory
iozone.DUMMY.15: No such file or directory
iozone.DUMMY.6: No such file or directory
iozone.DUMMY.7: No such file or directory
iozone.DUMMY.25: No such file or directory
iozone.DUMMY.14: No such file or directory
iozone.DUMMY.8: No such file or directory
iozone.DUMMY.13: No such file or directory
iozone.DUMMY.9: No such file or directory
iozone.DUMMY.12: No such file or directory
iozone.DUMMY.11: No such file or directory
iozone.DUMMY.10: No such file or directory
iozone.DUMMY.29: No such file or directory
iozone.DUMMY.27: No such file or directory
iozone.DUMMY.31: No such file or directory

What's your setup? Are you running md, lvm? What filesystem?

I'm getting a couple bug reports, and I think I know what commit introduced the regression but it seems to require something else slightly unusual in the stack to trigger, so I'm trying to figure out what the common factor is.

Hi

Very basic, no md or LVM involved. /dev/sda2 is the backing device and /dev/sdb is the cache device. On top of bcache0 I'm running xfs:

# parted -s /dev/sda p
Model: ATA Hitachi HDP72505 (scsi)
Disk /dev/sda: 500GB
Sector size (logical/physical): 512B/512B
Partition Table: msdos

Number  Start   End     Size    Type     File system     Flags
 1      1049kB  10.5GB  10.5GB  primary  xfs             boot
 2      10.5GB  499GB   489GB   primary
 3      499GB   500GB   1049MB  primary  linux-swap(v1)

# parted -s /dev/sdb p
Error: /dev/sdb: unrecognised disk label

# grep bcache /proc/mounts
/dev/bcache0 /srv xfs rw,relatime,attr2,inode64,noquota 0 0

# bcache-super-show /dev/sda2
sb.magic                ok
sb.first_sector         8 [match]
sb.csum                 7B66B1004B52FD9A [match]
sb.version              1 [backing device]

dev.uuid                3a131733-7d54-4feb-bf8c-62d6fbdbf935
dev.sectors_per_block   1
dev.sectors_per_bucket  1024
dev.data.first_sector   16
dev.data.cache_mode     1 [writeback]
dev.data.cache_state    1 [clean]

cset.uuid 2a108307-bab9-42dd-b072-10eeb0c13dd8

# bcache-super-show /dev/sdb
sb.magic                ok
sb.first_sector         8 [match]
sb.csum                 88965AD15D35A500 [match]
sb.version              3 [cache device]

dev.uuid                ffb6fc80-1dca-42d4-a951-cddee6af689e
dev.sectors_per_block   1
dev.sectors_per_bucket  1024
dev.cache.first_sector  1024

dev.cache.cache_sectors 62498816
dev.cache.total_sectors 62499840
dev.cache.discard no
dev.cache.pos 0

cset.uuid 2a108307-bab9-42dd-b072-10eeb0c13dd8

Does this help?

cheers

Carsten

Writeback or writethrough?

Hi

Sorry, writeback as this testing is aimed for high performance scratch space.

Cheers

Carsten

Hi again (sorry for the amount of small emails)

Just tested, the same happens with writethrough

Cheers

Carsten

Oh, damn. Can you check 3.10.9 and 3.10.10?

Wilco - if I new hot to git bisect across various branches I'd do that as well.

Time to learn :)

More soonish

Cheers

Carsten

Hi Kent (et al.)

I hit a bumpy road with bisectioning with kernels refusing to boot (not finding their rootfs neither via UUID nor /dev/sd{a,b}) and we had a large conference to run, so I failed to find any "bad" commit.

Also, it did not help, that I needed to get the test machine into production use last week - now I need another test bed for testing.

Given that I used a 32GB SSD and the problems only ever occurred when the iozone file size was close or exceeded the capacity of the cache device, does this help you in guessing what I hit along the road?

Cheers

Carsten