* fio reports data corruption with btrfs
@ 2012-06-25 18:30 Alex Lyakas
2012-06-25 19:10 ` Josef Bacik
2012-06-25 19:26 ` Josef Bacik
0 siblings, 2 replies; 9+ messages in thread
From: Alex Lyakas @ 2012-06-25 18:30 UTC (permalink / raw)
To: linux-btrfs
Greetings everybody,
I am running a fio test on btrfs compiled from
git://git.kernel.org/pub/scm/linux/kernel/git/mason/linux-btrfs.git,
up to commit:
cb77fcd88569cd2b7b25ecd4086ea932a53be9b3 Btrfs: delay iput with async extents
including this commit.
Below is a fio configuration file, and later fio textual output.
Here:
https://docs.google.com/folder/d/0B1AuaIB8xZtbNTRuSW1zVGozWFE/edit
are "expected" vs "received" mismatch reports. Strangely, when I read
the mismatched block from the file reported as corrupted by fio, I
receive data different both from "expected" and "received" blocks that
fio reports. I added one such file (job0.1.0.88576.now) to the
pastebin as well.
If you think that my fio configuration file is faulty, please let me
know. fio version is 1.59. The idea is to run 10 io processes in
parallel.
Thanks,
Alex.
-----fio configuration:---------
[global]
directory=/mnt/btrfs
rw=randrw
randrepeat=1
size=10000m
filesize=100k-10m
nrfiles=1000
bsrange=512b-64k
bs_unaligned
scramble_buffers=1
ioengine=sync
fsync=1024
verify=md5
do_verify=1
verify_fatal=1
verify_dump=1
[job0]
[job1]
[job2]
[job3]
[job4]
[job5]
[job6]
[job7]
[job8]
[job9]
-----fio output------------------
job0: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job1: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job2: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job3: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job4: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job5: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job6: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job7: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job8: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
job9: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1
fio 1.59
Starting 10 processes
job0: Laying out IO file(s) (1000 file(s) / 5131MB)
job1: Laying out IO file(s) (1000 file(s) / 5045MB)
job2: Laying out IO file(s) (1000 file(s) / 5168MB)
job3: Laying out IO file(s) (1000 file(s) / 4954MB)
job4: Laying out IO file(s) (1000 file(s) / 5041MB)
job5: Laying out IO file(s) (1000 file(s) / 4898MB)
job6: Laying out IO file(s) (1000 file(s) / 5099MB)
job7: Laying out IO file(s) (1000 file(s) / 5055MB)
job8: Laying out IO file(s) (1000 file(s) / 5049MB)
job9: Laying out IO file(s) (1000 file(s) / 4944MB)
job0: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3464
read : io=2496.3MB, bw=136725 B/s, iops=9 , runt=19144097msec
clat (usec): min=0 , max=1510.7K, avg=25048.70, stdev=42148.74
lat (usec): min=0 , max=1510.7K, avg=25049.48, stdev=42148.66
bw (KB/s) : min= 0, max= 1384, per=11.28%, avg=147.48, stdev=127.76
write: io=2478.3MB, bw=135738 B/s, iops=9 , runt=19144074msec
clat (usec): min=8 , max=6299.7K, avg=80909.59, stdev=134487.90
lat (usec): min=8 , max=6299.7K, avg=80910.18, stdev=134487.93
bw (KB/s) : min= 0, max= 881, per=10.68%, avg=139.44, stdev=86.23
cpu : usr=0.08%, sys=0.19%, ctx=515969, majf=0, minf=4547
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=180604/180349/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.23%, 10=1.62%, 20=0.75%, 50=2.20%
lat (usec): 100=0.31%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.03%
lat (msec): 2=0.61%, 4=7.66%, 10=24.17%, 20=19.00%, 50=18.18%
lat (msec): 100=9.30%, 250=13.19%, 500=2.38%, 750=0.13%, 1000=0.03%
lat (msec): 2000=0.13%, >=2000=0.02%
job1: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3465
read : io=2450.6MB, bw=136831 B/s, iops=9 , runt=18779397msec
clat (usec): min=0 , max=1489.8K, avg=23070.44, stdev=36372.06
lat (usec): min=0 , max=1489.8K, avg=23071.12, stdev=36372.17
bw (KB/s) : min= 0, max= 1894, per=11.18%, avg=146.18, stdev=123.43
write: io=2446.7MB, bw=136609 B/s, iops=9 , runt=18779340msec
clat (usec): min=7 , max=8154.8K, avg=82150.38, stdev=132095.17
lat (usec): min=7 , max=8154.8K, avg=82150.98, stdev=132095.19
bw (KB/s) : min= 0, max= 1477, per=10.70%, avg=139.58, stdev=79.31
cpu : usr=0.08%, sys=0.20%, ctx=499619, majf=0, minf=4467
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=177966/177189/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.15%, 10=1.49%, 20=0.61%, 50=2.02%
lat (usec): 100=0.27%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2=0.27%, 4=6.39%, 10=25.07%, 20=19.53%, 50=19.32%
lat (msec): 100=9.09%, 250=13.41%, 500=2.05%, 750=0.09%, 1000=0.02%
lat (msec): 2000=0.13%, >=2000=0.02%
job2: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3466
read : io=2510.8MB, bw=140997 B/s, iops=9 , runt=18671605msec
clat (usec): min=0 , max=1020.2K, avg=21983.31, stdev=33041.43
lat (usec): min=0 , max=1020.3K, avg=21984.00, stdev=33041.54
bw (KB/s) : min= 0, max= 1193, per=11.45%, avg=149.77, stdev=126.37
write: io=2506.7MB, bw=140771 B/s, iops=9 , runt=18671552msec
clat (usec): min=8 , max=6267.1K, avg=80858.49, stdev=131766.39
lat (usec): min=8 , max=6267.1K, avg=80859.08, stdev=131766.41
bw (KB/s) : min= 0, max= 1091, per=10.96%, avg=143.04, stdev=84.29
cpu : usr=0.08%, sys=0.20%, ctx=507090, majf=0, minf=4673
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=181766/181195/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.12%, 10=1.49%, 20=0.61%, 50=2.02%
lat (usec): 100=0.27%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2=0.23%, 4=6.05%, 10=25.29%, 20=19.92%, 50=19.74%
lat (msec): 100=9.03%, 250=13.06%, 500=1.87%, 750=0.07%, 1000=0.01%
lat (msec): 2000=0.13%, >=2000=0.02%
job3: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3467
read : io=2403.8MB, bw=141394 B/s, iops=9 , runt=17825854msec
clat (usec): min=0 , max=1507.1K, avg=21230.56, stdev=31634.13
lat (usec): min=0 , max=1507.1K, avg=21242.66, stdev=31706.30
bw (KB/s) : min= 0, max= 1631, per=11.43%, avg=149.48, stdev=129.48
write: io=2410.3MB, bw=141781 B/s, iops=9 , runt=17825392msec
clat (usec): min=7 , max=6122.6K, avg=80499.39, stdev=126021.57
lat (usec): min=7 , max=6122.6K, avg=80499.99, stdev=126021.59
bw (KB/s) : min= 0, max= 1368, per=10.98%, avg=143.31, stdev=87.04
cpu : usr=0.08%, sys=0.20%, ctx=488731, majf=6, minf=4475
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=174678/174992/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.15%, 10=1.47%, 20=0.64%, 50=1.98%
lat (usec): 100=0.26%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2=0.24%, 4=6.01%, 10=25.36%, 20=20.26%, 50=19.72%
lat (msec): 100=8.71%, 250=13.17%, 500=1.77%, 750=0.07%, 1000=0.01%
lat (msec): 2000=0.10%, >=2000=0.02%
job4: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3468
read : io=2439.5MB, bw=141037 B/s, iops=9 , runt=18136577msec
clat (usec): min=0 , max=1007.6K, avg=21403.03, stdev=31429.28
lat (usec): min=0 , max=1007.6K, avg=21410.58, stdev=31463.14
bw (KB/s) : min= 0, max= 1195, per=11.44%, avg=149.70, stdev=128.42
write: io=2449.5MB, bw=141615 B/s, iops=9 , runt=18136396msec
clat (usec): min=6 , max=6576.6K, avg=80851.64, stdev=130270.83
lat (usec): min=6 , max=6576.6K, avg=80852.24, stdev=130270.85
bw (KB/s) : min= 0, max= 1240, per=11.00%, avg=143.51, stdev=85.36
cpu : usr=0.08%, sys=0.20%, ctx=490020, majf=0, minf=4441
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=176712/177196/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.15%, 10=1.46%, 20=0.67%, 50=1.99%
lat (usec): 100=0.25%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2=0.23%, 4=5.95%, 10=24.99%, 20=20.16%, 50=20.13%
lat (msec): 100=8.92%, 250=13.06%, 500=1.78%, 750=0.07%, 1000=0.01%
lat (msec): 2000=0.11%, >=2000=0.02%
job5: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3469
read : io=2367.9MB, bw=138834 B/s, iops=9 , runt=17877831msec
clat (usec): min=0 , max=1077.8K, avg=21170.18, stdev=31605.60
lat (usec): min=0 , max=1077.8K, avg=21170.98, stdev=31606.07
bw (KB/s) : min= 0, max= 1250, per=11.34%, avg=148.27, stdev=126.53
write: io=2381.5MB, bw=139679 B/s, iops=9 , runt=17877733msec
clat (usec): min=8 , max=113686K, avg=82698.04, stdev=303004.44
lat (usec): min=8 , max=113686K, avg=82698.64, stdev=303004.45
bw (KB/s) : min= 0, max= 945, per=10.88%, avg=142.03, stdev=80.03
cpu : usr=0.08%, sys=0.20%, ctx=477997, majf=0, minf=4313
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=171549/172006/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.16%, 10=1.54%, 20=0.65%, 50=2.01%
lat (usec): 100=0.25%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2=0.23%, 4=5.90%, 10=25.08%, 20=20.17%, 50=19.83%
lat (msec): 100=8.75%, 250=13.33%, 500=1.83%, 750=0.06%, 1000=0.02%
lat (msec): 2000=0.10%, >=2000=0.02%
job6: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3470
read : io=2480.1MB, bw=142701 B/s, iops=9 , runt=18230196msec
clat (usec): min=0 , max=1104.2K, avg=21473.52, stdev=32023.64
lat (usec): min=0 , max=1104.2K, avg=21474.12, stdev=32023.64
bw (KB/s) : min= 0, max= 1334, per=11.57%, avg=151.33, stdev=130.32
write: io=2462.7MB, bw=141646 B/s, iops=9 , runt=18230168msec
clat (usec): min=8 , max=5290.6K, avg=80382.37, stdev=127185.58
lat (usec): min=9 , max=5290.6K, avg=80382.97, stdev=127185.60
bw (KB/s) : min= 0, max= 1494, per=10.99%, avg=143.47, stdev=85.71
cpu : usr=0.09%, sys=0.20%, ctx=496651, majf=0, minf=4584
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=179365/178598/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.16%, 10=1.47%, 20=0.65%, 50=1.99%
lat (usec): 100=0.24%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2=0.23%, 4=5.96%, 10=25.20%, 20=20.15%, 50=19.96%
lat (msec): 100=9.01%, 250=12.95%, 500=1.78%, 750=0.07%, 1000=0.01%
lat (msec): 2000=0.11%, >=2000=0.02%
job7: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3471
read : io=2457.5MB, bw=140897 B/s, iops=9 , runt=18288243msec
clat (usec): min=0 , max=1338.7K, avg=22043.04, stdev=33519.83
lat (usec): min=0 , max=1338.7K, avg=22046.87, stdev=33527.50
bw (KB/s) : min= 0, max= 1247, per=11.44%, avg=149.66, stdev=129.04
write: io=2443.5MB, bw=140096 B/s, iops=9 , runt=18288053msec
clat (usec): min=7 , max=8063.6K, avg=81557.61, stdev=132788.93
lat (usec): min=8 , max=8063.6K, avg=81558.20, stdev=132788.95
bw (KB/s) : min= 0, max= 1002, per=10.90%, avg=142.25, stdev=84.60
cpu : usr=0.08%, sys=0.20%, ctx=489184, majf=0, minf=4559
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=176436/176293/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.16%, 10=1.43%, 20=0.62%, 50=1.96%
lat (usec): 100=0.24%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2=0.24%, 4=6.06%, 10=25.24%, 20=19.99%, 50=19.64%
lat (msec): 100=8.99%, 250=13.25%, 500=1.88%, 750=0.08%, 1000=0.02%
lat (msec): 2000=0.11%, >=2000=0.02%
job8: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3472
read : io=2459.6MB, bw=137875 B/s, iops=9 , runt=18701643msec
clat (usec): min=0 , max=1511.2K, avg=23458.01, stdev=37066.34
lat (usec): min=0 , max=1511.2K, avg=23459.06, stdev=37066.34
bw (KB/s) : min= 0, max= 1156, per=11.21%, avg=146.57, stdev=126.45
write: io=2441.6MB, bw=136866 B/s, iops=9 , runt=18701599msec
clat (usec): min=8 , max=6941.5K, avg=82135.36, stdev=133215.89
lat (usec): min=8 , max=6941.5K, avg=82135.95, stdev=133215.91
bw (KB/s) : min= 0, max= 1077, per=10.67%, avg=139.19, stdev=83.27
cpu : usr=0.08%, sys=0.20%, ctx=491008, majf=0, minf=4569
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=177579/176670/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.14%, 10=1.50%, 20=0.60%, 50=1.98%
lat (usec): 100=0.25%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec): 2=0.27%, 4=6.28%, 10=24.85%, 20=19.55%, 50=19.45%
lat (msec): 100=9.31%, 250=13.49%, 500=2.02%, 750=0.09%, 1000=0.02%
lat (msec): 2000=0.12%, >=2000=0.02%
job9: (groupid=0, jobs=1): err=84 (file:io_u.c:1425,
func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide
character): pid=3473
read : io=2401.2MB, bw=132245 B/s, iops=9 , runt=19039047msec
clat (usec): min=0 , max=1476.2K, avg=25714.10, stdev=42489.38
lat (usec): min=0 , max=1476.2K, avg=25715.47, stdev=42489.41
bw (KB/s) : min= 0, max= 1445, per=10.87%, avg=142.23, stdev=122.88
write: io=2393.6MB, bw=131825 B/s, iops=9 , runt=19038993msec
clat (usec): min=7 , max=81630K, avg=83909.39, stdev=237517.33
lat (usec): min=7 , max=81630K, avg=83909.98, stdev=237517.34
bw (KB/s) : min= 0, max= 1680, per=10.37%, avg=135.39, stdev=81.47
cpu : usr=0.08%, sys=0.19%, ctx=490383, majf=0, minf=4490
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued r/w/d: total=173514/173472/0, short=0/0/0
lat (usec): 2=0.01%, 4=0.18%, 10=1.53%, 20=0.67%, 50=2.08%
lat (usec): 100=0.29%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.02%
lat (msec): 2=0.39%, 4=6.60%, 10=23.68%, 20=19.59%, 50=18.79%
lat (msec): 100=9.67%, 250=13.75%, 500=2.39%, 750=0.12%, 1000=0.03%
lat (msec): 2000=0.13%, >=2000=0.02%
Run status group 0 (all jobs):
READ: io=24466MB, aggrb=1308KB/s, minb=132KB/s, maxb=142KB/s,
mint=17825854msec, maxt=19144097msec
WRITE: io=24413MB, aggrb=1305KB/s, minb=131KB/s, maxb=141KB/s,
mint=17825392msec, maxt=19144074msec
^ permalink raw reply [flat|nested] 9+ messages in thread* Re: fio reports data corruption with btrfs 2012-06-25 18:30 fio reports data corruption with btrfs Alex Lyakas @ 2012-06-25 19:10 ` Josef Bacik 2012-06-25 19:26 ` Josef Bacik 1 sibling, 0 replies; 9+ messages in thread From: Josef Bacik @ 2012-06-25 19:10 UTC (permalink / raw) To: Alex Lyakas; +Cc: linux-btrfs@vger.kernel.org On Mon, Jun 25, 2012 at 12:30:34PM -0600, Alex Lyakas wrote: > Greetings everybody, > > I am running a fio test on btrfs compiled from > git://git.kernel.org/pub/scm/linux/kernel/git/mason/linux-btrfs.git, > up to commit: > cb77fcd88569cd2b7b25ecd4086ea932a53be9b3 Btrfs: delay iput with async extents > including this commit. > > Below is a fio configuration file, and later fio textual output. > Here: > https://docs.google.com/folder/d/0B1AuaIB8xZtbNTRuSW1zVGozWFE/edit > are "expected" vs "received" mismatch reports. Strangely, when I read > the mismatched block from the file reported as corrupted by fio, I > receive data different both from "expected" and "received" blocks that > fio reports. I added one such file (job0.1.0.88576.now) to the > pastebin as well. > > If you think that my fio configuration file is faulty, please let me > know. fio version is 1.59. The idea is to run 10 io processes in > parallel. > Mount options? I'm running the test now, I'll let you know if I can reproduce. Thanks, Josef ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: fio reports data corruption with btrfs 2012-06-25 18:30 fio reports data corruption with btrfs Alex Lyakas 2012-06-25 19:10 ` Josef Bacik @ 2012-06-25 19:26 ` Josef Bacik 2012-06-26 7:39 ` Alex Lyakas 1 sibling, 1 reply; 9+ messages in thread From: Josef Bacik @ 2012-06-25 19:26 UTC (permalink / raw) To: Alex Lyakas; +Cc: linux-btrfs@vger.kernel.org On Mon, Jun 25, 2012 at 12:30:34PM -0600, Alex Lyakas wrote: > Greetings everybody, > > I am running a fio test on btrfs compiled from > git://git.kernel.org/pub/scm/linux/kernel/git/mason/linux-btrfs.git, > up to commit: > cb77fcd88569cd2b7b25ecd4086ea932a53be9b3 Btrfs: delay iput with async extents > including this commit. > > Below is a fio configuration file, and later fio textual output. > Here: > https://docs.google.com/folder/d/0B1AuaIB8xZtbNTRuSW1zVGozWFE/edit > are "expected" vs "received" mismatch reports. Strangely, when I read > the mismatched block from the file reported as corrupted by fio, I > receive data different both from "expected" and "received" blocks that > fio reports. I added one such file (job0.1.0.88576.now) to the > pastebin as well. > > If you think that my fio configuration file is faulty, please let me > know. fio version is 1.59. The idea is to run 10 io processes in > parallel. > So we think it may be enospc, so try btrfs-next git://git.kernel.org/pub/scm/linux/kernel/git/josef/btrfs-next.git which has an enospc fix related to creating a crapptone of files. Let me know if that helps. Thanks, Josef ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: fio reports data corruption with btrfs 2012-06-25 19:26 ` Josef Bacik @ 2012-06-26 7:39 ` Alex Lyakas 2012-06-27 8:15 ` Alex Lyakas 0 siblings, 1 reply; 9+ messages in thread From: Alex Lyakas @ 2012-06-26 7:39 UTC (permalink / raw) To: Josef Bacik; +Cc: linux-btrfs@vger.kernel.org Hi Josef, Mount options were noatime, nodatacow. So you say that fio might have received ENOSPC, but didn't abort the test? I will compile your branch and let you know. I did not see any error messages from the kernel, except from: Jun 25 10:04:28 vc kernel: [ 436.730890] btrfs: setting nodatacow Jun 25 10:04:28 vc kernel: [ 436.744139] btrfs: no dev_stats entry found for device /dev/sdb2 (devid 1) (OK on first mount after mkfs) Jun 25 10:13:12 vc kernel: [ 960.844149] INFO: task flush-btrfs-2:3349 blocked for more than 120 seconds. Jun 25 10:13:12 vc kernel: [ 960.846600] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jun 25 10:13:12 vc kernel: [ 960.847507] flush-btrfs-2 D ffffffff8180ca80 0 3349 2 0x00000000 Jun 25 10:13:12 vc kernel: [ 960.847515] ffff8801186337a0 0000000000000046 0000000013e332ba ffffffff81c1d780 Jun 25 10:13:12 vc kernel: [ 960.847520] ffff880118633fd8 ffff880118633fd8 ffff880118633fd8 0000000000013840 Jun 25 10:13:12 vc kernel: [ 960.847525] ffffffff81c13020 ffff8801176f5b80 ffff880118633790 ffff88011fc140e8 Jun 25 10:13:12 vc kernel: [ 960.847530] Call Trace: Jun 25 10:13:12 vc kernel: [ 960.847554] [<ffffffff8166c239>] schedule+0x29/0x70 Jun 25 10:13:12 vc kernel: [ 960.847558] [<ffffffff8166c30f>] io_schedule+0x8f/0xd0 Jun 25 10:13:12 vc kernel: [ 960.847574] [<ffffffff812f0a3f>] get_request_wait+0xef/0x240 Jun 25 10:13:12 vc kernel: [ 960.847587] [<ffffffff81073a80>] ? add_wait_queue+0x60/0x60 Jun 25 10:13:12 vc kernel: [ 960.847592] [<ffffffff812f191f>] blk_queue_bio+0x7f/0x3a0 Jun 25 10:13:12 vc kernel: [ 960.847596] [<ffffffff812ee784>] generic_make_request.part.50+0x74/0xb0 Jun 25 10:13:12 vc kernel: [ 960.847600] [<ffffffff812eef18>] generic_make_request+0x68/0x70 Jun 25 10:13:12 vc kernel: [ 960.847603] [<ffffffff812eefa7>] submit_bio+0x87/0x110 Jun 25 10:13:12 vc kernel: [ 960.847649] [<ffffffffa006f8c7>] btrfs_map_bio+0x167/0x210 [btrfs] Jun 25 10:13:12 vc kernel: [ 960.847669] [<ffffffffa00428ad>] btrfs_submit_bio_hook+0x7d/0x140 [btrfs] Jun 25 10:13:12 vc kernel: [ 960.847691] [<ffffffffa00609fa>] submit_one_bio+0x6a/0xa0 [btrfs] Jun 25 10:13:12 vc kernel: [ 960.847713] [<ffffffffa0061059>] flush_epd_write_bio+0x39/0x50 [btrfs] Jun 25 10:13:12 vc kernel: [ 960.847734] [<ffffffffa00662c0>] extent_writepages+0x50/0x60 [btrfs] Jun 25 10:13:12 vc kernel: [ 960.847754] [<ffffffffa0045ba0>] ? btrfs_submit_direct+0x1e0/0x1e0 [btrfs] Jun 25 10:13:12 vc kernel: [ 960.847759] [<ffffffff81073654>] ? bit_waitqueue+0x14/0xc0 Jun 25 10:13:12 vc kernel: [ 960.847779] [<ffffffffa00436d8>] btrfs_writepages+0x28/0x30 [btrfs] Jun 25 10:13:12 vc kernel: [ 960.847793] [<ffffffff81128191>] do_writepages+0x21/0x40 Jun 25 10:13:12 vc kernel: [ 960.847805] [<ffffffff811a5462>] writeback_single_inode+0x112/0x380 Jun 25 10:13:12 vc kernel: [ 960.847809] [<ffffffff811a5886>] writeback_sb_inodes+0x1b6/0x270 Jun 25 10:13:12 vc kernel: [ 960.847813] [<ffffffff811a59de>] __writeback_inodes_wb+0x9e/0xd0 Jun 25 10:13:12 vc kernel: [ 960.847816] [<ffffffff811a5c9b>] wb_writeback+0x28b/0x340 Jun 25 10:13:12 vc kernel: [ 960.847823] [<ffffffff810125c7>] ? __switch_to+0x137/0x410 Jun 25 10:13:12 vc kernel: [ 960.847833] [<ffffffff81197d02>] ? get_nr_dirty_inodes+0x52/0x80 Jun 25 10:13:12 vc kernel: [ 960.847837] [<ffffffff811a5def>] wb_check_old_data_flush+0x9f/0xb0 Jun 25 10:13:12 vc kernel: [ 960.847842] [<ffffffff811a72c9>] wb_do_writeback+0x149/0x1d0 Jun 25 10:13:12 vc kernel: [ 960.847848] [<ffffffff8105f610>] ? usleep_range+0x50/0x50 Jun 25 10:13:12 vc kernel: [ 960.847852] [<ffffffff811a73db>] bdi_writeback_thread+0x8b/0x290 Jun 25 10:13:12 vc kernel: [ 960.847855] [<ffffffff811a7350>] ? wb_do_writeback+0x1d0/0x1d0 Jun 25 10:13:12 vc kernel: [ 960.847860] [<ffffffff81072fe3>] kthread+0x93/0xa0 Jun 25 10:13:12 vc kernel: [ 960.847868] [<ffffffff81676be4>] kernel_thread_helper+0x4/0x10 Jun 25 10:13:12 vc kernel: [ 960.847873] [<ffffffff81072f50>] ? kthread_freezable_should_stop+0x70/0x70 Jun 25 10:13:12 vc kernel: [ 960.847877] [<ffffffff81676be0>] ? gs_change+0x13/0x13 Thanks, Alex. On Mon, Jun 25, 2012 at 10:26 PM, Josef Bacik <jbacik@fusionio.com> wrote: > On Mon, Jun 25, 2012 at 12:30:34PM -0600, Alex Lyakas wrote: >> Greetings everybody, >> >> I am running a fio test on btrfs compiled from >> git://git.kernel.org/pub/scm/linux/kernel/git/mason/linux-btrfs.git, >> up to commit: >> cb77fcd88569cd2b7b25ecd4086ea932a53be9b3 Btrfs: delay iput with async extents >> including this commit. >> >> Below is a fio configuration file, and later fio textual output. >> Here: >> https://docs.google.com/folder/d/0B1AuaIB8xZtbNTRuSW1zVGozWFE/edit >> are "expected" vs "received" mismatch reports. Strangely, when I read >> the mismatched block from the file reported as corrupted by fio, I >> receive data different both from "expected" and "received" blocks that >> fio reports. I added one such file (job0.1.0.88576.now) to the >> pastebin as well. >> >> If you think that my fio configuration file is faulty, please let me >> know. fio version is 1.59. The idea is to run 10 io processes in >> parallel. >> > > So we think it may be enospc, so try btrfs-next > > git://git.kernel.org/pub/scm/linux/kernel/git/josef/btrfs-next.git > > which has an enospc fix related to creating a crapptone of files. Let me know > if that helps. Thanks, > > Josef ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: fio reports data corruption with btrfs 2012-06-26 7:39 ` Alex Lyakas @ 2012-06-27 8:15 ` Alex Lyakas 2012-06-27 13:46 ` Josef Bacik 0 siblings, 1 reply; 9+ messages in thread From: Alex Lyakas @ 2012-06-27 8:15 UTC (permalink / raw) To: Josef Bacik; +Cc: linux-btrfs@vger.kernel.org Hi Josef, I have rerun the test with btrfs-next master branch. fio reported mismatched blocks again. Mount options were the same (-o noatime,nodatacow). In both cases the drive is a 135Gb drive, while the total size of allocated block groups is around 60Gb: Data: total=62.01GB, used=49.04GB System, DUP: total=8.00MB, used=12.00KB System: total=4.00MB, used=0.00 Metadata, DUP: total=3.00GB, used=5.58MB Metadata: total=8.00MB, used=0.00 (In addition, one of the fio processes crashed with the following stack trace: Program terminated with signal 6, Aborted. #0 0x00007fbd66ddf445 in raise () from /lib/x86_64-linux-gnu/libc.so.6 (gdb) bt #0 0x00007fbd66ddf445 in raise () from /lib/x86_64-linux-gnu/libc.so.6 #1 0x00007fbd66de2bab in abort () from /lib/x86_64-linux-gnu/libc.so.6 #2 0x00007fbd66e1ce2e in ?? () from /lib/x86_64-linux-gnu/libc.so.6 #3 0x00007fbd66e27626 in ?? () from /lib/x86_64-linux-gnu/libc.so.6 #4 0x0000000000419e91 in verify_io_u () #5 0x000000000041cc0e in ?? () #6 0x000000000041cf49 in io_u_sync_complete () #7 0x000000000040b090 in ?? () #8 0x000000000040b4ae in ?? () #9 0x00000000004076a3 in main () I will recompile fio with symbols for later tests). I have put all the files here (including core), just in case: https://docs.google.com/folder/d/0B1AuaIB8xZtbb3ExRk5qRVFjYWc/edit fio output: job0: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job1: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job2: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job3: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job4: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job5: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job6: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job7: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job8: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job9: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 fio 1.59 Starting 10 processes job0: Laying out IO file(s) (1000 file(s) / 4997MB) job1: Laying out IO file(s) (1000 file(s) / 4921MB) job2: Laying out IO file(s) (1000 file(s) / 5140MB) job3: Laying out IO file(s) (1000 file(s) / 5086MB) job4: Laying out IO file(s) (1000 file(s) / 4869MB) job5: Laying out IO file(s) (1000 file(s) / 5106MB) job6: Laying out IO file(s) (1000 file(s) / 4980MB) job7: Laying out IO file(s) (1000 file(s) / 5052MB) job8: Laying out IO file(s) (1000 file(s) / 5075MB) job9: Laying out IO file(s) (1000 file(s) / 4964MB) md5: verify failed at file /mnt/btrfs/job5.6.0 offset 9728, length 512 Expected CRC: 00000000000000000000000000000000 Received CRC: e3e8620ae5404f1b8603a0d36f18cd38 received data dumped as job5.6.0.9728.received expected data dumped as job5.6.0.9728.expected job0: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job1: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job2: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job3: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job4: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job5: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job6: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job7: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job8: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job9: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 fio 1.59 Starting 10 processes job0: Laying out IO file(s) (1000 file(s) / 4997MB) job1: Laying out IO file(s) (1000 file(s) / 4921MB) job2: Laying out IO file(s) (1000 file(s) / 5140MB) job3: Laying out IO file(s) (1000 file(s) / 5086MB) job4: Laying out IO file(s) (1000 file(s) / 4869MB) job5: Laying out IO file(s) (1000 file(s) / 5106MB) job6: Laying out IO file(s) (1000 file(s) / 4980MB) job7: Laying out IO file(s) (1000 file(s) / 5052MB) job8: Laying out IO file(s) (1000 file(s) / 5075MB) job9: Laying out IO file(s) (1000 file(s) / 4964MB) fio: pid=2684, got signal=6 job0: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2679 read : io=2425.2MB, bw=139606 B/s, iops=9 , runt=18215098msec clat (usec): min=1 , max=1516.9K, avg=28821.71, stdev=53801.70 lat (usec): min=1 , max=1516.9K, avg=28823.38, stdev=53801.36 bw (KB/s) : min= 0, max= 1677, per=15058.66%, avg=150.59, stdev=127.61 write: io=2422.1MB, bw=139478 B/s, iops=9 , runt=18215071msec clat (usec): min=12 , max=11509K, avg=74324.21, stdev=123810.94 lat (usec): min=12 , max=11509K, avg=74324.85, stdev=123810.96 bw (KB/s) : min= 0, max= 1541, per=14368.19%, avg=143.68, stdev=89.16 cpu : usr=0.08%, sys=0.21%, ctx=501180, majf=0, minf=4422 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=175461/175326/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.14%, 10=1.74%, 20=0.36%, 50=2.44% lat (usec): 100=0.51%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.32%, 4=6.40%, 10=24.17%, 20=19.52%, 50=18.35% lat (msec): 100=10.57%, 250=12.64%, 500=2.42%, 750=0.18%, 1000=0.07% lat (msec): 2000=0.08%, >=2000=0.01% job1: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2680 read : io=2390.2MB, bw=143712 B/s, iops=9 , runt=17445480msec clat (usec): min=0 , max=1511.4K, avg=26605.60, stdev=47176.79 lat (usec): min=0 , max=1511.4K, avg=26606.23, stdev=47176.79 bw (KB/s) : min= 0, max= 1196, per=15100.71%, avg=151.01, stdev=131.88 write: io=2381.9MB, bw=143117 B/s, iops=9 , runt=17445461msec clat (usec): min=12 , max=7148.5K, avg=74260.28, stdev=108522.47 lat (usec): min=13 , max=7148.5K, avg=74260.91, stdev=108522.49 bw (KB/s) : min= 0, max= 1433, per=14424.66%, avg=144.25, stdev=93.19 cpu : usr=0.09%, sys=0.21%, ctx=477064, majf=0, minf=4373 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=173501/172436/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.11%, 10=1.46%, 20=0.29%, 50=2.16% lat (usec): 100=0.43%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.13%, 4=5.32%, 10=24.42%, 20=19.56%, 50=20.53% lat (msec): 100=10.76%, 250=12.49%, 500=2.01%, 750=0.15%, 1000=0.06% lat (msec): 2000=0.06%, >=2000=0.01% job2: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2681 read : io=2496.4MB, bw=148172 B/s, iops=10 , runt=17663792msec clat (usec): min=0 , max=1529.4K, avg=24625.57, stdev=43194.30 lat (usec): min=0 , max=1529.4K, avg=24626.67, stdev=43194.32 bw (KB/s) : min= 0, max= 1963, per=15564.69%, avg=155.65, stdev=138.00 write: io=2501.8MB, bw=148471 B/s, iops=10 , runt=17663741msec clat (usec): min=12 , max=9705.8K, avg=72681.05, stdev=109065.67 lat (usec): min=12 , max=9705.8K, avg=72681.67, stdev=109065.70 bw (KB/s) : min= 0, max= 1326, per=14916.54%, avg=149.17, stdev=95.28 cpu : usr=0.09%, sys=0.22%, ctx=502065, majf=0, minf=4681 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=181669/181083/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.10%, 10=1.55%, 20=0.30%, 50=2.23% lat (usec): 100=0.43%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.11%, 4=4.99%, 10=25.09%, 20=20.24%, 50=20.70% lat (msec): 100=10.25%, 250=11.82%, 500=1.89%, 750=0.15%, 1000=0.05% lat (msec): 2000=0.05%, >=2000=0.01% job3: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2682 read : io=2462.5MB, bw=149508 B/s, iops=10 , runt=17270645msec clat (usec): min=0 , max=1512.6K, avg=24019.27, stdev=41028.90 lat (usec): min=0 , max=1512.6K, avg=24019.92, stdev=41028.95 bw (KB/s) : min= 0, max= 1765, per=15659.51%, avg=156.60, stdev=138.16 write: io=2471.4MB, bw=150044 B/s, iops=10 , runt=17270600msec clat (usec): min=10 , max=8980.6K, avg=72398.80, stdev=104022.76 lat (usec): min=10 , max=8980.6K, avg=72399.45, stdev=104022.79 bw (KB/s) : min= 0, max= 1419, per=15025.37%, avg=150.25, stdev=95.46 cpu : usr=0.09%, sys=0.22%, ctx=496947, majf=0, minf=4580 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=178605/178801/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.10%, 10=1.47%, 20=0.28%, 50=2.21% lat (usec): 100=0.41%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.11%, 4=4.93%, 10=24.98%, 20=20.44%, 50=20.99% lat (msec): 100=10.23%, 250=11.73%, 500=1.82%, 750=0.14%, 1000=0.05% lat (msec): 2000=0.04%, >=2000=0.01% job4: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2683 read : io=2358.7MB, bw=150618 B/s, iops=10 , runt=16416381msec clat (usec): min=0 , max=1512.5K, avg=23370.23, stdev=38338.33 lat (usec): min=0 , max=1512.5K, avg=23371.36, stdev=38339.09 bw (KB/s) : min= 0, max= 1343, per=15690.18%, avg=156.90, stdev=133.97 write: io=2370.1MB, bw=151442 B/s, iops=10 , runt=16416264msec clat (usec): min=12 , max=9559.6K, avg=72489.79, stdev=102465.13 lat (usec): min=12 , max=9559.6K, avg=72490.44, stdev=102465.16 bw (KB/s) : min= 0, max= 1207, per=15094.32%, avg=150.94, stdev=90.87 cpu : usr=0.09%, sys=0.23%, ctx=474742, majf=5, minf=4304 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=170943/171046/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.10%, 10=1.56%, 20=0.29%, 50=2.28% lat (usec): 100=0.45%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.11%, 4=5.02%, 10=24.92%, 20=20.54%, 50=20.89% lat (msec): 100=9.98%, 250=11.82%, 500=1.79%, 750=0.13%, 1000=0.04% lat (msec): 2000=0.03%, >=2000=0.01% job5: (groupid=0, jobs=1): err= 0: pid=2684 cpu : usr=0.00%, sys=0.00%, ctx=0, majf=0, minf=0 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=178658/178373/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.11%, 10=1.54%, 20=0.30%, 50=2.20% lat (usec): 100=0.44%, 250=0.05%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.10%, 4=4.72%, 10=24.58%, 20=20.33%, 50=21.37% lat (msec): 100=10.26%, 250=11.86%, 500=1.91%, 750=0.15%, 1000=0.04% lat (msec): 2000=0.04%, >=2000=0.01% job6: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2685 read : io=2405.8MB, bw=145560 B/s, iops=10 , runt=17325411msec clat (usec): min=0 , max=1509.8K, avg=23944.81, stdev=40459.55 lat (usec): min=0 , max=1509.8K, avg=23946.23, stdev=40460.22 bw (KB/s) : min= 0, max= 1287, per=15327.71%, avg=153.28, stdev=124.51 write: io=2422.9MB, bw=146636 B/s, iops=10 , runt=17325313msec clat (usec): min=10 , max=155338K, avg=75211.59, stdev=387812.27 lat (usec): min=10 , max=155338K, avg=75212.22, stdev=387812.28 bw (KB/s) : min= 0, max= 1122, per=14759.86%, avg=147.60, stdev=76.71 cpu : usr=0.09%, sys=0.22%, ctx=480817, majf=0, minf=4501 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=173670/174837/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.12%, 10=1.54%, 20=0.31%, 50=2.25% lat (usec): 100=0.41%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.10%, 4=4.86%, 10=24.85%, 20=20.37%, 50=20.73% lat (msec): 100=10.16%, 250=12.04%, 500=1.96%, 750=0.14%, 1000=0.04% lat (msec): 2000=0.04%, >=2000=0.01% job7: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2686 read : io=2461.8MB, bw=147350 B/s, iops=10 , runt=17517920msec clat (usec): min=0 , max=1509.7K, avg=24600.73, stdev=41725.53 lat (usec): min=0 , max=1509.7K, avg=24601.50, stdev=41725.56 bw (KB/s) : min= 0, max= 1520, per=15458.08%, avg=154.58, stdev=125.61 write: io=2441.5MB, bw=146135 B/s, iops=10 , runt=17517870msec clat (usec): min=12 , max=85757K, avg=74337.25, stdev=230850.35 lat (usec): min=12 , max=85757K, avg=74337.88, stdev=230850.36 bw (KB/s) : min= 0, max= 1091, per=14685.98%, avg=146.86, stdev=80.26 cpu : usr=0.09%, sys=0.22%, ctx=489164, majf=0, minf=4543 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=177574/176604/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.11%, 10=1.53%, 20=0.31%, 50=2.23% lat (usec): 100=0.43%, 250=0.04%, 500=0.01%, 1000=0.01% lat (msec): 2=0.12%, 4=4.97%, 10=25.11%, 20=20.07%, 50=20.59% lat (msec): 100=10.26%, 250=11.97%, 500=1.98%, 750=0.15%, 1000=0.04% lat (msec): 2000=0.04%, >=2000=0.01% job8: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2687 read : io=2470.9MB, bw=145841 B/s, iops=10 , runt=17764551msec clat (usec): min=0 , max=1510.6K, avg=26085.23, stdev=45212.81 lat (usec): min=1 , max=1510.6K, avg=26086.16, stdev=45212.74 bw (KB/s) : min= 0, max= 1164, per=15345.15%, avg=153.45, stdev=123.91 write: io=2451.2MB, bw=144674 B/s, iops=10 , runt=17764524msec clat (usec): min=10 , max=9094.4K, avg=73556.38, stdev=110604.39 lat (usec): min=10 , max=9094.4K, avg=73557.01, stdev=110604.42 bw (KB/s) : min= 0, max= 1048, per=14543.02%, avg=145.43, stdev=82.24 cpu : usr=0.09%, sys=0.22%, ctx=493970, majf=0, minf=4589 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=178703/177873/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.10%, 10=1.53%, 20=0.30%, 50=2.20% lat (usec): 100=0.42%, 250=0.04%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.12%, 4=5.28%, 10=24.60%, 20=19.86%, 50=20.38% lat (msec): 100=10.68%, 250=12.16%, 500=2.02%, 750=0.16%, 1000=0.05% lat (msec): 2000=0.06%, >=2000=0.01% job9: (groupid=0, jobs=1): err=84 (file:io_u.c:1425, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2688 read : io=2403.8MB, bw=138958 B/s, iops=9 , runt=18138650msec clat (usec): min=0 , max=1513.3K, avg=28563.33, stdev=51247.73 lat (usec): min=1 , max=1513.3K, avg=28564.82, stdev=51247.66 bw (KB/s) : min= 0, max= 1285, per=14877.37%, avg=148.77, stdev=121.79 write: io=2410.7MB, bw=139357 B/s, iops=9 , runt=18138607msec clat (usec): min=10 , max=139931K, avg=75209.33, stdev=353297.66 lat (usec): min=10 , max=139931K, avg=75209.97, stdev=353297.67 bw (KB/s) : min= 0, max= 1367, per=14277.24%, avg=142.77, stdev=82.35 cpu : usr=0.09%, sys=0.21%, ctx=496079, majf=0, minf=4532 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued r/w/d: total=174228/174718/0, short=0/0/0 lat (usec): 2=0.01%, 4=0.14%, 10=1.66%, 20=0.31%, 50=2.41% lat (usec): 100=0.52%, 250=0.06%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec): 2=0.18%, 4=5.65%, 10=23.90%, 20=20.28%, 50=18.80% lat (msec): 100=10.73%, 250=12.63%, 500=2.39%, 750=0.17%, 1000=0.07% lat (msec): 2000=0.08%, >=2000=0.01% Run status group 0 (all jobs): READ: io=21874MB, aggrb=1KB/s, minb=0KB/s, maxb=150KB/s, mint=16416381msec, maxt=17694821418msec WRITE: io=21873MB, aggrb=1KB/s, minb=0KB/s, maxb=151KB/s, mint=16416264msec, maxt=17694821418msec fio: file hash not empty on exit Thanks, Alex. On Tue, Jun 26, 2012 at 10:39 AM, Alex Lyakas <alex.bolshoy.btrfs@gmail.com> wrote: > Hi Josef, > Mount options were noatime, nodatacow. > So you say that fio might have received ENOSPC, but didn't abort the test? > > I will compile your branch and let you know. > > I did not see any error messages from the kernel, except from: > Jun 25 10:04:28 vc kernel: [ 436.730890] btrfs: setting nodatacow > Jun 25 10:04:28 vc kernel: [ 436.744139] btrfs: no dev_stats entry > found for device /dev/sdb2 (devid 1) (OK on first mount after mkfs) > Jun 25 10:13:12 vc kernel: [ 960.844149] INFO: task > flush-btrfs-2:3349 blocked for more than 120 seconds. > Jun 25 10:13:12 vc kernel: [ 960.846600] "echo 0 > > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > Jun 25 10:13:12 vc kernel: [ 960.847507] flush-btrfs-2 D > ffffffff8180ca80 0 3349 2 0x00000000 > Jun 25 10:13:12 vc kernel: [ 960.847515] ffff8801186337a0 > 0000000000000046 0000000013e332ba ffffffff81c1d780 > Jun 25 10:13:12 vc kernel: [ 960.847520] ffff880118633fd8 > ffff880118633fd8 ffff880118633fd8 0000000000013840 > Jun 25 10:13:12 vc kernel: [ 960.847525] ffffffff81c13020 > ffff8801176f5b80 ffff880118633790 ffff88011fc140e8 > Jun 25 10:13:12 vc kernel: [ 960.847530] Call Trace: > Jun 25 10:13:12 vc kernel: [ 960.847554] [<ffffffff8166c239>] > schedule+0x29/0x70 > Jun 25 10:13:12 vc kernel: [ 960.847558] [<ffffffff8166c30f>] > io_schedule+0x8f/0xd0 > Jun 25 10:13:12 vc kernel: [ 960.847574] [<ffffffff812f0a3f>] > get_request_wait+0xef/0x240 > Jun 25 10:13:12 vc kernel: [ 960.847587] [<ffffffff81073a80>] ? > add_wait_queue+0x60/0x60 > Jun 25 10:13:12 vc kernel: [ 960.847592] [<ffffffff812f191f>] > blk_queue_bio+0x7f/0x3a0 > Jun 25 10:13:12 vc kernel: [ 960.847596] [<ffffffff812ee784>] > generic_make_request.part.50+0x74/0xb0 > Jun 25 10:13:12 vc kernel: [ 960.847600] [<ffffffff812eef18>] > generic_make_request+0x68/0x70 > Jun 25 10:13:12 vc kernel: [ 960.847603] [<ffffffff812eefa7>] > submit_bio+0x87/0x110 > Jun 25 10:13:12 vc kernel: [ 960.847649] [<ffffffffa006f8c7>] > btrfs_map_bio+0x167/0x210 [btrfs] > Jun 25 10:13:12 vc kernel: [ 960.847669] [<ffffffffa00428ad>] > btrfs_submit_bio_hook+0x7d/0x140 [btrfs] > Jun 25 10:13:12 vc kernel: [ 960.847691] [<ffffffffa00609fa>] > submit_one_bio+0x6a/0xa0 [btrfs] > Jun 25 10:13:12 vc kernel: [ 960.847713] [<ffffffffa0061059>] > flush_epd_write_bio+0x39/0x50 [btrfs] > Jun 25 10:13:12 vc kernel: [ 960.847734] [<ffffffffa00662c0>] > extent_writepages+0x50/0x60 [btrfs] > Jun 25 10:13:12 vc kernel: [ 960.847754] [<ffffffffa0045ba0>] ? > btrfs_submit_direct+0x1e0/0x1e0 [btrfs] > Jun 25 10:13:12 vc kernel: [ 960.847759] [<ffffffff81073654>] ? > bit_waitqueue+0x14/0xc0 > Jun 25 10:13:12 vc kernel: [ 960.847779] [<ffffffffa00436d8>] > btrfs_writepages+0x28/0x30 [btrfs] > Jun 25 10:13:12 vc kernel: [ 960.847793] [<ffffffff81128191>] > do_writepages+0x21/0x40 > Jun 25 10:13:12 vc kernel: [ 960.847805] [<ffffffff811a5462>] > writeback_single_inode+0x112/0x380 > Jun 25 10:13:12 vc kernel: [ 960.847809] [<ffffffff811a5886>] > writeback_sb_inodes+0x1b6/0x270 > Jun 25 10:13:12 vc kernel: [ 960.847813] [<ffffffff811a59de>] > __writeback_inodes_wb+0x9e/0xd0 > Jun 25 10:13:12 vc kernel: [ 960.847816] [<ffffffff811a5c9b>] > wb_writeback+0x28b/0x340 > Jun 25 10:13:12 vc kernel: [ 960.847823] [<ffffffff810125c7>] ? > __switch_to+0x137/0x410 > Jun 25 10:13:12 vc kernel: [ 960.847833] [<ffffffff81197d02>] ? > get_nr_dirty_inodes+0x52/0x80 > Jun 25 10:13:12 vc kernel: [ 960.847837] [<ffffffff811a5def>] > wb_check_old_data_flush+0x9f/0xb0 > Jun 25 10:13:12 vc kernel: [ 960.847842] [<ffffffff811a72c9>] > wb_do_writeback+0x149/0x1d0 > Jun 25 10:13:12 vc kernel: [ 960.847848] [<ffffffff8105f610>] ? > usleep_range+0x50/0x50 > Jun 25 10:13:12 vc kernel: [ 960.847852] [<ffffffff811a73db>] > bdi_writeback_thread+0x8b/0x290 > Jun 25 10:13:12 vc kernel: [ 960.847855] [<ffffffff811a7350>] ? > wb_do_writeback+0x1d0/0x1d0 > Jun 25 10:13:12 vc kernel: [ 960.847860] [<ffffffff81072fe3>] > kthread+0x93/0xa0 > Jun 25 10:13:12 vc kernel: [ 960.847868] [<ffffffff81676be4>] > kernel_thread_helper+0x4/0x10 > Jun 25 10:13:12 vc kernel: [ 960.847873] [<ffffffff81072f50>] ? > kthread_freezable_should_stop+0x70/0x70 > Jun 25 10:13:12 vc kernel: [ 960.847877] [<ffffffff81676be0>] ? > gs_change+0x13/0x13 > > Thanks, > Alex. > > > > On Mon, Jun 25, 2012 at 10:26 PM, Josef Bacik <jbacik@fusionio.com> wrote: >> On Mon, Jun 25, 2012 at 12:30:34PM -0600, Alex Lyakas wrote: >>> Greetings everybody, >>> >>> I am running a fio test on btrfs compiled from >>> git://git.kernel.org/pub/scm/linux/kernel/git/mason/linux-btrfs.git, >>> up to commit: >>> cb77fcd88569cd2b7b25ecd4086ea932a53be9b3 Btrfs: delay iput with async extents >>> including this commit. >>> >>> Below is a fio configuration file, and later fio textual output. >>> Here: >>> https://docs.google.com/folder/d/0B1AuaIB8xZtbNTRuSW1zVGozWFE/edit >>> are "expected" vs "received" mismatch reports. Strangely, when I read >>> the mismatched block from the file reported as corrupted by fio, I >>> receive data different both from "expected" and "received" blocks that >>> fio reports. I added one such file (job0.1.0.88576.now) to the >>> pastebin as well. >>> >>> If you think that my fio configuration file is faulty, please let me >>> know. fio version is 1.59. The idea is to run 10 io processes in >>> parallel. >>> >> >> So we think it may be enospc, so try btrfs-next >> >> git://git.kernel.org/pub/scm/linux/kernel/git/josef/btrfs-next.git >> >> which has an enospc fix related to creating a crapptone of files. Let me know >> if that helps. Thanks, >> >> Josef ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: fio reports data corruption with btrfs 2012-06-27 8:15 ` Alex Lyakas @ 2012-06-27 13:46 ` Josef Bacik 2012-07-02 11:48 ` Alex Lyakas 0 siblings, 1 reply; 9+ messages in thread From: Josef Bacik @ 2012-06-27 13:46 UTC (permalink / raw) To: Alex Lyakas; +Cc: Josef Bacik, linux-btrfs@vger.kernel.org On Wed, Jun 27, 2012 at 02:15:59AM -0600, Alex Lyakas wrote: > Hi Josef, > I have rerun the test with btrfs-next master branch. fio reported > mismatched blocks again. Mount options were the same (-o > noatime,nodatacow). > Ok I'll try running it again here locally, I didn't realize it was nodatacow. In the meantime can you try a newer version of fio, I'm running fio-2.0.6-1.fc18.x86_64 but I think git is even newer than that. Thanks, Josef ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: fio reports data corruption with btrfs 2012-06-27 13:46 ` Josef Bacik @ 2012-07-02 11:48 ` Alex Lyakas 2012-07-02 12:49 ` Josef Bacik 0 siblings, 1 reply; 9+ messages in thread From: Alex Lyakas @ 2012-07-02 11:48 UTC (permalink / raw) To: Josef Bacik; +Cc: linux-btrfs@vger.kernel.org Hi Josef, which branch from your (or another?) repo should I try this on: remotes/origin/HEAD -> origin/master remotes/origin/enospc 3c78455 Btrfs: fall back to non-inline if we don't have enough space remotes/origin/for-chris 7e9ce65 Btrfs: hold a ref on the inode during writepages remotes/origin/master 1573317 Btrfs: use helper function to simplify code Thanks, Alex. On Wed, Jun 27, 2012 at 4:46 PM, Josef Bacik <jbacik@fusionio.com> wrote: > On Wed, Jun 27, 2012 at 02:15:59AM -0600, Alex Lyakas wrote: >> Hi Josef, >> I have rerun the test with btrfs-next master branch. fio reported >> mismatched blocks again. Mount options were the same (-o >> noatime,nodatacow). >> > > Ok I'll try running it again here locally, I didn't realize it was nodatacow. > In the meantime can you try a newer version of fio, I'm running > fio-2.0.6-1.fc18.x86_64 but I think git is even newer than that. Thanks, > > Josef ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: fio reports data corruption with btrfs 2012-07-02 11:48 ` Alex Lyakas @ 2012-07-02 12:49 ` Josef Bacik 2012-07-03 10:35 ` Alex Lyakas 0 siblings, 1 reply; 9+ messages in thread From: Josef Bacik @ 2012-07-02 12:49 UTC (permalink / raw) To: Alex Lyakas; +Cc: Josef Bacik, linux-btrfs@vger.kernel.org On Mon, Jul 02, 2012 at 05:48:43AM -0600, Alex Lyakas wrote: > Hi Josef, > which branch from your (or another?) repo should I try this on: > Master, and make sure you've checked out a more recent fio from git to make sure it's not a bug in fio. Thanks, Josef ^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: fio reports data corruption with btrfs 2012-07-02 12:49 ` Josef Bacik @ 2012-07-03 10:35 ` Alex Lyakas 0 siblings, 0 replies; 9+ messages in thread From: Alex Lyakas @ 2012-07-03 10:35 UTC (permalink / raw) To: Josef Bacik; +Cc: linux-btrfs@vger.kernel.org Hi Josef, tested with your "master" branch, commit 157331741ba010ffcb2212b88342fb21ae140636. fio compiled from tag fio-2.0.8 (commit cf9a74c8bd63d9db5256f1362885c740e11a1fe5). Result: some kernel warnings about hung tasks, fio segfault and mismatch errors. Below are some outputs... I will try some more tests, changing different components. Alex. Kernel log: Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.740135] INFO: task df:3113 blocked for more than 120 seconds. Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.741878] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742881] df D ffffffff8180cae0 0 3113 3112 0x00000000 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742887] ffff88004668fcb8 0000000000000086 ffff880119b72e28 ffff88011fc13930 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742891] ffff88004668ffd8 ffff88004668ffd8 ffff88004668ffd8 00000000000138c0 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742894] ffffffff81c13440 ffff8801194544d0 ffff88011fc138c0 7fffffffffffffff Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742896] Call Trace: Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742912] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742916] [<ffffffff81678395>] schedule_timeout+0x2a5/0x320 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742920] [<ffffffff81679acf>] wait_for_common+0xdf/0x180 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742940] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742952] [<ffffffff81088c60>] ? try_to_wake_up+0x200/0x200 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742956] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742960] [<ffffffff81679c4d>] wait_for_completion+0x1d/0x20 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742963] [<ffffffff811a830d>] writeback_inodes_sb_nr+0x7d/0xa0 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742967] [<ffffffff811a857e>] writeback_inodes_sb+0x2e/0x40 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742970] [<ffffffff811afb0e>] __sync_filesystem+0x4e/0x90 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742973] [<ffffffff811afb6f>] sync_one_sb+0x1f/0x30 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742984] [<ffffffff81184a91>] iterate_supers+0x101/0x110 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742988] [<ffffffff811afc20>] sys_sync+0x30/0x70 Jul 3 00:02:12 vsa-00000018-vc-1 kernel: [ 9000.742993] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.740290] INFO: task df:3113 blocked for more than 120 seconds. Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.741252] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742282] df D ffffffff8180cae0 0 3113 3112 0x00000000 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742299] ffff88004668fcb8 0000000000000086 ffff880119b72e28 ffff88011fc13930 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742303] ffff88004668ffd8 ffff88004668ffd8 ffff88004668ffd8 00000000000138c0 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742307] ffffffff81c13440 ffff8801194544d0 ffff88011fc138c0 7fffffffffffffff Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742308] Call Trace: Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742324] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742328] [<ffffffff81678395>] schedule_timeout+0x2a5/0x320 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742332] [<ffffffff81679acf>] wait_for_common+0xdf/0x180 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742340] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742347] [<ffffffff81088c60>] ? try_to_wake_up+0x200/0x200 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742350] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742354] [<ffffffff81679c4d>] wait_for_completion+0x1d/0x20 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742358] [<ffffffff811a830d>] writeback_inodes_sb_nr+0x7d/0xa0 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742361] [<ffffffff811a857e>] writeback_inodes_sb+0x2e/0x40 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742364] [<ffffffff811afb0e>] __sync_filesystem+0x4e/0x90 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742368] [<ffffffff811afb6f>] sync_one_sb+0x1f/0x30 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742373] [<ffffffff81184a91>] iterate_supers+0x101/0x110 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742376] [<ffffffff811afc20>] sys_sync+0x30/0x70 Jul 3 00:04:12 vsa-00000018-vc-1 kernel: [ 9120.742381] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.740133] INFO: task df:3113 blocked for more than 120 seconds. Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.741191] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742103] df D ffffffff8180cae0 0 3113 3112 0x00000000 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742109] ffff88004668fcb8 0000000000000086 ffff880119b72e28 ffff88011fc13930 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742113] ffff88004668ffd8 ffff88004668ffd8 ffff88004668ffd8 00000000000138c0 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742117] ffffffff81c13440 ffff8801194544d0 ffff88011fc138c0 7fffffffffffffff Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742119] Call Trace: Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742134] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742139] [<ffffffff81678395>] schedule_timeout+0x2a5/0x320 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742143] [<ffffffff81679acf>] wait_for_common+0xdf/0x180 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742151] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742157] [<ffffffff81088c60>] ? try_to_wake_up+0x200/0x200 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742161] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742164] [<ffffffff81679c4d>] wait_for_completion+0x1d/0x20 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742168] [<ffffffff811a830d>] writeback_inodes_sb_nr+0x7d/0xa0 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742172] [<ffffffff811a857e>] writeback_inodes_sb+0x2e/0x40 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742175] [<ffffffff811afb0e>] __sync_filesystem+0x4e/0x90 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742178] [<ffffffff811afb6f>] sync_one_sb+0x1f/0x30 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742183] [<ffffffff81184a91>] iterate_supers+0x101/0x110 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742187] [<ffffffff811afc20>] sys_sync+0x30/0x70 Jul 3 00:06:12 vsa-00000018-vc-1 kernel: [ 9240.742191] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.740160] INFO: task df:3113 blocked for more than 120 seconds. Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.741617] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743043] df D ffffffff8180cae0 0 3113 3112 0x00000000 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743049] ffff88004668fcb8 0000000000000086 ffff880119b72e28 ffff88011fc13930 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743053] ffff88004668ffd8 ffff88004668ffd8 ffff88004668ffd8 00000000000138c0 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743056] ffffffff81c13440 ffff8801194544d0 ffff88011fc138c0 7fffffffffffffff Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743058] Call Trace: Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743074] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743078] [<ffffffff81678395>] schedule_timeout+0x2a5/0x320 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743083] [<ffffffff81679acf>] wait_for_common+0xdf/0x180 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743091] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743097] [<ffffffff81088c60>] ? try_to_wake_up+0x200/0x200 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743101] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743104] [<ffffffff81679c4d>] wait_for_completion+0x1d/0x20 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743108] [<ffffffff811a830d>] writeback_inodes_sb_nr+0x7d/0xa0 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743111] [<ffffffff811a857e>] writeback_inodes_sb+0x2e/0x40 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743115] [<ffffffff811afb0e>] __sync_filesystem+0x4e/0x90 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743118] [<ffffffff811afb6f>] sync_one_sb+0x1f/0x30 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743123] [<ffffffff81184a91>] iterate_supers+0x101/0x110 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743127] [<ffffffff811afc20>] sys_sync+0x30/0x70 Jul 3 00:08:12 vsa-00000018-vc-1 kernel: [ 9360.743131] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.740164] INFO: task df:3113 blocked for more than 120 seconds. Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.741309] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742519] df D ffffffff8180cae0 0 3113 3112 0x00000000 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742525] ffff88004668fcb8 0000000000000086 ffff880119b72e28 ffff88011fc13930 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742529] ffff88004668ffd8 ffff88004668ffd8 ffff88004668ffd8 00000000000138c0 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742532] ffffffff81c13440 ffff8801194544d0 ffff88011fc138c0 7fffffffffffffff Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742534] Call Trace: Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742547] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742551] [<ffffffff81678395>] schedule_timeout+0x2a5/0x320 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742555] [<ffffffff81679acf>] wait_for_common+0xdf/0x180 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742562] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742568] [<ffffffff81088c60>] ? try_to_wake_up+0x200/0x200 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742571] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742575] [<ffffffff81679c4d>] wait_for_completion+0x1d/0x20 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742579] [<ffffffff811a830d>] writeback_inodes_sb_nr+0x7d/0xa0 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742582] [<ffffffff811a857e>] writeback_inodes_sb+0x2e/0x40 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742586] [<ffffffff811afb0e>] __sync_filesystem+0x4e/0x90 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742589] [<ffffffff811afb6f>] sync_one_sb+0x1f/0x30 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742594] [<ffffffff81184a91>] iterate_supers+0x101/0x110 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742597] [<ffffffff811afc20>] sys_sync+0x30/0x70 Jul 3 00:10:12 vsa-00000018-vc-1 kernel: [ 9480.742601] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.740152] INFO: task df:3113 blocked for more than 120 seconds. Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.741373] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742515] df D ffffffff8180cae0 0 3113 3112 0x00000000 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742521] ffff88004668fcb8 0000000000000086 ffff880119b72e28 ffff88011fc13930 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742524] ffff88004668ffd8 ffff88004668ffd8 ffff88004668ffd8 00000000000138c0 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742528] ffffffff81c13440 ffff8801194544d0 ffff88011fc138c0 7fffffffffffffff Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742530] Call Trace: Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742546] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742550] [<ffffffff81678395>] schedule_timeout+0x2a5/0x320 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742554] [<ffffffff81679acf>] wait_for_common+0xdf/0x180 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742562] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742569] [<ffffffff81088c60>] ? try_to_wake_up+0x200/0x200 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742572] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742576] [<ffffffff81679c4d>] wait_for_completion+0x1d/0x20 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742580] [<ffffffff811a830d>] writeback_inodes_sb_nr+0x7d/0xa0 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742583] [<ffffffff811a857e>] writeback_inodes_sb+0x2e/0x40 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742586] [<ffffffff811afb0e>] __sync_filesystem+0x4e/0x90 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742589] [<ffffffff811afb6f>] sync_one_sb+0x1f/0x30 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742595] [<ffffffff81184a91>] iterate_supers+0x101/0x110 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742598] [<ffffffff811afc20>] sys_sync+0x30/0x70 Jul 3 00:12:12 vsa-00000018-vc-1 kernel: [ 9600.742603] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.740156] INFO: task df:3113 blocked for more than 120 seconds. Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.741421] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742641] df D 0000000000000000 0 3113 3112 0x00000000 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742647] ffff88004668fcd8 0000000000000086 ffff88004668fcb8 ffffffff8108e50b Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742651] ffff88004668ffd8 ffff88004668ffd8 ffff88004668ffd8 00000000000138c0 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742654] ffff88011603c4d0 ffff8801194544d0 00000000000138c0 7fffffffffffffff Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742657] Call Trace: Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742671] [<ffffffff8108e50b>] ? check_preempt_wakeup+0x14b/0x270 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742680] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742684] [<ffffffff81678395>] schedule_timeout+0x2a5/0x320 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742690] [<ffffffff81085f56>] ? ttwu_do_activate.constprop.85+0x66/0x70 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742693] [<ffffffff81086036>] ? ttwu_queue+0xd6/0xf0 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742697] [<ffffffff81679acf>] wait_for_common+0xdf/0x180 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742704] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742708] [<ffffffff81088c60>] ? try_to_wake_up+0x200/0x200 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742711] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742715] [<ffffffff81679c4d>] wait_for_completion+0x1d/0x20 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742718] [<ffffffff811a84de>] sync_inodes_sb+0x8e/0xc0 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742734] [<ffffffff811afb48>] __sync_filesystem+0x88/0x90 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742738] [<ffffffff811afb6f>] sync_one_sb+0x1f/0x30 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742744] [<ffffffff81184a91>] iterate_supers+0x101/0x110 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742747] [<ffffffff811afc37>] sys_sync+0x47/0x70 Jul 3 00:16:12 vsa-00000018-vc-1 kernel: [ 9840.742752] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.740208] INFO: task fio:2975 blocked for more than 120 seconds. Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.741633] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743001] fio D 0000000000000000 0 2975 2706 0x00000000 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743007] ffff8800d8bffac8 0000000000000082 0000000009bf6ad8 ffffffff81c1d980 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743011] ffff8800d8bfffd8 ffff8800d8bfffd8 ffff8800d8bfffd8 00000000000138c0 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743014] ffff880117660000 ffff8801175b44d0 ffff8800d8bffaa8 ffff88011fc14158 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743016] Call Trace: Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743045] [<ffffffff81121e50>] ? __lock_page+0x70/0x70 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743055] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743058] [<ffffffff81679d4f>] io_schedule+0x8f/0xd0 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743062] [<ffffffff81121e5e>] sleep_on_page+0xe/0x20 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743066] [<ffffffff8167861f>] __wait_on_bit+0x5f/0x90 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743069] [<ffffffff81121fb8>] wait_on_page_bit+0x78/0x80 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743078] [<ffffffff81076ca0>] ? autoremove_wake_function+0x40/0x40 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743110] [<ffffffffa03197f0>] prepare_pages.isra.14+0x240/0x370 [btrfs] Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743123] [<ffffffffa02f7758>] ? btrfs_delalloc_reserve_metadata+0x1f8/0x380 [btrfs] Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743127] [<ffffffff8167ab9e>] ? _raw_spin_lock+0xe/0x20 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743145] [<ffffffffa031a2cd>] __btrfs_buffered_write+0x17d/0x330 [btrfs] Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743164] [<ffffffffa031a6bd>] btrfs_file_aio_write+0x23d/0x4c0 [btrfs] Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743168] [<ffffffff811242ef>] ? generic_file_aio_read+0xef/0x280 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743173] [<ffffffff81181042>] do_sync_write+0xd2/0x110 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743187] [<ffffffff812e0a38>] ? apparmor_file_permission+0x18/0x20 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743199] [<ffffffff812a76ec>] ? security_file_permission+0x2c/0xb0 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743202] [<ffffffff811815d1>] ? rw_verify_area+0x61/0xf0 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743205] [<ffffffff81181933>] vfs_write+0xb3/0x180 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743208] [<ffffffff81181c5a>] sys_write+0x4a/0x90 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743212] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.743219] INFO: task df:3113 blocked for more than 120 seconds. Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.744750] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746723] df D 0000000000000000 0 3113 3112 0x00000000 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746730] ffff88004668fcd8 0000000000000086 ffff88004668fcb8 ffffffff8108e50b Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746735] ffff88004668ffd8 ffff88004668ffd8 ffff88004668ffd8 00000000000138c0 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746740] ffff88011603c4d0 ffff8801194544d0 00000000000138c0 7fffffffffffffff Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746742] Call Trace: Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746752] [<ffffffff8108e50b>] ? check_preempt_wakeup+0x14b/0x270 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746759] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746764] [<ffffffff81678395>] schedule_timeout+0x2a5/0x320 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746772] [<ffffffff81085f56>] ? ttwu_do_activate.constprop.85+0x66/0x70 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746776] [<ffffffff81086036>] ? ttwu_queue+0xd6/0xf0 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746782] [<ffffffff81679acf>] wait_for_common+0xdf/0x180 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746791] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746796] [<ffffffff81088c60>] ? try_to_wake_up+0x200/0x200 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746801] [<ffffffff811afb50>] ? __sync_filesystem+0x90/0x90 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746807] [<ffffffff81679c4d>] wait_for_completion+0x1d/0x20 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746812] [<ffffffff811a84de>] sync_inodes_sb+0x8e/0xc0 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746817] [<ffffffff811afb48>] __sync_filesystem+0x88/0x90 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746822] [<ffffffff811afb6f>] sync_one_sb+0x1f/0x30 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746826] [<ffffffff81184a91>] iterate_supers+0x101/0x110 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746830] [<ffffffff811afc37>] sys_sync+0x47/0x70 Jul 3 00:18:12 vsa-00000018-vc-1 kernel: [ 9960.746833] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.744121] INFO: task fio:2975 blocked for more than 120 seconds. Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.745759] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747269] fio D 0000000000000000 0 2975 2706 0x00000000 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747283] ffff8800d8bffac8 0000000000000082 0000000009bf6ad8 ffffffff81c1d980 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747288] ffff8800d8bfffd8 ffff8800d8bfffd8 ffff8800d8bfffd8 00000000000138c0 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747291] ffff880117660000 ffff8801175b44d0 ffff8800d8bffaa8 ffff88011fc14158 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747293] Call Trace: Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747307] [<ffffffff81121e50>] ? __lock_page+0x70/0x70 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747317] [<ffffffff81679c79>] schedule+0x29/0x70 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747320] [<ffffffff81679d4f>] io_schedule+0x8f/0xd0 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747324] [<ffffffff81121e5e>] sleep_on_page+0xe/0x20 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747328] [<ffffffff8167861f>] __wait_on_bit+0x5f/0x90 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747332] [<ffffffff81121fb8>] wait_on_page_bit+0x78/0x80 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747337] [<ffffffff81076ca0>] ? autoremove_wake_function+0x40/0x40 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747369] [<ffffffffa03197f0>] prepare_pages.isra.14+0x240/0x370 [btrfs] Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747383] [<ffffffffa02f7758>] ? btrfs_delalloc_reserve_metadata+0x1f8/0x380 [btrfs] Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747386] [<ffffffff8167ab9e>] ? _raw_spin_lock+0xe/0x20 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747405] [<ffffffffa031a2cd>] __btrfs_buffered_write+0x17d/0x330 [btrfs] Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747423] [<ffffffffa031a6bd>] btrfs_file_aio_write+0x23d/0x4c0 [btrfs] Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747428] [<ffffffff811242ef>] ? generic_file_aio_read+0xef/0x280 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747433] [<ffffffff81181042>] do_sync_write+0xd2/0x110 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747440] [<ffffffff812e0a38>] ? apparmor_file_permission+0x18/0x20 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747446] [<ffffffff812a76ec>] ? security_file_permission+0x2c/0xb0 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747449] [<ffffffff811815d1>] ? rw_verify_area+0x61/0xf0 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747452] [<ffffffff81181933>] vfs_write+0xb3/0x180 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747455] [<ffffffff81181c5a>] sys_write+0x4a/0x90 Jul 3 00:20:12 vsa-00000018-vc-1 kernel: [10080.747460] [<ffffffff816833e9>] system_call_fastpath+0x16/0x1b Jul 3 03:10:22 vsa-00000018-vc-1 kernel: [20291.040538] show_signal_msg: 2310 callbacks suppressed Jul 3 03:10:22 vsa-00000018-vc-1 kernel: [20291.040552] fio[2973]: segfault at 1cef000 ip 0000000000429f7a sp 00007fff49697cf0 error 4 in fio[400000+52000] fio output: job0: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job1: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job2: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job3: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job4: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job5: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job6: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job7: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job8: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 job9: (g=0): rw=randrw, bs=512-64K/512-64K, ioengine=sync, iodepth=1 fio-2.0.8 Starting 10 processes job0: Laying out IO file(s) (1000 file(s) / 5100MB) job1: Laying out IO file(s) (1000 file(s) / 5075MB) job2: Laying out IO file(s) (1000 file(s) / 5027MB) job3: Laying out IO file(s) (1000 file(s) / 4914MB) job4: Laying out IO file(s) (1000 file(s) / 4981MB) job5: Laying out IO file(s) (1000 file(s) / 4931MB) job6: Laying out IO file(s) (1000 file(s) / 4891MB) job7: Laying out IO file(s) (1000 file(s) / 5163MB) job8: Laying out IO file(s) (1000 file(s) / 4853MB) job9: Laying out IO file(s) (999 file(s) / 5117MB) fio: pid=2973, got signal=11 job0: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2971 read : io=2491.5MB, bw=134829 B/s, iops=9 , runt=19375884msec clat (usec): min=0 , max=857708 , avg=20919.57, stdev=30157.57 lat (usec): min=0 , max=857709 , avg=20920.44, stdev=30157.52 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2320], 10.00th=[ 3312], 20.00th=[ 4896], | 30.00th=[ 6816], 40.00th=[ 8160], 50.00th=[10176], 60.00th=[13504], | 70.00th=[18560], 80.00th=[29056], 90.00th=[49920], 95.00th=[76288], | 99.00th=[152576], 99.50th=[189440], 99.90th=[276480], 99.95th=[317440], | 99.99th=[415744] bw (KB/s) : min= 0, max= 1289, per=100.00%, avg=145.73, stdev=125.40 write: io=2471.9MB, bw=133771 B/s, iops=9 , runt=19375848msec clat (usec): min=10 , max=12106K, avg=85756.30, stdev=175488.75 lat (usec): min=10 , max=12106K, avg=85756.84, stdev=175488.75 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 43], 10.00th=[ 4256], 20.00th=[ 8640], | 30.00th=[12608], 40.00th=[17792], 50.00th=[26752], 60.00th=[44800], | 70.00th=[91648], 80.00th=[207872], 90.00th=[224256], 95.00th=[244736], | 99.00th=[333824], 99.50th=[423936], 99.90th=[2998272], 99.95th=[3588096], | 99.99th=[5079040] bw (KB/s) : min= 0, max= 1098, per=100.00%, avg=137.70, stdev=72.17 lat (usec) : 2=0.01%, 4=0.20%, 10=1.61%, 20=0.55%, 50=2.16% lat (usec) : 100=0.37%, 250=0.02%, 500=0.01%, 1000=0.01% lat (msec) : 2=0.25%, 4=6.56%, 10=24.60%, 20=20.93%, 50=18.76% lat (msec) : 100=7.95%, 250=13.86%, 500=2.03%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.10% cpu : usr=0.08%, sys=0.18%, ctx=511723, majf=0, minf=5044 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=181562/w=181084/d=0, short=r=0/w=0/d=0 job1: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2972 read : io=2465.6MB, bw=136017 B/s, iops=9 , runt=19006854msec clat (usec): min=0 , max=676890 , avg=19367.84, stdev=25668.39 lat (usec): min=0 , max=676890 , avg=19368.44, stdev=25668.36 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2416], 10.00th=[ 3440], 20.00th=[ 4896], | 30.00th=[ 6432], 40.00th=[ 7904], 50.00th=[10176], 60.00th=[13376], | 70.00th=[18560], 80.00th=[27776], 90.00th=[45824], 95.00th=[68096], | 99.00th=[127488], 99.50th=[156672], 99.90th=[228352], 99.95th=[264192], | 99.99th=[329728] bw (KB/s) : min= 0, max= 1336, per=100.00%, avg=146.62, stdev=123.92 write: io=2468.1MB, bw=136204 B/s, iops=9 , runt=19006833msec clat (usec): min=9 , max=14876K, avg=85672.50, stdev=176996.64 lat (usec): min=9 , max=14876K, avg=85673.03, stdev=176996.64 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 53], 10.00th=[ 4576], 20.00th=[ 8640], | 30.00th=[12608], 40.00th=[18304], 50.00th=[27520], 60.00th=[44800], | 70.00th=[90624], 80.00th=[207872], 90.00th=[222208], 95.00th=[238592], | 99.00th=[309248], 99.50th=[419840], 99.90th=[2965504], 99.95th=[3489792], | 99.99th=[4882432] bw (KB/s) : min= 0, max= 1075, per=100.00%, avg=139.90, stdev=71.91 lat (usec) : 2=0.01%, 4=0.14%, 10=1.56%, 20=0.46%, 50=2.03% lat (usec) : 100=0.34%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.19%, 4=6.34%, 10=25.21%, 20=20.78%, 50=19.56% lat (msec) : 100=7.77%, 250=13.85%, 500=1.63%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.10% cpu : usr=0.09%, sys=0.18%, ctx=508804, majf=0, minf=5022 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=180153/w=180433/d=0, short=r=0/w=0/d=0 job2: (groupid=0, jobs=1): err= 0: pid=2973 lat (usec) : 2=0.01%, 4=0.12%, 10=1.59%, 20=0.43%, 50=2.12% lat (usec) : 100=0.35%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.18%, 4=6.01%, 10=25.66%, 20=21.21%, 50=19.36% lat (msec) : 100=7.43%, 250=13.83%, 500=1.57%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.09% cpu : usr=0.00%, sys=0.00%, ctx=0, majf=0, minf=0 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=177564/w=177672/d=0, short=r=0/w=0/d=0 job3: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2974 read : io=2390.2MB, bw=140347 B/s, iops=9 , runt=17857819msec clat (usec): min=0 , max=887053 , avg=17706.34, stdev=22150.19 lat (usec): min=0 , max=887053 , avg=17707.05, stdev=22150.29 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2384], 10.00th=[ 3408], 20.00th=[ 4832], | 30.00th=[ 6304], 40.00th=[ 7776], 50.00th=[ 9792], 60.00th=[12864], | 70.00th=[17536], 80.00th=[25472], 90.00th=[41216], 95.00th=[60160], | 99.00th=[109056], 99.50th=[134144], 99.90th=[189440], 99.95th=[218112], | 99.99th=[276480] bw (KB/s) : min= 0, max= 1320, per=100.00%, avg=148.80, stdev=127.62 write: io=2383.6MB, bw=139959 B/s, iops=9 , runt=17857809msec clat (usec): min=9 , max=8970.8K, avg=84432.85, stdev=154437.54 lat (usec): min=9 , max=8970.8K, avg=84433.38, stdev=154437.55 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 49], 10.00th=[ 4512], 20.00th=[ 8640], | 30.00th=[12480], 40.00th=[18048], 50.00th=[26752], 60.00th=[43264], | 70.00th=[93696], 80.00th=[207872], 90.00th=[222208], 95.00th=[236544], | 99.00th=[292864], 99.50th=[415744], 99.90th=[2703360], 99.95th=[3260416], | 99.99th=[4177920] bw (KB/s) : min= 0, max= 1120, per=100.00%, avg=142.03, stdev=74.82 lat (usec) : 2=0.01%, 4=0.15%, 10=1.65%, 20=0.47%, 50=2.11% lat (usec) : 100=0.36%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.19%, 4=6.20%, 10=25.65%, 20=21.48%, 50=19.38% lat (msec) : 100=6.86%, 250=13.95%, 500=1.44%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.08% cpu : usr=0.09%, sys=0.18%, ctx=493832, majf=2, minf=4827 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=173997/w=174260/d=0, short=r=0/w=0/d=0 job4: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2975 read : io=2400.2MB, bw=132928 B/s, iops=9 , runt=18933247msec clat (usec): min=0 , max=862323 , avg=17747.97, stdev=21405.61 lat (usec): min=0 , max=862324 , avg=17748.77, stdev=21405.65 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2448], 10.00th=[ 3472], 20.00th=[ 4960], | 30.00th=[ 6496], 40.00th=[ 7904], 50.00th=[10048], 60.00th=[13120], | 70.00th=[17792], 80.00th=[25728], 90.00th=[41728], 95.00th=[60160], | 99.00th=[105984], 99.50th=[127488], 99.90th=[173056], 99.95th=[197632], | 99.99th=[240640] bw (KB/s) : min= 0, max= 1237, per=100.00%, avg=148.37, stdev=123.43 write: io=2434.1MB, bw=134855 B/s, iops=9 , runt=18933206msec clat (usec): min=10 , max=584767K, avg=89479.53, stdev=1404088.00 lat (usec): min=10 , max=584767K, avg=89480.07, stdev=1404088.00 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 47], 10.00th=[ 4576], 20.00th=[ 8512], | 30.00th=[12480], 40.00th=[18048], 50.00th=[26752], 60.00th=[43264], | 70.00th=[89600], 80.00th=[209920], 90.00th=[222208], 95.00th=[238592], | 99.00th=[329728], 99.50th=[428032], 99.90th=[3031040], 99.95th=[3489792], | 99.99th=[5013504] bw (KB/s) : min= 0, max= 1263, per=100.00%, avg=143.23, stdev=70.67 lat (usec) : 2=0.01%, 4=0.15%, 10=1.59%, 20=0.49%, 50=2.18% lat (usec) : 100=0.35%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.16%, 4=6.00%, 10=25.52%, 20=21.50%, 50=19.68% lat (msec) : 100=7.07%, 250=13.58%, 500=1.59%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.10% cpu : usr=0.08%, sys=0.18%, ctx=499570, majf=0, minf=4868 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=174353/w=176293/d=0, short=r=0/w=0/d=0 job5: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2976 read : io=2391.2MB, bw=133960 B/s, iops=9 , runt=18716957msec clat (usec): min=0 , max=891313 , avg=17602.87, stdev=21152.14 lat (usec): min=1 , max=891314 , avg=17603.74, stdev=21152.97 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2416], 10.00th=[ 3472], 20.00th=[ 4896], | 30.00th=[ 6432], 40.00th=[ 7840], 50.00th=[ 9920], 60.00th=[13120], | 70.00th=[17792], 80.00th=[25472], 90.00th=[41216], 95.00th=[59136], | 99.00th=[104960], 99.50th=[125440], 99.90th=[171008], 99.95th=[193536], | 99.99th=[236544] bw (KB/s) : min= 0, max= 1581, per=100.00%, avg=148.09, stdev=122.04 write: io=2395.2MB, bw=134185 B/s, iops=9 , runt=18716860msec clat (usec): min=11 , max=386265K, avg=89290.72, stdev=977978.29 lat (usec): min=11 , max=386265K, avg=89291.25, stdev=977978.29 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 48], 10.00th=[ 4576], 20.00th=[ 8512], | 30.00th=[12480], 40.00th=[18048], 50.00th=[27008], 60.00th=[43776], | 70.00th=[93696], 80.00th=[209920], 90.00th=[222208], 95.00th=[238592], | 99.00th=[317440], 99.50th=[423936], 99.90th=[2932736], 99.95th=[3424256], | 99.99th=[4751360] bw (KB/s) : min= 0, max= 1385, per=100.00%, avg=141.05, stdev=64.15 lat (usec) : 2=0.01%, 4=0.16%, 10=1.63%, 20=0.48%, 50=2.14% lat (usec) : 100=0.35%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.17%, 4=6.01%, 10=25.63%, 20=21.42%, 50=19.63% lat (msec) : 100=6.95%, 250=13.69%, 500=1.59%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.10% cpu : usr=0.08%, sys=0.18%, ctx=497146, majf=0, minf=4853 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=174488/w=174566/d=0, short=r=0/w=0/d=0 job6: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2977 read : io=2385.6MB, bw=139486 B/s, iops=9 , runt=17932764msec clat (usec): min=0 , max=1125.3K, avg=17923.32, stdev=22716.56 lat (usec): min=0 , max=1125.3K, avg=17927.72, stdev=22731.16 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2416], 10.00th=[ 3440], 20.00th=[ 4896], | 30.00th=[ 6368], 40.00th=[ 7776], 50.00th=[ 9792], 60.00th=[12992], | 70.00th=[17536], 80.00th=[25728], 90.00th=[41728], 95.00th=[61696], | 99.00th=[112128], 99.50th=[136192], 99.90th=[189440], 99.95th=[211968], | 99.99th=[264192] bw (KB/s) : min= 0, max= 1299, per=100.00%, avg=148.31, stdev=124.58 write: io=2370.9MB, bw=138631 B/s, iops=9 , runt=17932561msec clat (usec): min=9 , max=8897.9K, avg=85392.70, stdev=157427.16 lat (usec): min=10 , max=8897.9K, avg=85393.23, stdev=157427.17 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 49], 10.00th=[ 4576], 20.00th=[ 8640], | 30.00th=[12480], 40.00th=[18048], 50.00th=[27008], 60.00th=[44288], | 70.00th=[96768], 80.00th=[207872], 90.00th=[222208], 95.00th=[238592], | 99.00th=[296960], 99.50th=[419840], 99.90th=[2736128], 99.95th=[3260416], | 99.99th=[4358144] bw (KB/s) : min= 0, max= 973, per=100.00%, avg=140.76, stdev=70.43 lat (usec) : 2=0.01%, 4=0.14%, 10=1.60%, 20=0.48%, 50=2.11% lat (usec) : 100=0.34%, 250=0.03%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.20%, 4=6.19%, 10=25.72%, 20=21.31%, 50=19.25% lat (msec) : 100=7.05%, 250=14.00%, 500=1.50%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.08% cpu : usr=0.09%, sys=0.18%, ctx=491998, majf=0, minf=4825 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=173755/w=172811/d=0, short=r=0/w=0/d=0 job7: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2978 read : io=2505.2MB, bw=137126 B/s, iops=9 , runt=19162681msec clat (usec): min=0 , max=529888 , avg=17997.31, stdev=22709.91 lat (usec): min=1 , max=529888 , avg=17998.78, stdev=22710.20 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2384], 10.00th=[ 3408], 20.00th=[ 4832], | 30.00th=[ 6368], 40.00th=[ 7776], 50.00th=[ 9792], 60.00th=[12864], | 70.00th=[17536], 80.00th=[25728], 90.00th=[42240], 95.00th=[61696], | 99.00th=[113152], 99.50th=[138240], 99.90th=[197632], 99.95th=[220160], | 99.99th=[280576] bw (KB/s) : min= 0, max= 1299, per=100.00%, avg=150.86, stdev=123.59 write: io=2504.4MB, bw=137035 B/s, iops=9 , runt=19162649msec clat (usec): min=9 , max=384337K, avg=87058.85, stdev=918383.55 lat (usec): min=10 , max=384337K, avg=87059.40, stdev=918383.55 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 51], 10.00th=[ 4512], 20.00th=[ 8384], | 30.00th=[12352], 40.00th=[17792], 50.00th=[26240], 60.00th=[42240], | 70.00th=[86528], 80.00th=[207872], 90.00th=[222208], 95.00th=[238592], | 99.00th=[321536], 99.50th=[423936], 99.90th=[2965504], 99.95th=[3489792], | 99.99th=[4816896] bw (KB/s) : min= 0, max= 1412, per=100.00%, avg=143.60, stdev=69.52 lat (usec) : 2=0.01%, 4=0.19%, 10=1.59%, 20=0.50%, 50=2.06% lat (usec) : 100=0.35%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.18%, 4=6.43%, 10=25.73%, 20=21.31%, 50=19.41% lat (msec) : 100=7.09%, 250=13.43%, 500=1.60%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.10% cpu : usr=0.08%, sys=0.18%, ctx=517322, majf=0, minf=5020 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=182283/w=181812/d=0, short=r=0/w=0/d=0 job8: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2979 read : io=2356.8MB, bw=133678 B/s, iops=9 , runt=18486492msec clat (usec): min=0 , max=1035.4K, avg=19644.75, stdev=26623.29 lat (usec): min=1 , max=1035.4K, avg=19645.98, stdev=26623.37 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2416], 10.00th=[ 3440], 20.00th=[ 4896], | 30.00th=[ 6432], 40.00th=[ 7904], 50.00th=[10048], 60.00th=[13376], | 70.00th=[18560], 80.00th=[27776], 90.00th=[46848], 95.00th=[70144], | 99.00th=[132096], 99.50th=[160768], 99.90th=[232448], 99.95th=[272384], | 99.99th=[366592] bw (KB/s) : min= 0, max= 1434, per=100.00%, avg=142.83, stdev=121.65 write: io=2361.8MB, bw=133961 B/s, iops=9 , runt=18486447msec clat (usec): min=8 , max=15642K, avg=87303.80, stdev=168164.18 lat (usec): min=8 , max=15642K, avg=87304.33, stdev=168164.18 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 50], 10.00th=[ 4576], 20.00th=[ 8640], | 30.00th=[12736], 40.00th=[18560], 50.00th=[28544], 60.00th=[47360], | 70.00th=[103936], 80.00th=[209920], 90.00th=[222208], 95.00th=[240640], | 99.00th=[305152], 99.50th=[419840], 99.90th=[2899968], 99.95th=[3358720], | 99.99th=[4358144] bw (KB/s) : min= 0, max= 989, per=100.00%, avg=136.59, stdev=68.79 lat (usec) : 2=0.01%, 4=0.14%, 10=1.60%, 20=0.43%, 50=2.13% lat (usec) : 100=0.32%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.20%, 4=6.24%, 10=25.19%, 20=20.55%, 50=19.11% lat (msec) : 100=7.77%, 250=14.50%, 500=1.69%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.10% cpu : usr=0.08%, sys=0.18%, ctx=486694, majf=0, minf=4834 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=172010/w=172407/d=0, short=r=0/w=0/d=0 job9: (groupid=0, jobs=1): err=84 (file:io_u.c:1487, func=io_u_sync_complete, error=Invalid or incomplete multibyte or wide character): pid=2980 read : io=2492.4MB, bw=134240 B/s, iops=9 , runt=19467910msec clat (usec): min=0 , max=561451 , avg=20419.23, stdev=29312.48 lat (usec): min=0 , max=561452 , avg=20419.83, stdev=29312.44 clat percentiles (usec): | 1.00th=[ 4], 5.00th=[ 2224], 10.00th=[ 3184], 20.00th=[ 4704], | 30.00th=[ 6432], 40.00th=[ 7904], 50.00th=[ 9792], 60.00th=[13120], | 70.00th=[18304], 80.00th=[28544], 90.00th=[49408], 95.00th=[74240], | 99.00th=[146432], 99.50th=[181248], 99.90th=[264192], 99.95th=[309248], | 99.99th=[382976] bw (KB/s) : min= 0, max= 1492, per=100.00%, avg=146.12, stdev=123.90 write: io=2489.9MB, bw=134107 B/s, iops=9 , runt=19467892msec clat (usec): min=10 , max=131194K, avg=86442.14, stdev=357275.36 lat (usec): min=10 , max=131194K, avg=86442.68, stdev=357275.37 clat percentiles (usec): | 1.00th=[ 20], 5.00th=[ 40], 10.00th=[ 3952], 20.00th=[ 8096], | 30.00th=[12096], 40.00th=[17024], 50.00th=[25984], 60.00th=[44288], | 70.00th=[91648], 80.00th=[207872], 90.00th=[224256], 95.00th=[244736], | 99.00th=[346112], 99.50th=[428032], 99.90th=[3031040], 99.95th=[3522560], | 99.99th=[5079040] bw (KB/s) : min= 0, max= 923, per=100.00%, avg=138.94, stdev=71.74 lat (usec) : 2=0.01%, 4=0.22%, 10=1.63%, 20=0.57%, 50=2.18% lat (usec) : 100=0.36%, 250=0.02%, 500=0.01%, 750=0.01%, 1000=0.01% lat (msec) : 2=0.38%, 4=7.25%, 10=24.95%, 20=20.41%, 50=18.16% lat (msec) : 100=7.87%, 250=13.83%, 500=2.02%, 750=0.01%, 1000=0.01% lat (msec) : 2000=0.01%, >=2000=0.10% cpu : usr=0.08%, sys=0.18%, ctx=515307, majf=0, minf=5046 IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0% submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% complete : 0=0.1%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0% issued : total=r=182023/w=181629/d=0, short=r=0/w=0/d=0 Run status group 0 (all jobs): READ: io=21879MB, aggrb=1KB/s, minb=0KB/s, maxb=137KB/s, mint=17857819msec, maxt=18501748936msec WRITE: io=21881MB, aggrb=1KB/s, minb=0KB/s, maxb=136KB/s, mint=17857809msec, maxt=18501748936msec fio: file hash not empty on exit fio crash: (gdb) bt #0 0x0000000000429f7a in fio_md5_update (mctx=0x7fff49698040, data=0x1ceefc8 "", len=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/string3.h:52 #1 0x0000000000419077 in fill_md5 (len=472, p=0x1ceef48, hdr=0x1ceef20) at verify.c:850 #2 populate_hdr (td=0x7fbe446f2460, io_u=0x7fff49698250, hdr=0x1ceef20, header_num=88, header_len=<optimized out>) at verify.c:875 #3 0x000000000041967b in fill_pattern_headers (use_seed=1, seed=<optimized out>, io_u=0x7fff49698250, td=0x7fbe446f2460) at verify.c:100 #4 dump_verify_buffers (vc=0x7fff496984d0, hdr=<optimized out>) at verify.c:277 #5 0x000000000041aadd in verify_io_u_md5 (vc=0x7fff496984d0, hdr=0xc9bc90) at verify.c:588 #6 verify_io_u (td=0x7fbe446f2460, io_u=0xc7b530) at verify.c:713 #7 0x000000000041e896 in io_completed (td=0x7fbe446f2460, io_u=0xc7b530, icd=0x7fff49698710) at io_u.c:1423 #8 0x000000000041ebb9 in io_u_sync_complete (td=0x7fbe446f2460, io_u=0xc7b530, bytes=0x0) at io_u.c:1481 #9 0x0000000000438b17 in do_verify (td=0x7fbe446f2460) at backend.c:476 #10 thread_main (data=0x7fbe446f2460) at backend.c:1136 #11 0x000000000043918a in fork_main (offset=2, shmid=<optimized out>) at backend.c:1250 #12 run_threads () at backend.c:1492 #13 0x00000000004395fd in fio_backend () at backend.c:1662 #14 0x00007fbe4942576d in __libc_start_main () from /lib/x86_64-linux-gnu/libc.so.6 #15 0x0000000000407ead in _start () 48 __extern_always_inline void * 49 __NTH (memcpy (void *__restrict __dest, __const void *__restrict __src, 50 size_t __len)) 51 { 52 return __builtin___memcpy_chk (__dest, __src, __len, __bos0 (__dest)); 53 } On Mon, Jul 2, 2012 at 3:49 PM, Josef Bacik <jbacik@fusionio.com> wrote: > On Mon, Jul 02, 2012 at 05:48:43AM -0600, Alex Lyakas wrote: >> Hi Josef, >> which branch from your (or another?) repo should I try this on: >> > > Master, and make sure you've checked out a more recent fio from git to make sure > it's not a bug in fio. Thanks, > > Josef ^ permalink raw reply [flat|nested] 9+ messages in thread
end of thread, other threads:[~2012-07-03 10:35 UTC | newest] Thread overview: 9+ messages (download: mbox.gz follow: Atom feed -- links below jump to the message on this page -- 2012-06-25 18:30 fio reports data corruption with btrfs Alex Lyakas 2012-06-25 19:10 ` Josef Bacik 2012-06-25 19:26 ` Josef Bacik 2012-06-26 7:39 ` Alex Lyakas 2012-06-27 8:15 ` Alex Lyakas 2012-06-27 13:46 ` Josef Bacik 2012-07-02 11:48 ` Alex Lyakas 2012-07-02 12:49 ` Josef Bacik 2012-07-03 10:35 ` Alex Lyakas
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).