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
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs"
in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
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 -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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 -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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-- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs"
in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
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 -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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-- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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 -- To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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
--
To unsubscribe from this list: send the line "unsubscribe linux-btrfs"
in
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html