* xfs clones crash issue - illegal state 13 in block map
@ 2017-09-07 12:58 Amir Goldstein
2017-09-07 16:13 ` Darrick J. Wong
0 siblings, 1 reply; 8+ messages in thread
From: Amir Goldstein @ 2017-09-07 12:58 UTC (permalink / raw)
To: Darrick J. Wong, Christoph Hellwig; +Cc: linux-xfs
[-- Attachment #1: Type: text/plain, Size: 2327 bytes --]
Hi guys,
I am getting these errors often when running the crash tests
with cloned files (generic/502 in my xfstests patches).
Hitting these errors requires first fixing 2 other issues
that shadow over this issue:
"xfs: fix incorrect log_flushed on fsync" (in master)
"xfs: fix leftover CoW extent after truncate"
available on my tree based on Darrick's simple fix:
https://github.com/amir73il/linux/commits/xfs-fsync
I get the errors more often (1 out of 5) on a 100G fs on spinning disk.
On a 10G fs on SSD they are less frequent.
The log in this email was captured on patched stable 4.9.47 kernel,
but I am getting the same errors on patched upstream kernel.
I wasn't able to create a deterministic reproducer, so attaching
the full log from a failed test along with an IO log that can be
replayed on your disk to examine the outcome.
Following is the output of fsx process #5, which is the process
that wrote the problematic testfile5.mark0 to the log.
This process performs only read,zero,fsync before creating
the log mark.
The file testfile5 was cloned from an origin 256K file before
running fsx.
Later, I used the random seed 35484 in this log for all
processes and it seemed to increase the probability for failure.
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P
/mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5
/mnt/scratch/testfile5
Seed set to 35484
file_size=262144
5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
5: 3 fsync
5: Dumped fsync buffer to testfile5.mark0
In order to get to the crash state you need to get my
xfstests replay-log patches and replay the attached log
on a >= 100G scratch device:
# ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
$SCRATCH_DEV --end-mark testfile5.mark0
# mount $SCRATCH_DEV $SCRATCH_MNT
# umount $SCRATCH_MNT
# xfs_repair -n $SCRATCH_DEV
Phase 1 - find and verify superblock...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
- found root inode chunk
Phase 3 - for each AG...
- scan (but don't clear) agi unlinked lists...
- process known inodes and perform inode discovery...
- agno = 0
fatal error -- illegal state 13 in block map 376
Can anyone provide some insight?
Thanks,
Amir.
[-- Attachment #2: 502.full.xfs.testfile5.mark0 --]
[-- Type: application/octet-stream, Size: 56285 bytes --]
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 0 /mnt/scratch/testfile0
Seed set to 35469
file_size=262144
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 1 /mnt/scratch/testfile1
Seed set to 35472
file_size=262144
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 2 /mnt/scratch/testfile2
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 3 /mnt/scratch/testfile3
Seed set to 35475
file_size=262144
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 4 /mnt/scratch/testfile4
Seed set to 35478
file_size=262144
Seed set to 35481
file_size=262144
1 collapse from 0x14000 to 0x17000, (0x3000 bytes)
2 trunc from 0x3d000 to 0x3c9c2
3 write 0x26b76 thru 0x2939b (0x2826 bytes)
4 punch from 0x3b8b to 0x60a7, (0x251c bytes)
1: 1 mapwrite 0x3bde1 thru 0x3ffff (0x421f bytes)
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5 /mnt/scratch/testfile5
5 fsync
3: 1 punch from 0xfff to 0x20ba, (0x10bb bytes)
Seed set to 35484
file_size=262144
4: 1 falloc from 0x2cf41 to 0x36ecd (0x9f8c bytes)
4: 2 trunc from 0x40000 to 0x1c992
4: 3 zero from 0xcbfc to 0x1b6e5, (0xeae9 bytes)
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 6 /mnt/scratch/testfile6
Seed set to 35487
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 7 /mnt/scratch/testfile7
Seed set to 35490
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 8 /mnt/scratch/testfile8
Seed set to 35493
# /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 9 /mnt/scratch/testfile9
Seed set to 35495
5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
4: 4 insert from 0x7000 to 0x9000, (0x2000 bytes)
2: 1 mapread 0x1dd6e thru 0x232d3 (0x5566 bytes)
2: 2 punch from 0x13809 to 0x1d667, (0x9e5e bytes)
1: 2 punch from 0x7d16 to 0x9189, (0x1473 bytes)
file_size=262144
file_size=262144
file_size=262144
file_size=262144
4: 5 collapse from 0x2000 to 0x5000, (0x3000 bytes)
3: 2 mapwrite 0x34e9b thru 0x3f82d (0xa993 bytes)
5: 3 fsync
4: 6 read 0x302e thru 0xa61d (0x75f0 bytes)
6: 1 write 0x3bc56 thru 0x3ffff (0x43aa bytes)
6: 2 mapwrite 0x2a159 thru 0x3295e (0x8806 bytes)
2: 3 falloc from 0x199da to 0x27efe (0xe524 bytes)
2: 4 fsync
7: 1 mapwrite 0x1ffb4 thru 0x29a97 (0x9ae4 bytes)
8: 1 trunc from 0x40000 to 0xa4d4
8: 2 punch from 0x693a to 0xa4d4, (0x3b9a bytes)
1: 3 zero from 0xc80b to 0x18635, (0xbe2a bytes)
9: 1 punch from 0x36ed4 to 0x39fe9, (0x3115 bytes)
4: 7 trunc from 0x1b992 to 0xd20
4: 8 mapwrite 0x1240c thru 0x20fa2 (0xeb97 bytes)
Dumped fsync buffer to testfile0.mark0
6 mapwrite 0xe8f2 thru 0x1d9bb (0xf0ca bytes)
9: 2 punch from 0x311 to 0x5acc, (0x57bb bytes)
8: 3 fsync
1: 4 fsync
6: 3 collapse from 0x34000 to 0x3f000, (0xb000 bytes)
3: 3 write 0x35a83 thru 0x363fc (0x97a bytes)
3: 4 fsync
5: Dumped fsync buffer to testfile5.mark0
5: 4 fsync
9: 3 falloc from 0x183b4 to 0x20dda (0x8a26 bytes)
9: 4 collapse from 0x38000 to 0x3a000, (0x2000 bytes)
4: 9 punch from 0x18274 to 0x20fa3, (0x8d2f bytes)
2: Dumped fsync buffer to testfile2.mark0
2: 5 falloc from 0x38fba to 0x3fc1d (0x6c63 bytes)
7: 2 read 0x3e98d thru 0x3ffff (0x1673 bytes)
2: 6 zero from 0x1766b to 0x1f506, (0x7e9b bytes)
7: 3 fsync
7 falloc from 0x260c6 to 0x33300 (0xd23a bytes)
8 punch from 0x29f38 to 0x2cf02, (0x2fca bytes)
9: 5 collapse from 0x38000 to 0x39000, (0x1000 bytes)
9: 6 insert from 0x15000 to 0x18000, (0x3000 bytes)
5: Dumped fsync buffer to testfile5.mark1
5: 5 falloc from 0x15886 to 0x25180 (0xf8fa bytes)
5: 6 zero from 0x18f0b to 0x2114d, (0x8242 bytes)
6: 4 mapread 0x27110 thru 0x27cd7 (0xbc8 bytes)
6: 5 fsync
2: 7 write 0x3584 thru 0xb0c5 (0x7b42 bytes)
2: 8 punch from 0x5333 to 0x102ae, (0xaf7b bytes)
9: 7 punch from 0x3e344 to 0x40000, (0x1cbc bytes)
9 fsync
9: 8 zero from 0x37530 to 0x40000, (0x8ad0 bytes)
5: 8 read 0x30e3a thru 0x357ac (0x4973 bytes)
5: 9 fsync
1: Dumped fsync buffer to testfile1.mark0
1: 5 mapwrite 0x36923 thru 0x3918e (0x286c bytes)
4: 10 mapread 0x5966 thru 0x10995 (0xb030 bytes)
4: 11 falloc from 0x3010d to 0x3ef29 (0xee1c bytes)
4: 12 trunc from 0x3ef29 to 0x376ff
4: 13 punch from 0x1e1da to 0x253cc, (0x71f2 bytes)
4: 14 punch from 0x364a9 to 0x376ff, (0x1256 bytes)
4: 15 mapwrite 0x35b1d thru 0x3c152 (0x6636 bytes)
3: Dumped fsync buffer to testfile3.mark0
3: 5 mapread 0x1068d thru 0x205c1 (0xff35 bytes)
3: 6 mapwrite 0x30a78 thru 0x38831 (0x7dba bytes)
8: Dumped fsync buffer to testfile8.mark0
8: 4 zero from 0x763c to 0xa4d4, (0x2e98 bytes)
2: 9 fsync
8: 5 insert from 0x9000 to 0xb000, (0x2000 bytes)
6: Dumped fsync buffer to testfile6.mark0
6: 6 read 0xe65f thru 0x13a5a (0x53fc bytes)
6: 7 mapwrite 0x28fe thru 0xa083 (0x7786 bytes)
9: 10 punch from 0x170ae to 0x1947c, (0x23ce bytes)
9: 11 punch from 0x34594 to 0x377b6, (0x3222 bytes)
8: 6 fsync
7: Dumped fsync buffer to testfile7.mark0
7: 4 falloc from 0x2b47d to 0x36980 (0xb503 bytes)
7: 5 write 0x5b7d thru 0x8c08 (0x308c bytes)
7: 6 trunc from 0x40000 to 0x2551e
7: 7 fsync
5: Dumped fsync buffer to testfile5.mark2
5: 10 zero from 0x2bbf6 to 0x33221, (0x762b bytes)
1: 6 trunc from 0x40000 to 0x30fa5
1: 7 falloc from 0x3d144 to 0x40000 (0x2ebc bytes)
1: 8 punch from 0x18269 to 0x272e9, (0xf080 bytes)
Dumped fsync buffer to testfile0.mark1
11 punch from 0x37ea4 to 0x3c9c2, (0x4b1e bytes)
5: 11 read 0x35cf1 thru 0x3ffff (0xa30f bytes)
5: 12 punch from 0x2c331 to 0x39d14, (0xd9e3 bytes)
4: 16 mapwrite 0x21b7e thru 0x21efd (0x380 bytes)
9: 12 punch from 0x108a4 to 0x11c8a, (0x13e6 bytes)
12 insert from 0x18000 to 0x1b000, (0x3000 bytes)
1: 9 write 0x1e70d thru 0x26399 (0x7c8d bytes)
1: 10 write 0x68e4 thru 0xd698 (0x6db5 bytes)
1: 11 trunc from 0x30fa5 to 0x1a4ce
1: 13 zero from 0xd29f to 0x10ff2, (0x3d53 bytes)
6: 8 trunc from 0x35000 to 0x2822a
3: 8 collapse from 0x22000 to 0x24000, (0x2000 bytes)
3: 9 zero from 0xdf49 to 0x173f8, (0x94af bytes)
6: 9 punch from 0x1785d to 0x193e1, (0x1b84 bytes)
8: Dumped fsync buffer to testfile8.mark1
8: 7 fsync
2: Dumped fsync buffer to testfile2.mark1
2: 10 read 0x2e95f thru 0x36378 (0x7a1a bytes)
2: 11 falloc from 0x37e33 to 0x40000 (0x81cd bytes)
2: 12 punch from 0x32300 to 0x3c33a, (0xa03a bytes)
5: 13 punch from 0x2530b to 0x275be, (0x22b3 bytes)
14 trunc from 0x3f9c2 to 0x1123e
15 falloc from 0x2e0cf to 0x34d44 (0x6c75 bytes)
16 mapwrite 0xeb69 thru 0x1d914 (0xedac bytes)
3: 10 mapread 0x2a240 thru 0x3733e (0xd0ff bytes)
1: 14 mapread 0xabf1 thru 0x12e97 (0x82a7 bytes)
1: 15 insert from 0x3000 to 0x8000, (0x5000 bytes)
6: 10 fsync
9: 13 trunc from 0x40000 to 0x2df04
2: 13 punch from 0x10ae0 to 0x19adb, (0x8ffb bytes)
8: Dumped fsync buffer to testfile8.mark2
8: 8 trunc from 0xc4d4 to 0x3d14a
7: Dumped fsync buffer to testfile7.mark1
7: 8 write 0x2196e thru 0x314df (0xfb72 bytes)
7: 9 fsync
1: 16 falloc from 0x26ebe to 0x323be (0xb500 bytes)
1: 17 read 0x112a8 thru 0x1e4c4 (0xd21d bytes)
5: 14 zero from 0x3b4fe to 0x40000, (0x4b02 bytes)
2: 14 punch from 0xf5a3 to 0x19e91, (0xa8ee bytes)
8: 10 trunc from 0x3d14a to 0x22b29
8: 11 trunc from 0x22b29 to 0x3fc1b
8: 12 falloc from 0x35f93 to 0x40000 (0xa06d bytes)
8: 13 mapread 0x24bb9 thru 0x31697 (0xcadf bytes)
8: 14 fsync
9: 14 mapread 0x179c thru 0x65ec (0x4e51 bytes)
9: 15 zero from 0x47c9 to 0x124ba, (0xdcf1 bytes)
3: 11 write 0x35e08 thru 0x3b313 (0x550c bytes)
4: 17 punch from 0x2ffbf to 0x3a2e1, (0xa322 bytes)
5: 15 zero from 0x1e3a2 to 0x2a9ce, (0xc62c bytes)
3: 12 write 0xcd3b thru 0x138c4 (0x6b8a bytes)
3: 13 insert from 0x3d000 to 0x3f000, (0x2000 bytes)
3: 14 write 0x3d8ba thru 0x3ffff (0x2746 bytes)
2: 15 collapse from 0x39000 to 0x3f000, (0x6000 bytes)
3: 15 mapwrite 0x94de thru 0xb2dd (0x1e00 bytes)
1: 18 insert from 0xe000 to 0x12000, (0x4000 bytes)
1: 19 insert from 0x19000 to 0x1d000, (0x4000 bytes)
1: 20 read 0x334ff thru 0x3a3bd (0x6ebf bytes)
1: 21 write 0x7d97 thru 0x93f9 (0x1663 bytes)
4: 18 trunc from 0x3c153 to 0xf2dc
1: 22 mapwrite 0x2a010 thru 0x3023b (0x622c bytes)
4: 19 zero from 0x3668 to 0xbf66, (0x88fe bytes)
4: 20 zero from 0xba67 to 0xf2dc, (0x3875 bytes)
4: 21 read 0x80ae thru 0xf2db (0x722e bytes)
4: 22 trunc from 0xf2dc to 0x4715
4: 23 write 0x2e27d thru 0x3734d (0x90d1 bytes)
9: 16 zero from 0x61cc to 0xa86e, (0x46a2 bytes)
4: 24 mapwrite 0x3c13b thru 0x3fa2d (0x38f3 bytes)
9: 17 mapwrite 0x269f6 thru 0x308da (0x9ee5 bytes)
2: 16 insert from 0x13000 to 0x19000, (0x6000 bytes)
5: 16 collapse from 0x2c000 to 0x2e000, (0x2000 bytes)
2: 17 read 0x3f31 thru 0x8ed2 (0x4fa2 bytes)
2: 18 falloc from 0x3004c to 0x36efc (0x6eb0 bytes)
2: 19 trunc from 0x40000 to 0x10069
2: 20 falloc from 0x18252 to 0x23e59 (0xbc07 bytes)
2: 21 falloc from 0x357f4 to 0x3a7f3 (0x4fff bytes)
2: 22 collapse from 0x6000 to 0x15000, (0xf000 bytes)
2: 23 insert from 0x1000 to 0xa000, (0x9000 bytes)
2: 24 mapwrite 0x3eed5 thru 0x3ffff (0x112b bytes)
5: 17 falloc from 0x253c3 to 0x2a7af (0x53ec bytes)
5: 18 collapse from 0x28000 to 0x35000, (0xd000 bytes)
6: Dumped fsync buffer to testfile6.mark1
6: 11 falloc from 0x2063d to 0x251cb (0x4b8e bytes)
6: 12 fsync
17 fsync
7: Dumped fsync buffer to testfile7.mark2
7: 10 read 0x508d thru 0x5a60 (0x9d4 bytes)
7: 11 insert from 0x21000 to 0x23000, (0x2000 bytes)
5: 19 write 0x54fe thru 0xaf20 (0x5a23 bytes)
5: 20 insert from 0x2f000 to 0x3a000, (0xb000 bytes)
5: 21 insert from 0x0 to 0x4000, (0x4000 bytes)
3: 16 collapse from 0x27000 to 0x2e000, (0x7000 bytes)
Dumped fsync buffer to testfile0.mark2
18 mapwrite 0x26038 thru 0x2f17b (0x9144 bytes)
7: 12 mapread 0x2f089 thru 0x334df (0x4457 bytes)
5: 22 fsync
1: 23 write 0x9dd5 thru 0x1708c (0xd2b8 bytes)
1: 24 zero from 0x2e6c2 to 0x2f71a, (0x1058 bytes)
7: 13 trunc from 0x334e0 to 0x35af
8: Dumped fsync buffer to testfile8.mark3
8: 15 read 0x1ac73 thru 0x292ee (0xe67c bytes)
8: 16 falloc from 0x33a6b to 0x3bb92 (0x8127 bytes)
8: 17 mapread 0x1bd2e thru 0x25441 (0x9714 bytes)
7: 14 write 0x33192 thru 0x3e008 (0xae77 bytes)
8: 18 write 0x2f894 thru 0x355eb (0x5d58 bytes)
7: 15 zero from 0x2e5b0 to 0x394ce, (0xaf1e bytes)
8: 19 write 0x1c59d thru 0x27f2d (0xb991 bytes)
8: 20 read 0x1d1f9 thru 0x1ef74 (0x1d7c bytes)
8: 22 falloc from 0x1d8a8 to 0x2b959 (0xe0b1 bytes)
8: 23 trunc from 0x3fc1b to 0x1cd9c
8: 24 mapread 0x82ca thru 0xdf7a (0x5cb1 bytes)
8: 25 write 0x134f5 thru 0x19515 (0x6021 bytes)
8: 26 fsync
3: 17 collapse from 0x36000 to 0x37000, (0x1000 bytes)
3: 18 insert from 0x2e000 to 0x36000, (0x8000 bytes)
3: 19 fsync
4: 25 falloc from 0x23eb1 to 0x25562 (0x16b1 bytes)
4: 26 zero from 0x3b77f to 0x3fa2e, (0x42af bytes)
1: 25 collapse from 0x1d000 to 0x2c000, (0xf000 bytes)
9: 18 falloc from 0x23778 to 0x28204 (0x4a8c bytes)
2: 25 punch from 0xb277 to 0x1021f, (0x4fa8 bytes)
9: 19 read 0x15b27 thru 0x1a70a (0x4be4 bytes)
9: 20 read 0x1c6d9 thru 0x293b9 (0xcce1 bytes)
9: 21 fsync
7: 16 mapwrite 0x128d0 thru 0x1f493 (0xcbc4 bytes)
4: 27 punch from 0x23250 to 0x27872, (0x4622 bytes)
4: 28 collapse from 0x2000 to 0xa000, (0x8000 bytes)
6: Dumped fsync buffer to testfile6.mark2
6: 13 punch from 0x16993 to 0x261b8, (0xf825 bytes)
1: 26 zero from 0x1add5 to 0x2563b, (0xa866 bytes)
1: 27 trunc from 0x2b3be to 0x15619
1: 28 punch from 0x4959 to 0x835f, (0x3a06 bytes)
2: 26 collapse from 0x2d000 to 0x38000, (0xb000 bytes)
2: 27 punch from 0x2ae13 to 0x2c904, (0x1af1 bytes)
2: 28 zero from 0x26476 to 0x31a99, (0xb623 bytes)
2: 29 mapwrite 0x3f5d1 thru 0x3ffff (0xa2f bytes)
19 falloc from 0x379af to 0x40000 (0x8651 bytes)
20 mapwrite 0xf727 thru 0x12709 (0x2fe3 bytes)
6: 14 fsync
1: 29 punch from 0x6871 to 0x14972, (0xe101 bytes)
8: Dumped fsync buffer to testfile8.mark4
8: 27 collapse from 0x5000 to 0x7000, (0x2000 bytes)
5: Dumped fsync buffer to testfile5.mark3
5: 23 write 0x38446 thru 0x3ffff (0x7bba bytes)
5: 24 mapwrite 0x1cc54 thru 0x2ba27 (0xedd4 bytes)
4: 29 trunc from 0x37a2e to 0xbc78
4: 30 mapwrite 0x241c3 thru 0x33afc (0xf93a bytes)
8: 28 zero from 0x13eb6 to 0x1577b, (0x18c5 bytes)
9: Dumped fsync buffer to testfile9.mark0
9: 22 trunc from 0x308db to 0xec4f
9: 23 zero from 0x92d9 to 0xec4f, (0x5976 bytes)
9: 24 trunc from 0xec4f to 0x14ac9
9: 25 trunc from 0x14ac9 to 0x3fbc6
9: 26 collapse from 0x3b000 to 0x3f000, (0x4000 bytes)
9: 27 falloc from 0x1ccc0 to 0x29fa9 (0xd2e9 bytes)
9: 28 fsync
7: 17 read 0x189dc thru 0x25137 (0xc75c bytes)
2: 30 read 0xa61e thru 0x1653a (0xbf1d bytes)
7: 18 punch from 0x30681 to 0x37265, (0x6be4 bytes)
7: 19 punch from 0x10bb2 to 0x1e261, (0xd6af bytes)
1: 30 mapread 0xc9e3 thru 0xd9e8 (0x1006 bytes)
1: 31 zero from 0xc984 to 0x12e44, (0x64c0 bytes)
1: 32 trunc from 0x15619 to 0x230b0
1: 33 trunc from 0x230b0 to 0x24c4f
1: 34 write 0x6832 thru 0xa4b8 (0x3c87 bytes)
1: 35 zero from 0x21537 to 0x24c4f, (0x3718 bytes)
1: 36 falloc from 0x159a5 to 0x254d8 (0xfb33 bytes)
1: 37 write 0x1b9a1 thru 0x26046 (0xa6a6 bytes)
1: 38 collapse from 0x1a000 to 0x25000, (0xb000 bytes)
3: Dumped fsync buffer to testfile3.mark1
3: 20 write 0x36f28 thru 0x3ffff (0x90d8 bytes)
2: 31 trunc from 0x40000 to 0x26f77
7: 20 write 0x26957 thru 0x2cb14 (0x61be bytes)
7: 21 mapread 0x1ac67 thru 0x24ce3 (0xa07d bytes)
2: 32 mapread 0xf8fb thru 0x14638 (0x4d3e bytes)
7: 22 falloc from 0x27e5 to 0x7f31 (0x574c bytes)
2: 33 mapwrite 0x231cc thru 0x2e54c (0xb381 bytes)
7: 23 mapwrite 0x3d thru 0xc7cf (0xc793 bytes)
21 read 0x10f48 thru 0x18945 (0x79fe bytes)
22 zero from 0x442a to 0x5881, (0x1457 bytes)
23 punch from 0xd3da to 0x111b3, (0x3dd9 bytes)
8: 29 insert from 0x11000 to 0x15000, (0x4000 bytes)
3: 21 mapread 0x39e2b thru 0x3ffff (0x61d5 bytes)
3: 22 mapwrite 0x1f32 thru 0x20c0 (0x18f bytes)
8: 30 punch from 0x1339e to 0x1ce52, (0x9ab4 bytes)
8: 31 falloc from 0x37f7c to 0x40000 (0x8084 bytes)
24 zero from 0xbfde to 0xd1d0, (0x11f2 bytes)
8: 32 zero from 0x3a970 to 0x40000, (0x5690 bytes)
8: 33 collapse from 0x21000 to 0x25000, (0x4000 bytes)
1: 39 mapread 0x16d10 thru 0x1b046 (0x4337 bytes)
8: 34 collapse from 0x36000 to 0x3b000, (0x5000 bytes)
8: 35 falloc from 0x3f2a3 to 0x40000 (0xd5d bytes)
8: 36 read 0x22200 thru 0x27693 (0x5494 bytes)
8: 37 write 0x1dd1d thru 0x26fe4 (0x92c8 bytes)
8: 38 insert from 0xb000 to 0x14000, (0x9000 bytes)
1: 40 write 0x1ef79 thru 0x2c7cc (0xd854 bytes)
1: 41 read 0x477c thru 0x561a (0xe9f bytes)
1: 42 trunc from 0x2c7cd to 0x1591d
1: 43 punch from 0x9d88 to 0xf6a9, (0x5921 bytes)
6: Dumped fsync buffer to testfile6.mark3
6: 15 insert from 0x26000 to 0x2a000, (0x4000 bytes)
8: 39 write 0xe840 thru 0x1e431 (0xfbf2 bytes)
8: 41 zero from 0x350b2 to 0x3edc6, (0x9d14 bytes)
8: 42 punch from 0x236c0 to 0x332bb, (0xfbfb bytes)
8: 43 zero from 0x280f4 to 0x37a85, (0xf991 bytes)
8: 44 punch from 0x21097 to 0x2b358, (0xa2c1 bytes)
8: 45 zero from 0x19b32 to 0x258f4, (0xbdc2 bytes)
4: 31 zero from 0x3164a to 0x33afd, (0x24b3 bytes)
5: 25 mapwrite 0xaf87 thru 0xb645 (0x6bf bytes)
9: Dumped fsync buffer to testfile9.mark1
9: 29 insert from 0xe000 to 0x12000, (0x4000 bytes)
9: 31 zero from 0x3ce93 to 0x3fbc6, (0x2d33 bytes)
9: 32 falloc from 0x134ff to 0x171ae (0x3caf bytes)
9: 33 read 0x6e73 thru 0xac3e (0x3dcc bytes)
9: 34 zero from 0x2b4a9 to 0x2e1d1, (0x2d28 bytes)
9: 35 write 0x2e9e thru 0x99d3 (0x6b36 bytes)
9: 36 mapread 0x7049 thru 0x110c6 (0xa07e bytes)
9: 37 trunc from 0x3fbc6 to 0xec37
9: 38 collapse from 0xb000 to 0xd000, (0x2000 bytes)
9: 39 falloc from 0x2e066 to 0x3544f (0x73e9 bytes)
6: 16 fsync
7: 24 mapread 0x21cd0 thru 0x2ab79 (0x8eaa bytes)
7: 25 zero from 0xe099 to 0x1b672, (0xd5d9 bytes)
7: 26 collapse from 0x18000 to 0x1c000, (0x4000 bytes)
2: 34 fsync
3: 23 trunc from 0x40000 to 0x3b443
3: 24 zero from 0x34799 to 0x3b416, (0x6c7d bytes)
1: 44 fsync
25 punch from 0x2b0b6 to 0x34d44, (0x9c8e bytes)
4: 32 write 0x63fe thru 0xa2fe (0x3f01 bytes)
4: 33 read 0x1c9c7 thru 0x23d8e (0x73c8 bytes)
4: 34 read 0x273f8 thru 0x2d096 (0x5c9f bytes)
4: 35 mapwrite 0x10cf2 thru 0x11bfe (0xf0d bytes)
8: 46 write 0x2dafd thru 0x386fb (0xabff bytes)
8: 47 falloc from 0x27563 to 0x2eb56 (0x75f3 bytes)
8: 48 trunc from 0x40000 to 0x1f1e0
8: 49 mapread 0x1b223 thru 0x1f1df (0x3fbd bytes)
8: 50 mapwrite 0x38a20 thru 0x3a828 (0x1e09 bytes)
9: 40 trunc from 0xcc37 to 0x3d33c
9: 41 read 0x1e90d thru 0x23abb (0x51af bytes)
9: 42 zero from 0x156b1 to 0x1f800, (0xa14f bytes)
9: 43 falloc from 0x219a8 to 0x2dbe3 (0xc23b bytes)
9: 44 fsync
26 mapread 0x288f6 thru 0x343f2 (0xbafd bytes)
27 read 0x27aa3 thru 0x2cabb (0x5019 bytes)
28 trunc from 0x34d44 to 0x3b132
29 mapread 0x1668e thru 0x1b899 (0x520c bytes)
30 read 0x36ccd thru 0x3b131 (0x4465 bytes)
31 falloc from 0xf487 to 0x1d1e7 (0xdd60 bytes)
32 read 0x1c02e thru 0x1d251 (0x1224 bytes)
33 mapwrite 0x28922 thru 0x356f5 (0xcdd4 bytes)
3: 25 collapse from 0x18000 to 0x24000, (0xc000 bytes)
7: 27 mapread 0x17837 thru 0x1aa30 (0x31fa bytes)
3: 26 write 0x3503a thru 0x3a124 (0x50eb bytes)
3: 27 punch from 0x203e to 0xbff6, (0x9fb8 bytes)
7: 28 falloc from 0x10309 to 0x1cc72 (0xc969 bytes)
7: 29 write 0x17aeb thru 0x1b709 (0x3c1f bytes)
7: 30 read 0x2b637 thru 0x390d4 (0xda9e bytes)
6: Dumped fsync buffer to testfile6.mark4
6: 17 collapse from 0x8000 to 0x11000, (0x9000 bytes)
7: 31 mapwrite 0x767f thru 0x15a2f (0xe3b1 bytes)
5: 26 read 0xa037 thru 0x1241a (0x83e4 bytes)
4: 36 mapread 0x304e3 thru 0x33afc (0x361a bytes)
8: 51 write 0x2ee24 thru 0x3cd28 (0xdf05 bytes)
5: 27 mapread 0x19d41 thru 0x1c0eb (0x23ab bytes)
4: 37 trunc from 0x33afd to 0x18237
5: 28 mapread 0x2cfa2 thru 0x3c920 (0xf97f bytes)
8: 52 read 0x79f9 thru 0x8789 (0xd91 bytes)
8: 53 read 0x1d31e thru 0x24d26 (0x7a09 bytes)
5: 29 mapwrite 0x337a2 thru 0x36adb (0x333a bytes)
8: 54 falloc from 0x2fbd2 to 0x3922e (0x965c bytes)
8: 55 trunc from 0x3cd29 to 0x28ec7
4: 38 fsync
8: 56 write 0x23b0a thru 0x25303 (0x17fa bytes)
8: 57 mapwrite 0x2ed75 thru 0x36b90 (0x7e1c bytes)
3: 28 falloc from 0x302d2 to 0x36668 (0x6396 bytes)
3: 29 mapread 0x407c thru 0xeeef (0xae74 bytes)
3: 30 mapread 0x173e thru 0x8ca4 (0x7567 bytes)
3: 31 zero from 0x1e510 to 0x226fa, (0x41ea bytes)
6: 18 fsync
2: Dumped fsync buffer to testfile2.mark2
2: 35 insert from 0x6000 to 0x14000, (0xe000 bytes)
2: 36 read 0xb7ba thru 0xfa0b (0x4252 bytes)
2: 37 read 0x11c83 thru 0x1f93e (0xdcbc bytes)
1: Dumped fsync buffer to testfile1.mark1
1: 45 write 0x3e1c3 thru 0x3ffff (0x1e3d bytes)
1: 46 zero from 0x1f92c to 0x2b7d0, (0xbea4 bytes)
1: 47 read 0x1f99c thru 0x2d880 (0xdee5 bytes)
1: 48 mapread 0x22568 thru 0x2e672 (0xc10b bytes)
1: 49 collapse from 0x15000 to 0x18000, (0x3000 bytes)
34 write 0x20eba thru 0x2afcd (0xa114 bytes)
35 write 0xa3d3 thru 0x1440c (0xa03a bytes)
36 read 0x1a731 thru 0x1c025 (0x18f5 bytes)
37 punch from 0x20ac6 to 0x26837, (0x5d71 bytes)
3: 32 falloc from 0x16755 to 0x1b524 (0x4dcf bytes)
3: 33 collapse from 0x20000 to 0x2b000, (0xb000 bytes)
2: 38 zero from 0x22d8a to 0x2c402, (0x9678 bytes)
2: 39 read 0xdb1c thru 0x1b56e (0xda53 bytes)
2: 40 trunc from 0x3c54d to 0x1f67a
2: 41 mapwrite 0x2cb89 thru 0x340ac (0x7524 bytes)
9: Dumped fsync buffer to testfile9.mark2
9: 45 collapse from 0x22000 to 0x2f000, (0xd000 bytes)
9: 46 falloc from 0x1cb75 to 0x28e63 (0xc2ee bytes)
9: 47 collapse from 0x2a000 to 0x2c000, (0x2000 bytes)
9: 48 fsync
7: 32 mapread 0x10363 thru 0x19791 (0x942f bytes)
7: 33 insert from 0x29000 to 0x2c000, (0x3000 bytes)
1: 50 write 0xcf73 thru 0xe516 (0x15a4 bytes)
1: 51 trunc from 0x3d000 to 0x34b91
1: 52 zero from 0x7bb4 to 0xafa1, (0x33ed bytes)
8: 58 collapse from 0x3000 to 0x5000, (0x2000 bytes)
5: 30 zero from 0x3c35b to 0x40000, (0x3ca5 bytes)
38 trunc from 0x3b132 to 0x526f
3: 34 falloc from 0x19332 to 0x20022 (0x6cf0 bytes)
3: 35 zero from 0x126b8 to 0x1ae19, (0x8761 bytes)
7: 34 write 0x24dfe thru 0x29dd4 (0x4fd7 bytes)
1: 53 insert from 0x1f000 to 0x2a000, (0xb000 bytes)
7: 35 read 0x14720 thru 0x1e124 (0x9a05 bytes)
7: 36 trunc from 0x3d009 to 0x32cba
1: 55 read 0x27f8b thru 0x33de2 (0xbe58 bytes)
1: 56 mapwrite 0x3b7a9 thru 0x3ffff (0x4857 bytes)
7: 37 read 0xf5de thru 0x12c3a (0x365d bytes)
7: 38 zero from 0x8ace to 0xba4b, (0x2f7d bytes)
4: Dumped fsync buffer to testfile4.mark0
4: 39 mapwrite 0x3d2ec thru 0x3ffff (0x2d14 bytes)
39 fsync
8: 59 punch from 0x2ca6 to 0x1292b, (0xfc85 bytes)
9: Dumped fsync buffer to testfile9.mark3
9: 49 mapwrite 0x15cf0 thru 0x1e80c (0x8b1d bytes)
5: 31 collapse from 0x5000 to 0x10000, (0xb000 bytes)
2: 42 collapse from 0x1f000 to 0x27000, (0x8000 bytes)
7: 39 zero from 0xe8c3 to 0x15eb8, (0x75f5 bytes)
3: 36 read 0x2ee2d thru 0x2f124 (0x2f8 bytes)
6: Dumped fsync buffer to testfile6.mark5
6: 19 fsync
2: 43 fsync
5: 32 punch from 0x26587 to 0x26de9, (0x862 bytes)
5: 33 falloc from 0x23f70 to 0x2c4b7 (0x8547 bytes)
5: 34 falloc from 0x326f8 to 0x3afef (0x88f7 bytes)
5: 35 falloc from 0x34bbe to 0x40000 (0xb442 bytes)
5: 36 collapse from 0x10000 to 0x16000, (0x6000 bytes)
5: 37 punch from 0x2679f to 0x2862d, (0x1e8e bytes)
1: 57 mapwrite 0x1744 thru 0x697f (0x523c bytes)
6: Dumped fsync buffer to testfile6.mark6
6: 20 mapwrite 0x94b0 thru 0x1696d (0xd4be bytes)
4: 40 mapread 0x5361 thru 0x10dcd (0xba6d bytes)
4: 41 fsync
8: 60 read 0xd843 thru 0x10d67 (0x3525 bytes)
8: 61 write 0x3ba98 thru 0x3ffff (0x4568 bytes)
8: 62 trunc from 0x40000 to 0x2e105
Dumped fsync buffer to testfile0.mark3
40 write 0x191c3 thru 0x244ce (0xb30c bytes)
41 write 0x11d13 thru 0x2128b (0xf579 bytes)
42 write 0x48e thru 0x94ff (0x9072 bytes)
43 read 0x1c4a7 thru 0x244ce (0x8028 bytes)
44 mapread 0x30bd thru 0x6ac6 (0x3a0a bytes)
45 read 0xc2ed thru 0x19a43 (0xd757 bytes)
5: 38 read 0x36a7b thru 0x36b16 (0x9c bytes)
5: 39 fsync
47 trunc from 0x244cf to 0x3d0bb
3: 37 collapse from 0x2b000 to 0x2e000, (0x3000 bytes)
8: 63 trunc from 0x2e105 to 0x2ecbb
8: 64 read 0x11cee thru 0x11ef1 (0x204 bytes)
8: 65 collapse from 0x2000 to 0xf000, (0xd000 bytes)
7: 40 write 0x2abec thru 0x34367 (0x977c bytes)
7: 41 fsync
48 mapwrite 0x22f4d thru 0x28d37 (0x5deb bytes)
9: 50 mapwrite 0x1d248 thru 0x2167b (0x4434 bytes)
3: 38 write 0x24f59 thru 0x2d5f6 (0x869e bytes)
3: 39 zero from 0x49c3 to 0x74ac, (0x2ae9 bytes)
3: 40 punch from 0x13619 to 0x1cef6, (0x98dd bytes)
8: 66 fsync
1: 58 write 0x9012 thru 0xa728 (0x1717 bytes)
1: 59 punch from 0x17b75 to 0x1e60d, (0x6a98 bytes)
1: 60 trunc from 0x40000 to 0xbd14
1: 61 trunc from 0xbd14 to 0xe87c
1: 62 trunc from 0xe87c to 0x3dd2f
1: 63 mapread 0x293af thru 0x379c7 (0xe619 bytes)
1: 64 fsync
4: Dumped fsync buffer to testfile4.mark1
4: 42 mapread 0xf92e thru 0x13ba2 (0x4275 bytes)
4: 43 fsync
5: Dumped fsync buffer to testfile5.mark4
5: 40 read 0x222a thru 0x6087 (0x3e5e bytes)
2: Dumped fsync buffer to testfile2.mark3
2: 44 read 0x4067 thru 0x13cf8 (0xfc92 bytes)
2: 45 mapread 0x940b thru 0xb2f4 (0x1eea bytes)
2: 46 punch from 0xd0cd to 0xdef2, (0xe25 bytes)
2: 47 falloc from 0x391aa to 0x3e3c2 (0x5218 bytes)
2: 48 mapread 0x27f58 thru 0x2c0ac (0x4155 bytes)
3: 41 mapwrite 0x7c3b thru 0xae0f (0x31d5 bytes)
9: 51 trunc from 0x2e33c to 0x9ce6
9: 52 mapwrite 0x3f590 thru 0x3f74f (0x1c0 bytes)
49 mapread 0x2f0be thru 0x37aee (0x8a31 bytes)
50 insert from 0xd000 to 0xf000, (0x2000 bytes)
6: 21 zero from 0x172cd to 0x2322a, (0xbf5d bytes)
51 write 0x2df99 thru 0x2e0c0 (0x128 bytes)
52 zero from 0x2d31 to 0x4e3f, (0x210e bytes)
5: 41 falloc from 0x326f to 0x4d60 (0x1af1 bytes)
4: Dumped fsync buffer to testfile4.mark2
5: 42 fsync
4: 44 write 0x23f1d thru 0x32254 (0xe338 bytes)
4: 45 collapse from 0xb000 to 0x13000, (0x8000 bytes)
2: 49 mapread 0x4a3 thru 0xac18 (0xa776 bytes)
2: 50 zero from 0x21264 to 0x27e10, (0x6bac bytes)
7: Dumped fsync buffer to testfile7.mark3
7: 42 fsync
6: 22 collapse from 0x1c000 to 0x22000, (0x6000 bytes)
4: 46 trunc from 0x38000 to 0xc5ab
2: 51 fsync
4: 47 write 0x20c9f thru 0x2a2c2 (0x9624 bytes)
4: 48 read 0xa8bf thru 0x1a279 (0xf9bb bytes)
4: 49 insert from 0x8000 to 0xd000, (0x5000 bytes)
4: 50 collapse from 0x22000 to 0x26000, (0x4000 bytes)
8: Dumped fsync buffer to testfile8.mark5
8: 67 falloc from 0x3caf3 to 0x40000 (0x350d bytes)
8: 68 read 0x19a45 thru 0x1fa34 (0x5ff0 bytes)
7: Dumped fsync buffer to testfile7.mark4
7: 43 collapse from 0x18000 to 0x25000, (0xd000 bytes)
8: 69 mapwrite 0x37867 thru 0x3c27c (0x4a16 bytes)
53 fsync
6: 23 insert from 0xa000 to 0xf000, (0x5000 bytes)
7: 44 collapse from 0x1f000 to 0x26000, (0x7000 bytes)
4: 51 collapse from 0xf000 to 0x16000, (0x7000 bytes)
1: Dumped fsync buffer to testfile1.mark2
1: 65 fsync
3: 42 trunc from 0x2d5f7 to 0x38380
9: 53 write 0x742c thru 0x81bb (0xd90 bytes)
9: 55 mapwrite 0x234cb thru 0x2a43f (0x6f75 bytes)
5: Dumped fsync buffer to testfile5.mark5
5: 43 zero from 0x2f350 to 0x3a000, (0xacb0 bytes)
1: Dumped fsync buffer to testfile1.mark3
1: 66 punch from 0x3b6fc to 0x3dd2f, (0x2633 bytes)
1: 67 mapwrite 0xa52d thru 0xd861 (0x3335 bytes)
5: 44 falloc from 0x2d258 to 0x37990 (0xa738 bytes)
5: 45 write 0x392eb thru 0x3face (0x67e4 bytes)
5: 46 mapread 0x3d462 thru 0x3face (0x266d bytes)
5: 47 trunc from 0x3facf to 0x25993
3: 43 write 0x19eb0 thru 0x1a9b3 (0xb04 bytes)
3: 44 falloc from 0x2830b to 0x341e1 (0xbed6 bytes)
3: 45 mapread 0x297b4 thru 0x2c3e9 (0x2c36 bytes)
3: 46 falloc from 0x3dd74 to 0x40000 (0x228c bytes)
3: 47 mapread 0x2f65d thru 0x35085 (0x5a29 bytes)
3: 48 trunc from 0x38380 to 0x3633d
3: 49 write 0x3fcb5 thru 0x3ffff (0x34b bytes)
3: 50 fsync
6: 24 read 0x20c10 thru 0x22229 (0x161a bytes)
7: 45 fsync
5: 48 collapse from 0x1c000 to 0x20000, (0x4000 bytes)
4: 52 mapwrite 0x12d78 thru 0x1a341 (0x75ca bytes)
6: 25 collapse from 0x18000 to 0x21000, (0x9000 bytes)
2: Dumped fsync buffer to testfile2.mark4
2: 52 insert from 0x17000 to 0x25000, (0xe000 bytes)
6: 26 write 0x3df0c thru 0x3ffff (0x20f4 bytes)
6: 27 falloc from 0x2731 to 0x9d87 (0x7656 bytes)
6: 28 collapse from 0x2e000 to 0x37000, (0x9000 bytes)
2: 53 read 0x1a53f thru 0x1c8d1 (0x2393 bytes)
2: 54 mapwrite 0x16f27 thru 0x21968 (0xaa42 bytes)
6: 29 fsync
5: 49 punch from 0xabc4 to 0x18029, (0xd465 bytes)
8: 70 collapse from 0x22000 to 0x27000, (0x5000 bytes)
1: 68 zero from 0x1cfda to 0x2c7b8, (0xf7de bytes)
9: 56 punch from 0x2b5c4 to 0x3612a, (0xab66 bytes)
1: 69 mapread 0x266ab thru 0x2c300 (0x5c56 bytes)
9: 57 mapwrite 0x5246 thru 0xdb91 (0x894c bytes)
1: 70 mapwrite 0x25b2e thru 0x2e879 (0x8d4c bytes)
5: 50 fsync
8: 71 trunc from 0x3727d to 0x14916
Dumped fsync buffer to testfile0.mark4
54 mapread 0x27535 thru 0x351ec (0xdcb8 bytes)
8: 72 falloc from 0xe20b to 0x10ec1 (0x2cb6 bytes)
8: 73 write 0x13157 thru 0x1c435 (0x92df bytes)
8: 74 mapwrite 0x38400 thru 0x3ef96 (0x6b97 bytes)
55 fsync
7: Dumped fsync buffer to testfile7.mark5
7: 46 zero from 0x14f62 to 0x1e870, (0x990e bytes)
2: 55 fsync
4: 53 read 0x12363 thru 0x21df1 (0xfa8f bytes)
4: 54 mapwrite 0x328f4 thru 0x3f1a7 (0xc8b4 bytes)
7: 47 punch from 0x1debc to 0x1e93e, (0xa82 bytes)
6: Dumped fsync buffer to testfile6.mark7
6: 30 write 0x1766a thru 0x206ff (0x9096 bytes)
3: Dumped fsync buffer to testfile3.mark2
3: 51 read 0x3f83e thru 0x3ffff (0x7c2 bytes)
3: 52 zero from 0xf591 to 0x1e72e, (0xf19d bytes)
1: 71 mapwrite 0x12772 thru 0x15c21 (0x34b0 bytes)
6: 31 mapread 0x41ac thru 0x134f6 (0xf34b bytes)
2: Dumped fsync buffer to testfile2.mark5
2: 56 zero from 0x14941 to 0x1c523, (0x7be2 bytes)
9: 58 falloc from 0x3e42b to 0x40000 (0x1bd5 bytes)
9: 59 write 0x834a thru 0xe61f (0x62d6 bytes)
9: 60 fsync
6: 32 zero from 0x2b31d to 0x35090, (0x9d73 bytes)
3: 53 falloc from 0x3973d to 0x40000 (0x68c3 bytes)
7: 48 insert from 0x15000 to 0x1d000, (0x8000 bytes)
3: 54 mapread 0x31282 thru 0x35343 (0x40c2 bytes)
3: 55 mapwrite 0x39435 thru 0x3c47f (0x304b bytes)
2: 57 read 0x39091 thru 0x3a0ac (0x101c bytes)
Dumped fsync buffer to testfile0.mark5
56 write 0x3a816 thru 0x3ffff (0x57ea bytes)
57 write 0x79b thru 0xe146 (0xd9ac bytes)
60 read 0x21a17 thru 0x29d7e (0x8368 bytes)
61 zero from 0x37662 to 0x40000, (0x899e bytes)
6: 33 punch from 0x1b513 to 0x1bfeb, (0xad8 bytes)
7: 49 mapread 0x22ac7 thru 0x28367 (0x58a1 bytes)
62 mapwrite 0x1563f thru 0x23bdd (0xe59f bytes)
5: Dumped fsync buffer to testfile5.mark6
5: 51 fsync
2: 58 fsync
4: 55 fsync
8: 75 trunc from 0x3ef97 to 0x68b8
7: 50 trunc from 0x28368 to 0x14a91
7: 51 zero from 0x8b57 to 0xf8cf, (0x6d78 bytes)
5: Dumped fsync buffer to testfile5.mark7
5: 52 mapread 0x17061 thru 0x17de2 (0xd82 bytes)
5: 53 collapse from 0xc000 to 0x15000, (0x9000 bytes)
8: 76 write 0xa8b8 thru 0xc781 (0x1eca bytes)
8: 77 insert from 0x3000 to 0x12000, (0xf000 bytes)
9: Dumped fsync buffer to testfile9.mark4
9: 62 mapwrite 0x15836 thru 0x1e81c (0x8fe7 bytes)
1: 72 write 0x3437f thru 0x3b9ea (0x766c bytes)
1: 73 fsync
4: Dumped fsync buffer to testfile4.mark3
4: 57 zero from 0xe372 to 0x12530, (0x41be bytes)
6: 34 write 0x3791e thru 0x385f3 (0xcd6 bytes)
6: 35 zero from 0x32960 to 0x385f4, (0x5c94 bytes)
7: 52 insert from 0x13000 to 0x17000, (0x4000 bytes)
7: 53 insert from 0x7000 to 0x15000, (0xe000 bytes)
8: 78 mapread 0xbb14 thru 0x134c5 (0x79b2 bytes)
8: 79 insert from 0x19000 to 0x1f000, (0x6000 bytes)
7: 54 insert from 0x1e000 to 0x2a000, (0xc000 bytes)
7: 55 trunc from 0x32a91 to 0x3e521
7: 56 mapread 0x35323 thru 0x3e520 (0x91fe bytes)
7: 57 trunc from 0x3e521 to 0x3fbae
7: 58 zero from 0xe397 to 0x18eca, (0xab33 bytes)
5: 54 write 0x3ab1a thru 0x3ffff (0x54e6 bytes)
5: 56 read 0x2ae72 thru 0x3183f (0x69ce bytes)
5: 57 fsync
7: 59 collapse from 0x25000 to 0x30000, (0xb000 bytes)
7: 60 fsync
3: 56 falloc from 0x1632 to 0x693a (0x5308 bytes)
3: 57 punch from 0x23a67 to 0x28de8, (0x5381 bytes)
4: 58 write 0x1fc3b thru 0x268d6 (0x6c9c bytes)
4: 59 mapread 0x34378 thru 0x3b73c (0x73c5 bytes)
4: 60 mapread 0x31b9 thru 0x7c83 (0x4acb bytes)
4: 61 write 0xa486 thru 0x10062 (0x5bdd bytes)
4: 62 mapread 0x35797 thru 0x3f1a7 (0x9a11 bytes)
4: 64 read 0x888d thru 0x14ea4 (0xc618 bytes)
4: 65 collapse from 0x6000 to 0xa000, (0x4000 bytes)
8: 80 punch from 0x3428 to 0x868f, (0x5267 bytes)
8: 81 mapwrite 0x28dac thru 0x2ceda (0x412f bytes)
6: 36 trunc from 0x385f4 to 0x3fc6f
6: 37 zero from 0x3b017 to 0x3fc6f, (0x4c58 bytes)
64 mapread 0x8b6f thru 0x10099 (0x752b bytes)
65 mapwrite 0x3ae12 thru 0x3ffff (0x51ee bytes)
3: 58 fsync
2: Dumped fsync buffer to testfile2.mark6
2: 59 read 0x27be thru 0xae19 (0x865c bytes)
2: 60 trunc from 0x3a0ad to 0x33655
2: 61 read 0x287 thru 0x9719 (0x9493 bytes)
2: 62 zero from 0xb3ba to 0x13bed, (0x8833 bytes)
2: 63 insert from 0x14000 to 0x1f000, (0xb000 bytes)
2: 64 insert from 0x10000 to 0x11000, (0x1000 bytes)
2: 65 punch from 0x26e7d to 0x33988, (0xcb0b bytes)
2: 67 mapwrite 0x32ce1 thru 0x3cf5e (0xa27e bytes)
4: 66 trunc from 0x3b1a8 to 0x17f71
1: Dumped fsync buffer to testfile1.mark4
1: 74 punch from 0x2f96 to 0xe98f, (0xb9f9 bytes)
9: 63 read 0x296a4 thru 0x3747a (0xddd7 bytes)
9: 64 falloc from 0x23de0 to 0x2611e (0x233e bytes)
9: 65 zero from 0xf210 to 0xff1d, (0xd0d bytes)
9: 66 mapwrite 0xda83 thru 0x11d19 (0x4297 bytes)
1: 75 punch from 0x12704 to 0x1eab6, (0xc3b2 bytes)
4: 67 fsync
6: 38 collapse from 0x27000 to 0x30000, (0x9000 bytes)
7: Dumped fsync buffer to testfile7.mark6
7: 61 read 0x21f96 thru 0x2c9c6 (0xaa31 bytes)
7: 62 collapse from 0x2b000 to 0x32000, (0x7000 bytes)
7: 63 read 0x2d91e thru 0x2dbad (0x290 bytes)
7: 64 mapwrite 0x6c95 thru 0xe92b (0x7c97 bytes)
1: 76 trunc from 0x3dd2f to 0x399f1
1: 77 collapse from 0x0 to 0xa000, (0xa000 bytes)
5: Dumped fsync buffer to testfile5.mark8
5: 59 mapwrite 0x2fa49 thru 0x39636 (0x9bee bytes)
66 fsync
8: 82 collapse from 0x6000 to 0xb000, (0x5000 bytes)
6: 39 mapread 0xda0e thru 0xf22d (0x1820 bytes)
6: 40 collapse from 0x1f000 to 0x21000, (0x2000 bytes)
3: Dumped fsync buffer to testfile3.mark3
3: 59 trunc from 0x40000 to 0x2ffed
3: 60 write 0x182de thru 0x18da9 (0xacc bytes)
3: 61 mapwrite 0x18b6f thru 0x23065 (0xa4f7 bytes)
9: 67 mapread 0x214a6 thru 0x2b148 (0x9ca3 bytes)
9: 69 mapwrite 0x231c2 thru 0x31223 (0xe062 bytes)
8: 83 collapse from 0x13000 to 0x14000, (0x1000 bytes)
2: 68 mapread 0xba50 thru 0x122e0 (0x6891 bytes)
2: 69 write 0x3a165 thru 0x3ffff (0x5e9b bytes)
2: 71 read 0x17fbb thru 0x221d7 (0xa21d bytes)
2: 72 collapse from 0x1c000 to 0x2a000, (0xe000 bytes)
4: Dumped fsync buffer to testfile4.mark4
4: 68 mapread 0x15f3a thru 0x17f70 (0x2037 bytes)
1: 78 mapwrite 0x22c5d thru 0x31b01 (0xeea5 bytes)
2: 73 trunc from 0x32000 to 0x1fa1f
2: 74 fsync
5: 60 trunc from 0x40000 to 0x1d08e
5: 61 punch from 0xb81 to 0xa3f9, (0x9878 bytes)
8: 84 falloc from 0x1db3f to 0x2c122 (0xe5e3 bytes)
6: 41 zero from 0xe150 to 0x1127f, (0x312f bytes)
8: 85 mapwrite 0x2744 thru 0x11505 (0xedc2 bytes)
4: 69 falloc from 0x295be to 0x37fa8 (0xe9ea bytes)
4: 70 collapse from 0x11000 to 0x16000, (0x5000 bytes)
7: 65 mapwrite 0x1161d thru 0x1adb2 (0x9796 bytes)
Dumped fsync buffer to testfile0.mark6
67 punch from 0x3c7ed to 0x40000, (0x3813 bytes)
5: 62 falloc from 0x1eaef to 0x246f4 (0x5c05 bytes)
5: 63 fsync
6: 42 collapse from 0xf000 to 0x12000, (0x3000 bytes)
4: 71 insert from 0xb000 to 0x18000, (0xd000 bytes)
4: 72 collapse from 0x20000 to 0x2b000, (0xb000 bytes)
4: 73 falloc from 0x1fb7c to 0x28179 (0x85fd bytes)
4: 74 read 0x5154 thru 0x6adb (0x1988 bytes)
4: 75 falloc from 0x2cef3 to 0x3b37e (0xe48b bytes)
4: 76 write 0x9af thru 0x4ff4 (0x4646 bytes)
4: 77 write 0x32186 thru 0x39844 (0x76bf bytes)
4: 78 mapread 0x1a698 thru 0x1b6da (0x1043 bytes)
68 write 0xeb3e thru 0x1b7ea (0xccad bytes)
70 fsync
9: 70 mapwrite 0x2f02a thru 0x38d54 (0x9d2b bytes)
4: 79 read 0xd8b6 thru 0x1993a (0xc085 bytes)
4: 80 mapwrite 0x321b8 thru 0x37960 (0x57a9 bytes)
3: 62 read 0x2d81b thru 0x2ffec (0x27d2 bytes)
3: 63 write 0x15496 thru 0x1c47a (0x6fe5 bytes)
3: 64 mapwrite 0xfe51 thru 0x16f03 (0x70b3 bytes)
2: Dumped fsync buffer to testfile2.mark7
2: 75 falloc from 0xab7a to 0x16da8 (0xc22e bytes)
2: 76 zero from 0x1e2c5 to 0x1fa1f, (0x175a bytes)
2: 78 write 0x1dd7 thru 0x42fb (0x2525 bytes)
2: 79 falloc from 0x3a0f3 to 0x40000 (0x5f0d bytes)
2: 80 fsync
7: 66 collapse from 0x27000 to 0x2d000, (0x6000 bytes)
7: 67 read 0x2cad thru 0x11de8 (0xf13c bytes)
7: 68 zero from 0x196 to 0xaf06, (0xad70 bytes)
6: 43 punch from 0x135ba to 0x20464, (0xceaa bytes)
1: 79 zero from 0x1acab to 0x1c102, (0x1457 bytes)
6: 45 insert from 0x5000 to 0xd000, (0x8000 bytes)
5: Dumped fsync buffer to testfile5.mark9
1: 80 mapread 0x1359f thru 0x17ba2 (0x4604 bytes)
5: 64 zero from 0x6c1a to 0x10c24, (0xa00a bytes)
1: 81 mapwrite 0x42d1 thru 0x758f (0x32bf bytes)
7: 69 write 0xe2a6 thru 0x1706a (0x8dc5 bytes)
7: 70 fsync
5: 65 trunc from 0x246f4 to 0x3b388
5: 66 fsync
Dumped fsync buffer to testfile0.mark7
71 collapse from 0x9000 to 0xc000, (0x3000 bytes)
72 zero from 0xa5e4 to 0xc495, (0x1eb1 bytes)
6: 46 read 0x4135 thru 0xb5d5 (0x74a1 bytes)
6: 47 insert from 0x28000 to 0x2b000, (0x3000 bytes)
4: 81 mapread 0xeb30 thru 0x116a2 (0x2b73 bytes)
8: 86 mapread 0x281e thru 0x4dff (0x25e2 bytes)
9: 71 trunc from 0x3f750 to 0x3ea69
4: 82 trunc from 0x3b37e to 0x3175b
8: 87 fsync
3: 65 fsync
9: 72 collapse from 0x10000 to 0x1a000, (0xa000 bytes)
4: 83 mapread 0x1eb7f thru 0x29c7a (0xb0fc bytes)
4: 84 falloc from 0x13197 to 0x20bd1 (0xda3a bytes)
4: 85 write 0x2251b thru 0x296d5 (0x71bb bytes)
9: 73 insert from 0x34000 to 0x3f000, (0xb000 bytes)
4: 86 trunc from 0x3175b to 0xa499
9: 74 read 0x10dc0 thru 0x153ff (0x4640 bytes)
4: 87 punch from 0x9d60 to 0xa499, (0x739 bytes)
9: 77 write 0x14c21 thru 0x21fbf (0xd39f bytes)
9: 78 mapwrite 0x26ef4 thru 0x28261 (0x136e bytes)
73 punch from 0x28854 to 0x37ab9, (0xf265 bytes)
6: 48 mapread 0x7c58 thru 0x1413f (0xc4e8 bytes)
2: Dumped fsync buffer to testfile2.mark8
2: 81 falloc from 0x24b0 to 0xbdb5 (0x9905 bytes)
2: 82 punch from 0x135f9 to 0x17e79, (0x4880 bytes)
2: 83 write 0x333ad thru 0x3e903 (0xb557 bytes)
2: 84 read 0x3c585 thru 0x3e903 (0x237f bytes)
2: 85 write 0x31e78 thru 0x39365 (0x74ee bytes)
2: 86 mapwrite 0x2ab70 thru 0x2e556 (0x39e7 bytes)
74 collapse from 0x7000 to 0x9000, (0x2000 bytes)
4: 89 write 0xc091 thru 0xcd1e (0xc8e bytes)
4: 90 mapread 0xb06e thru 0xcd1e (0x1cb1 bytes)
4: 91 read 0xfaf thru 0x63d6 (0x5428 bytes)
4: 92 write 0x1dedf thru 0x2aff0 (0xd112 bytes)
4: 93 punch from 0x5a6e to 0xad92, (0x5324 bytes)
75 mapwrite 0x13b8c thru 0x23685 (0xfafa bytes)
6: 49 write 0xebd7 thru 0x17b73 (0x8f9d bytes)
6: 50 mapwrite 0x3d28c thru 0x3db79 (0x8ee bytes)
4: 94 zero from 0x59b3 to 0xedd6, (0x9423 bytes)
5: Dumped fsync buffer to testfile5.mark10
5: 67 zero from 0x10ddc to 0x17d8c, (0x6fb0 bytes)
1: 82 trunc from 0x31b02 to 0x10bc1
1: 83 write 0x3c81a thru 0x3ffff (0x37e6 bytes)
1: 84 collapse from 0x3b000 to 0x3f000, (0x4000 bytes)
7: Dumped fsync buffer to testfile7.mark7
7: 71 mapread 0x21f00 thru 0x27bad (0x5cae bytes)
7: 72 read 0x43ac thru 0x5e3e (0x1a93 bytes)
7: 73 punch from 0xed56 to 0x1bbcc, (0xce76 bytes)
3: Dumped fsync buffer to testfile3.mark4
3: 66 trunc from 0x2ffed to 0x11fb4
3: 67 zero from 0x978e to 0x11fb4, (0x8826 bytes)
8: Dumped fsync buffer to testfile8.mark6
8: 88 write 0x3eb20 thru 0x3ffff (0x14e0 bytes)
8: 89 mapwrite 0xa619 thru 0x15842 (0xb22a bytes)
4: 95 zero from 0x2a697 to 0x2aff1, (0x95a bytes)
5: 68 collapse from 0x1000 to 0x6000, (0x5000 bytes)
9: 79 fsync
7: 74 fsync
1: 85 falloc from 0x23c5d to 0x28e3b (0x51de bytes)
1: 86 mapread 0x1eecc thru 0x26a0b (0x7b40 bytes)
5: 69 fsync
1: 87 falloc from 0x3f272 to 0x40000 (0xd8e bytes)
1: 89 mapread 0x308fc thru 0x3dd65 (0xd46a bytes)
2: 88 punch from 0x4987 to 0xbf35, (0x75ae bytes)
1: 91 zero from 0x20868 to 0x22825, (0x1fbd bytes)
1: 92 mapwrite 0x37a95 thru 0x3890a (0xe76 bytes)
4: 96 read 0x110b0 thru 0x1af2b (0x9e7c bytes)
4: 97 read 0x4ed6 thru 0x7fe7 (0x3112 bytes)
4: 98 mapwrite 0x34826 thru 0x3ffff (0xb7da bytes)
2: 89 punch from 0x2540f to 0x26fa0, (0x1b91 bytes)
2: 90 fsync
76 mapwrite 0x377c4 thru 0x3ea4a (0x7287 bytes)
3: 68 read 0x81bb thru 0xf53b (0x7381 bytes)
3: 69 read 0x35be thru 0xefe1 (0xba24 bytes)
3: 70 mapread 0x915e thru 0x11fb3 (0x8e56 bytes)
3: 71 punch from 0xdad8 to 0x11ef3, (0x441b bytes)
6: 51 read 0x2b668 thru 0x2ede6 (0x377f bytes)
6: 52 zero from 0xb9ba to 0x1887f, (0xcec5 bytes)
3: 73 read 0xa110 thru 0x11fb3 (0x7ea4 bytes)
3: 74 mapwrite 0x3e9 thru 0xef7d (0xeb95 bytes)
6: 53 mapwrite 0xe8f0 thru 0x12689 (0x3d9a bytes)
5: Dumped fsync buffer to testfile5.mark11
5: 70 read 0x32f65 thru 0x3358e (0x62a bytes)
5: 71 zero from 0x34252 to 0x35e87, (0x1c35 bytes)
5: 72 read 0xd969 thru 0x1d00a (0xf6a2 bytes)
8: 90 fsync
5: 73 mapread 0x312bb thru 0x36387 (0x50cd bytes)
5: 74 mapread 0x11ba thru 0x9677 (0x84be bytes)
5: 75 collapse from 0x34000 to 0x35000, (0x1000 bytes)
5: 76 mapwrite 0x1bd2c thru 0x1f559 (0x382e bytes)
7: Dumped fsync buffer to testfile7.mark8
7: 75 read 0xfc42 thru 0x121ef (0x25ae bytes)
7: 76 fsync
9: Dumped fsync buffer to testfile9.mark5
9: 80 mapwrite 0x16648 thru 0x250a8 (0xea61 bytes)
2: Dumped fsync buffer to testfile2.mark9
2: 91 write 0x14942 thru 0x165bf (0x1c7e bytes)
2: 92 mapwrite 0x3a197 thru 0x3d402 (0x326c bytes)
77 collapse from 0x1b000 to 0x26000, (0xb000 bytes)
4: 99 mapread 0x7c27 thru 0xa25e (0x2638 bytes)
1: 93 punch from 0xbf to 0xef8a, (0xeecb bytes)
4: 100 trunc from 0x40000 to 0x1d2dc
9: 81 write 0x6987 thru 0xe338 (0x79b2 bytes)
9: 82 fsync
1: 94 punch from 0x191b7 to 0x23a94, (0xa8dd bytes)
1: 95 punch from 0xbec4 to 0x1a35e, (0xe49a bytes)
4: All 100 operations completed A-OK!
1: 96 write 0x87c9 thru 0xc480 (0x3cb8 bytes)
1: 97 mapread 0xe186 thru 0x123a4 (0x421f bytes)
1: 98 mapwrite 0x2ba73 thru 0x31480 (0x5a0e bytes)
78 falloc from 0x3e2ee to 0x40000 (0x1d12 bytes)
79 mapwrite 0xe3a6 thru 0x11f7e (0x3bd9 bytes)
2: 93 read 0x32b2 thru 0xf9f2 (0xc741 bytes)
2: 94 falloc from 0xcbbf to 0x18932 (0xbd73 bytes)
2: 95 collapse from 0x1c000 to 0x25000, (0x9000 bytes)
7: Dumped fsync buffer to testfile7.mark9
7: 77 mapread 0x3a76 thru 0x63f3 (0x297e bytes)
7: 78 collapse from 0x6000 to 0x12000, (0xc000 bytes)
7: 79 write 0x2748 thru 0x7f1b (0x57d4 bytes)
7: 80 insert from 0x4000 to 0xf000, (0xb000 bytes)
6: 54 insert from 0x35000 to 0x37000, (0x2000 bytes)
3: 75 trunc from 0x11fb4 to 0x3ca
5: 77 mapread 0x1b933 thru 0x1eb46 (0x3214 bytes)
5: 78 read 0x1ff3e thru 0x262a6 (0x6369 bytes)
5: 79 mapread 0x25bd8 thru 0x29920 (0x3d49 bytes)
5: 80 zero from 0x24936 to 0x28e36, (0x4500 bytes)
5: 81 trunc from 0x35388 to 0x246a2
3: 76 fsync
5: 82 trunc from 0x246a2 to 0x23875
5: 83 trunc from 0x23875 to 0x7a3
5: 84 insert from 0x0 to 0xb000, (0xb000 bytes)
5: 85 collapse from 0x2000 to 0xa000, (0x8000 bytes)
5: 87 insert from 0x3000 to 0x4000, (0x1000 bytes)
5: 88 fsync
2: 96 trunc from 0x35904 to 0x36672
2: 97 fsync
7: 81 mapread 0xc9a1 thru 0x119a5 (0x5005 bytes)
6: 55 collapse from 0x7000 to 0x8000, (0x1000 bytes)
8: Dumped fsync buffer to testfile8.mark7
8: 91 punch from 0x3bd02 to 0x40000, (0x42fe bytes)
8: 92 falloc from 0x24d79 to 0x2c3ab (0x7632 bytes)
8: 93 collapse from 0x22000 to 0x30000, (0xe000 bytes)
8: 94 insert from 0x27000 to 0x35000, (0xe000 bytes)
8: 95 falloc from 0x31e45 to 0x3ac3f (0x8dfa bytes)
8: 96 collapse from 0x0 to 0x5000, (0x5000 bytes)
8: 97 read 0x21cd4 thru 0x2e65f (0xc98c bytes)
8: 98 mapread 0x7081 thru 0x10085 (0x9005 bytes)
7: 82 zero from 0x15ed1 to 0x1bc36, (0x5d65 bytes)
7: 83 zero from 0x248d7 to 0x26bae, (0x22d7 bytes)
7: 84 fsync
9: Dumped fsync buffer to testfile9.mark6
9: 83 fsync
8: 99 mapread 0x5aa4 thru 0x1593c (0xfe99 bytes)
8: 100 collapse from 0xd000 to 0x1a000, (0xd000 bytes)
8: All 100 operations completed A-OK!
1: 99 read 0x109c6 thru 0x128ba (0x1ef5 bytes)
1: 100 zero from 0xc2af to 0x1a1c7, (0xdf18 bytes)
6: 56 zero from 0x2150 to 0x666a, (0x451a bytes)
6: 57 punch from 0x4b61 to 0xe9ae, (0x9e4d bytes)
9: Dumped fsync buffer to testfile9.mark7
9: 84 mapread 0x350cc thru 0x37ed9 (0x2e0e bytes)
9: 85 write 0xbe1 thru 0xebe1 (0xe001 bytes)
9: 86 mapwrite 0x37e71 thru 0x39432 (0x15c2 bytes)
1: All 100 operations completed A-OK!
6: 58 fsync
5: Dumped fsync buffer to testfile5.mark12
5: 89 fsync
80 trunc from 0x33a4b to 0x269de
81 fsync
3: Dumped fsync buffer to testfile3.mark5
3: 77 insert from 0x0 to 0x6000, (0x6000 bytes)
5: Dumped fsync buffer to testfile5.mark13
5: 90 falloc from 0x16182 to 0x22424 (0xc2a2 bytes)
5: 91 mapread 0x2afc thru 0x42d6 (0x17db bytes)
5: 92 falloc from 0x36da3 to 0x40000 (0x925d bytes)
5: 93 trunc from 0x40000 to 0x2d204
5: 94 mapread 0xb2d3 thru 0x15ecc (0xabfa bytes)
5: 95 fsync
2: Dumped fsync buffer to testfile2.mark10
2: 98 read 0x347f2 thru 0x36671 (0x1e80 bytes)
3: 78 falloc from 0xaa1 to 0xe76e (0xdccd bytes)
9: 87 write 0x26167 thru 0x2f34b (0x91e5 bytes)
9: 89 zero from 0x31d2c to 0x3fa69, (0xdd3d bytes)
9: 90 falloc from 0xbd9e to 0x11caa (0x5f0c bytes)
9: 91 mapread 0xf397 thru 0x1599a (0x6604 bytes)
9: 92 punch from 0x1cb5f to 0x29f43, (0xd3e4 bytes)
2: 99 write 0x27a90 thru 0x32a80 (0xaff1 bytes)
7: Dumped fsync buffer to testfile7.mark10
7: 85 zero from 0xb291 to 0xfcab, (0x4a1a bytes)
3: 79 fsync
2: 100 fsync
7: 86 insert from 0xc000 to 0xf000, (0x3000 bytes)
Dumped fsync buffer to testfile0.mark8
82 read 0x80ca thru 0x9597 (0x14ce bytes)
83 write 0x219c4 thru 0x2b16b (0x97a8 bytes)
84 mapwrite 0x15281 thru 0x19812 (0x4592 bytes)
5: Dumped fsync buffer to testfile5.mark14
5: 96 punch from 0x28880 to 0x2d204, (0x4984 bytes)
5: 97 insert from 0x2a000 to 0x33000, (0x9000 bytes)
5: 98 fsync
9: 93 mapread 0x339ff thru 0x37845 (0x3e47 bytes)
9: 94 read 0x2ab2 thru 0x53b2 (0x2901 bytes)
9: 95 write 0x29267 thru 0x36c70 (0xda0a bytes)
9: 96 mapread 0x282f7 thru 0x3593c (0xd646 bytes)
9: 97 mapwrite 0x33ea2 thru 0x380c4 (0x4223 bytes)
7: 87 collapse from 0x16000 to 0x1a000, (0x4000 bytes)
7: 88 trunc from 0x25bae to 0x22aba
7: 89 fsync
6: Dumped fsync buffer to testfile6.mark8
6: 59 collapse from 0x2d000 to 0x2f000, (0x2000 bytes)
3: Dumped fsync buffer to testfile3.mark6
3: 80 punch from 0x2491 to 0xe76e, (0xc2dd bytes)
3: 81 collapse from 0x6000 to 0xd000, (0x7000 bytes)
3: 82 read 0x3c04 thru 0x776d (0x3b6a bytes)
3: 83 mapwrite 0x1614d thru 0x1b90e (0x57c2 bytes)
85 read 0x3213 thru 0x10fbe (0xddac bytes)
86 mapread 0x1578e thru 0x1daa2 (0x8315 bytes)
87 collapse from 0x27000 to 0x2a000, (0x3000 bytes)
6: 60 collapse from 0x1d000 to 0x21000, (0x4000 bytes)
2: Dumped fsync buffer to testfile2.mark11
2: All 100 operations completed A-OK!
6: 61 fsync
7: Dumped fsync buffer to testfile7.mark11
7: 90 collapse from 0x20000 to 0x22000, (0x2000 bytes)
7: 91 read 0xb448 thru 0xeb71 (0x372a bytes)
7: 92 collapse from 0x1e000 to 0x20000, (0x2000 bytes)
7: 93 insert from 0x6000 to 0xa000, (0x4000 bytes)
9: 98 write 0x1e77f thru 0x27583 (0x8e05 bytes)
9: 99 zero from 0x3bc37 to 0x3d688, (0x1a51 bytes)
9: 100 fsync
88 fsync
5: Dumped fsync buffer to testfile5.mark15
5: 99 insert from 0x2d000 to 0x35000, (0x8000 bytes)
5: 100 mapread 0xf941 thru 0x1c7f8 (0xceb8 bytes)
5: All 100 operations completed A-OK!
7: 94 read 0x189fa thru 0x197df (0xde6 bytes)
3: 84 collapse from 0x1a000 to 0x1b000, (0x1000 bytes)
7: 95 insert from 0x1f000 to 0x20000, (0x1000 bytes)
7: 96 fsync
3: 85 write 0x117d8 thru 0x1d4f3 (0xbd1c bytes)
3: 86 mapwrite 0x2166b thru 0x2c444 (0xadda bytes)
6: Dumped fsync buffer to testfile6.mark9
6: 62 collapse from 0x35000 to 0x38000, (0x3000 bytes)
Dumped fsync buffer to testfile0.mark9
89 write 0x2bbbf thru 0x2cbea (0x102c bytes)
90 trunc from 0x2cbeb to 0x13e6c
91 zero from 0x116bd to 0x11745, (0x88 bytes)
6: 63 zero from 0x29bf6 to 0x3479f, (0xaba9 bytes)
6: 64 mapwrite 0x7579 thru 0xe810 (0x7298 bytes)
92 trunc from 0x13e6c to 0x3b34c
93 read 0x2ce5d thru 0x32da1 (0x5f45 bytes)
94 punch from 0x1c9b9 to 0x2a951, (0xdf98 bytes)
95 mapread 0x2d8f thru 0x12889 (0xfafb bytes)
96 mapwrite 0x1b17b thru 0x238ac (0x8732 bytes)
7: Dumped fsync buffer to testfile7.mark12
7: 97 read 0xbab thru 0x10846 (0xfc9c bytes)
7: 98 mapwrite 0x2f1ad thru 0x39fc1 (0xae15 bytes)
9: Dumped fsync buffer to testfile9.mark8
9: All 100 operations completed A-OK!
3: 87 read 0x24634 thru 0x2c444 (0x7e11 bytes)
3: 88 trunc from 0x2c445 to 0x2d0ac
3: 89 collapse from 0x1c000 to 0x25000, (0x9000 bytes)
3: 90 mapwrite 0xd0f8 thru 0x17eef (0xadf8 bytes)
7: 99 fsync
6: 65 mapread 0x2677d thru 0x2c0e5 (0x5969 bytes)
97 collapse from 0x11000 to 0x12000, (0x1000 bytes)
6: 66 mapread 0xde3e thru 0x1bed0 (0xe093 bytes)
6: 67 zero from 0x2d0d9 to 0x2e815, (0x173c bytes)
6: 68 write 0x1b368 thru 0x28e0e (0xdaa7 bytes)
6: 69 mapread 0x230bc thru 0x2339d (0x2e2 bytes)
6: 70 write 0x2969e thru 0x2b554 (0x1eb7 bytes)
6: 71 collapse from 0x9000 to 0xb000, (0x2000 bytes)
7: Dumped fsync buffer to testfile7.mark13
7: 100 punch from 0xa496 to 0x11c92, (0x77fc bytes)
7: All 100 operations completed A-OK!
3: 91 zero from 0x2116b to 0x23ebb, (0x2d50 bytes)
6: 72 insert from 0x32000 to 0x3e000, (0xc000 bytes)
6: 73 trunc from 0x3fb7a to 0x36fc
6: 74 falloc from 0x275a9 to 0x3314d (0xbba4 bytes)
6: 75 mapwrite 0xda1a thru 0x12726 (0x4d0d bytes)
98 mapread 0xa662 thru 0x11553 (0x6ef2 bytes)
3: 92 mapread 0x16f37 thru 0x1ae3f (0x3f09 bytes)
3: 93 mapread 0xf879 thru 0x12d75 (0x34fd bytes)
3: 94 mapread 0x1b4d6 thru 0x240ab (0x8bd6 bytes)
99 insert from 0xb000 to 0x10000, (0x5000 bytes)
100 mapwrite 0x15640 thru 0x1a51b (0x4edc bytes)
6: 76 collapse from 0x2000 to 0x5000, (0x3000 bytes)
3: 95 write 0x7865 thru 0xcdde (0x557a bytes)
3: 96 punch from 0x12a58 to 0x157e6, (0x2d8e bytes)
6: 77 read 0x234f thru 0x9451 (0x7103 bytes)
6: 78 insert from 0xc000 to 0xf000, (0x3000 bytes)
3: 97 falloc from 0x8428 to 0xc0b6 (0x3c8e bytes)
3: 98 write 0x56b5 thru 0x116bd (0xc009 bytes)
3: 99 trunc from 0x240ac to 0x2e8de
3: 100 fsync
6: 79 trunc from 0x12727 to 0x240d7
6: 80 punch from 0x13292 to 0x1ce5b, (0x9bc9 bytes)
6: 81 write 0x3bafe thru 0x3ffff (0x4502 bytes)
6: 83 mapread 0x230c1 thru 0x3126b (0xe1ab bytes)
6: 84 zero from 0x643b to 0x11f7d, (0xbb42 bytes)
6: 86 punch from 0xa16 to 0xcde6, (0xc3d0 bytes)
All 100 operations completed A-OK!
6: 87 trunc from 0x40000 to 0x303c2
6: 88 fsync
3: Dumped fsync buffer to testfile3.mark7
3: All 100 operations completed A-OK!
6: Dumped fsync buffer to testfile6.mark10
6: 89 mapread 0x12d25 thru 0x19ab1 (0x6d8d bytes)
6: 90 zero from 0xf887 to 0x10a9d, (0x1216 bytes)
6: 91 mapread 0x1fbc3 thru 0x27a74 (0x7eb2 bytes)
6: 92 fsync
6: Dumped fsync buffer to testfile6.mark11
6: 93 falloc from 0x98e2 to 0x14948 (0xb066 bytes)
6: 94 punch from 0x8c3e to 0xaccc, (0x208e bytes)
6: 95 falloc from 0x2beab to 0x32d6d (0x6ec2 bytes)
6: 96 trunc from 0x32d6d to 0x2c6bd
6: 97 read 0x3a02 thru 0x11f1d (0xe51c bytes)
6: 98 trunc from 0x2c6bd to 0x14267
6: 99 insert from 0xa000 to 0xb000, (0x1000 bytes)
6: 100 zero from 0x9391 to 0x131f6, (0x9e65 bytes)
6: All 100 operations completed A-OK!
checking pre umount
checking testfile0.mark0
checking testfile0.mark1
checking testfile0.mark2
checking testfile0.mark3
checking testfile0.mark4
checking testfile0.mark5
checking testfile0.mark6
checking testfile0.mark7
checking testfile0.mark8
checking testfile0.mark9
checking testfile1.mark0
checking testfile1.mark1
checking testfile1.mark2
checking testfile1.mark3
checking testfile1.mark4
checking testfile2.mark0
checking testfile2.mark1
checking testfile2.mark2
checking testfile2.mark3
checking testfile2.mark4
checking testfile2.mark5
checking testfile2.mark6
checking testfile2.mark7
checking testfile2.mark8
checking testfile2.mark9
checking testfile2.mark10
checking testfile2.mark11
checking testfile3.mark0
checking testfile3.mark1
checking testfile3.mark2
checking testfile3.mark3
checking testfile3.mark4
checking testfile3.mark5
checking testfile3.mark6
checking testfile3.mark7
checking testfile4.mark0
checking testfile4.mark1
checking testfile4.mark2
checking testfile4.mark3
checking testfile4.mark4
checking testfile5.mark0
_check_xfs_filesystem: filesystem on /dev/mapper/storage-scratch is inconsistent (r)
*** xfs_repair -n output ***
Phase 1 - find and verify superblock...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
- found root inode chunk
Phase 3 - for each AG...
- scan (but don't clear) agi unlinked lists...
- process known inodes and perform inode discovery...
- agno = 0
fatal error -- illegal state 13 in block map 376
*** end xfs_repair output
*** mount output ***
sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
udev on /dev type devtmpfs (rw,nosuid,relatime,size=8119060k,nr_inodes=2029765,mode=755)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,noexec,relatime,size=1629116k,mode=755)
/dev/sda6 on / type ext4 (rw,relatime,errors=remount-ro,data=ordered)
securityfs on /sys/kernel/security type securityfs (rw,nosuid,nodev,noexec,relatime)
tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev)
tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k)
tmpfs on /sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,mode=755)
cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd)
pstore on /sys/fs/pstore type pstore (rw,nosuid,nodev,noexec,relatime)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /sys/fs/cgroup/hugetlb type cgroup (rw,nosuid,nodev,noexec,relatime,hugetlb)
cgroup on /sys/fs/cgroup/perf_event type cgroup (rw,nosuid,nodev,noexec,relatime,perf_event)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /sys/fs/cgroup/net_cls,net_prio type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls,net_prio)
cgroup on /sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct)
cgroup on /sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory)
hugetlbfs on /dev/hugepages type hugetlbfs (rw,relatime)
mqueue on /dev/mqueue type mqueue (rw,relatime)
debugfs on /sys/kernel/debug type debugfs (rw,relatime)
fusectl on /sys/fs/fuse/connections type fusectl (rw,relatime)
tracefs on /sys/kernel/debug/tracing type tracefs (rw,relatime)
/dev/sda1 on /old type ext4 (rw,relatime,errors=remount-ro,data=ordered)
tmpfs on /run/user/108 type tmpfs (rw,nosuid,nodev,relatime,size=1629116k,mode=700,uid=108,gid=114)
gvfsd-fuse on /run/user/108/gvfs type fuse.gvfsd-fuse (rw,nosuid,nodev,relatime,user_id=108,group_id=114)
tmpfs on /run/user/1001 type tmpfs (rw,nosuid,nodev,relatime,size=1629116k,mode=700,uid=1001,gid=1001)
/dev/mapper/storage-test on /mnt/test type xfs (rw,relatime,attr2,inode64,noquota)
*** end mount output
_check_xfs_filesystem: filesystem on /dev/mapper/storage-scratch is inconsistent (r)
*** xfs_repair -n output ***
Phase 1 - find and verify superblock...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
- found root inode chunk
Phase 3 - for each AG...
- scan (but don't clear) agi unlinked lists...
- process known inodes and perform inode discovery...
- agno = 0
fatal error -- illegal state 13 in block map 376
*** end xfs_repair output
*** mount output ***
sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
udev on /dev type devtmpfs (rw,nosuid,relatime,size=8119060k,nr_inodes=2029765,mode=755)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,noexec,relatime,size=1629116k,mode=755)
/dev/sda6 on / type ext4 (rw,relatime,errors=remount-ro,data=ordered)
securityfs on /sys/kernel/security type securityfs (rw,nosuid,nodev,noexec,relatime)
tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev)
tmpfs on /run/lock type tmpfs (rw,nosuid,nodev,noexec,relatime,size=5120k)
tmpfs on /sys/fs/cgroup type tmpfs (ro,nosuid,nodev,noexec,mode=755)
cgroup on /sys/fs/cgroup/systemd type cgroup (rw,nosuid,nodev,noexec,relatime,xattr,release_agent=/lib/systemd/systemd-cgroups-agent,name=systemd)
pstore on /sys/fs/pstore type pstore (rw,nosuid,nodev,noexec,relatime)
cgroup on /sys/fs/cgroup/devices type cgroup (rw,nosuid,nodev,noexec,relatime,devices)
cgroup on /sys/fs/cgroup/blkio type cgroup (rw,nosuid,nodev,noexec,relatime,blkio)
cgroup on /sys/fs/cgroup/freezer type cgroup (rw,nosuid,nodev,noexec,relatime,freezer)
cgroup on /sys/fs/cgroup/hugetlb type cgroup (rw,nosuid,nodev,noexec,relatime,hugetlb)
cgroup on /sys/fs/cgroup/perf_event type cgroup (rw,nosuid,nodev,noexec,relatime,perf_event)
cgroup on /sys/fs/cgroup/cpuset type cgroup (rw,nosuid,nodev,noexec,relatime,cpuset)
cgroup on /sys/fs/cgroup/net_cls,net_prio type cgroup (rw,nosuid,nodev,noexec,relatime,net_cls,net_prio)
cgroup on /sys/fs/cgroup/cpu,cpuacct type cgroup (rw,nosuid,nodev,noexec,relatime,cpu,cpuacct)
cgroup on /sys/fs/cgroup/memory type cgroup (rw,nosuid,nodev,noexec,relatime,memory)
hugetlbfs on /dev/hugepages type hugetlbfs (rw,relatime)
mqueue on /dev/mqueue type mqueue (rw,relatime)
debugfs on /sys/kernel/debug type debugfs (rw,relatime)
fusectl on /sys/fs/fuse/connections type fusectl (rw,relatime)
tracefs on /sys/kernel/debug/tracing type tracefs (rw,relatime)
/dev/sda1 on /old type ext4 (rw,relatime,errors=remount-ro,data=ordered)
tmpfs on /run/user/108 type tmpfs (rw,nosuid,nodev,relatime,size=1629116k,mode=700,uid=108,gid=114)
gvfsd-fuse on /run/user/108/gvfs type fuse.gvfsd-fuse (rw,nosuid,nodev,relatime,user_id=108,group_id=114)
tmpfs on /run/user/1001 type tmpfs (rw,nosuid,nodev,relatime,size=1629116k,mode=700,uid=1001,gid=1001)
/dev/mapper/storage-test on /mnt/test type xfs (rw,relatime,attr2,inode64,noquota)
*** end mount output
[-- Attachment #3: log.xfs.testfile5.mark0.bz2 --]
[-- Type: application/x-bzip2, Size: 156761 bytes --]
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs clones crash issue - illegal state 13 in block map
2017-09-07 12:58 xfs clones crash issue - illegal state 13 in block map Amir Goldstein
@ 2017-09-07 16:13 ` Darrick J. Wong
2017-09-08 8:34 ` Amir Goldstein
0 siblings, 1 reply; 8+ messages in thread
From: Darrick J. Wong @ 2017-09-07 16:13 UTC (permalink / raw)
To: Amir Goldstein; +Cc: Christoph Hellwig, linux-xfs
On Thu, Sep 07, 2017 at 03:58:56PM +0300, Amir Goldstein wrote:
> Hi guys,
>
> I am getting these errors often when running the crash tests
> with cloned files (generic/502 in my xfstests patches).
>
> Hitting these errors requires first fixing 2 other issues
> that shadow over this issue:
> "xfs: fix incorrect log_flushed on fsync" (in master)
> "xfs: fix leftover CoW extent after truncate"
> available on my tree based on Darrick's simple fix:
> https://github.com/amir73il/linux/commits/xfs-fsync
>
> I get the errors more often (1 out of 5) on a 100G fs on spinning disk.
> On a 10G fs on SSD they are less frequent.
> The log in this email was captured on patched stable 4.9.47 kernel,
> but I am getting the same errors on patched upstream kernel.
>
> I wasn't able to create a deterministic reproducer, so attaching
> the full log from a failed test along with an IO log that can be
> replayed on your disk to examine the outcome.
>
> Following is the output of fsx process #5, which is the process
> that wrote the problematic testfile5.mark0 to the log.
> This process performs only read,zero,fsync before creating
> the log mark.
> The file testfile5 was cloned from an origin 256K file before
> running fsx.
> Later, I used the random seed 35484 in this log for all
> processes and it seemed to increase the probability for failure.
>
> # /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P
> /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5
> /mnt/scratch/testfile5
> Seed set to 35484
> file_size=262144
> 5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
> 5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
> 5: 3 fsync
> 5: Dumped fsync buffer to testfile5.mark0
>
> In order to get to the crash state you need to get my
> xfstests replay-log patches and replay the attached log
> on a >= 100G scratch device:
>
> # ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
> $SCRATCH_DEV --end-mark testfile5.mark0
> # mount $SCRATCH_DEV $SCRATCH_MNT
> # umount $SCRATCH_MNT
> # xfs_repair -n $SCRATCH_DEV
> Phase 1 - find and verify superblock...
> Phase 2 - using internal log
> - zero log...
> - scan filesystem freespace and inode maps...
> - found root inode chunk
> Phase 3 - for each AG...
> - scan (but don't clear) agi unlinked lists...
> - process known inodes and perform inode discovery...
> - agno = 0
>
> fatal error -- illegal state 13 in block map 376
>
> Can anyone provide some insight?
Looks like I missed a couple of extent states in process_bmbt_reclist_int.
What happens if you add the following (only compile tested) patch to
xfsprogs?
(Normally I'd say send a metadump too for us mere mortals to work with,
though I'm about to plunge into weddingland so I likely won't be able to
do much until the 18th.)
((Eric: If this doesn't turn out to be a totally garbage patch, feel
free to add it to xfsprogs.))
--D
xfs_repair: handle missing extent states
Missed a couple of the new extent states in the bmbt processing, so add
them to avoid aborting xfs_repair.
Signed-off-by: Darrick J. Wong <darrick.wong@oracle.com>
---
repair/dinode.c | 7 +++++++
1 file changed, 7 insertions(+)
diff --git a/repair/dinode.c b/repair/dinode.c
index f817b5a..b35a523 100644
--- a/repair/dinode.c
+++ b/repair/dinode.c
@@ -796,6 +796,7 @@ _("%s fork in ino %" PRIu64 " claims free block %" PRIu64 "\n"),
case XR_E_FS_MAP:
case XR_E_INO:
case XR_E_INUSE_FS:
+ case XR_E_REFC:
do_warn(
_("%s fork in inode %" PRIu64 " claims metadata block %" PRIu64 "\n"),
forkname, ino, b);
@@ -812,6 +813,12 @@ _("%s fork in %s inode %" PRIu64 " claims used block %" PRIu64 "\n"),
forkname, ftype, ino, b);
goto done;
+ case XR_E_COW:
+ do_warn(
+_("%s fork in %s inode %" PRIu64 " claims CoW block %" PRIu64 "\n"),
+ forkname, ftype, ino, b);
+ goto done;
+
default:
do_error(
_("illegal state %d in block map %" PRIu64 "\n"),
^ permalink raw reply related [flat|nested] 8+ messages in thread
* Re: xfs clones crash issue - illegal state 13 in block map
2017-09-07 16:13 ` Darrick J. Wong
@ 2017-09-08 8:34 ` Amir Goldstein
2017-09-19 5:38 ` Darrick J. Wong
0 siblings, 1 reply; 8+ messages in thread
From: Amir Goldstein @ 2017-09-08 8:34 UTC (permalink / raw)
To: Darrick J. Wong; +Cc: Christoph Hellwig, linux-xfs
[-- Attachment #1: Type: text/plain, Size: 4627 bytes --]
On Thu, Sep 7, 2017 at 7:13 PM, Darrick J. Wong <darrick.wong@oracle.com> wrote:
> On Thu, Sep 07, 2017 at 03:58:56PM +0300, Amir Goldstein wrote:
>> Hi guys,
>>
>> I am getting these errors often when running the crash tests
>> with cloned files (generic/502 in my xfstests patches).
>>
>> Hitting these errors requires first fixing 2 other issues
>> that shadow over this issue:
>> "xfs: fix incorrect log_flushed on fsync" (in master)
>> "xfs: fix leftover CoW extent after truncate"
>> available on my tree based on Darrick's simple fix:
>> https://github.com/amir73il/linux/commits/xfs-fsync
>>
>> I get the errors more often (1 out of 5) on a 100G fs on spinning disk.
>> On a 10G fs on SSD they are less frequent.
>> The log in this email was captured on patched stable 4.9.47 kernel,
>> but I am getting the same errors on patched upstream kernel.
>>
>> I wasn't able to create a deterministic reproducer, so attaching
>> the full log from a failed test along with an IO log that can be
>> replayed on your disk to examine the outcome.
>>
>> Following is the output of fsx process #5, which is the process
>> that wrote the problematic testfile5.mark0 to the log.
>> This process performs only read,zero,fsync before creating
>> the log mark.
>> The file testfile5 was cloned from an origin 256K file before
>> running fsx.
>> Later, I used the random seed 35484 in this log for all
>> processes and it seemed to increase the probability for failure.
>>
>> # /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P
>> /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5
>> /mnt/scratch/testfile5
>> Seed set to 35484
>> file_size=262144
>> 5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
>> 5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
>> 5: 3 fsync
>> 5: Dumped fsync buffer to testfile5.mark0
>>
>> In order to get to the crash state you need to get my
>> xfstests replay-log patches and replay the attached log
>> on a >= 100G scratch device:
>>
>> # ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
>> $SCRATCH_DEV --end-mark testfile5.mark0
>> # mount $SCRATCH_DEV $SCRATCH_MNT
>> # umount $SCRATCH_MNT
>> # xfs_repair -n $SCRATCH_DEV
>> Phase 1 - find and verify superblock...
>> Phase 2 - using internal log
>> - zero log...
>> - scan filesystem freespace and inode maps...
>> - found root inode chunk
>> Phase 3 - for each AG...
>> - scan (but don't clear) agi unlinked lists...
>> - process known inodes and perform inode discovery...
>> - agno = 0
>>
>> fatal error -- illegal state 13 in block map 376
>>
>> Can anyone provide some insight?
>
> Looks like I missed a couple of extent states in process_bmbt_reclist_int.
>
> What happens if you add the following (only compile tested) patch to
> xfsprogs?
This is what happens:
Phase 1 - find and verify superblock...
Phase 2 - using internal log
- zero log...
- scan filesystem freespace and inode maps...
- found root inode chunk
Phase 3 - for each AG...
- scan (but don't clear) agi unlinked lists...
- process known inodes and perform inode discovery...
- agno = 0
data fork in regular inode 134 claims CoW block 376
correcting nextents for inode 134
bad data fork in inode 134
would have cleared inode 134
- agno = 1
- agno = 2
- agno = 3
- process newly discovered inodes...
Phase 4 - check for duplicate blocks...
- setting up duplicate extent list...
unknown block state, ag 0, block 376
unknown block state, ag 1, block 16
- check for inodes claiming duplicate blocks...
- agno = 0
- agno = 1
- agno = 2
entry "testfile2" in shortform directory 128 references free inode 134
- agno = 3
would have junked entry "testfile2" in directory inode 128
imap claims in-use inode 134 is free, would correct imap
Missing reverse-mapping record for (0/376) len 1 owner 134 off 19
No modify flag set, skipping phase 5
Phase 6 - check inode connectivity...
- traversing filesystem ...
- traversal finished ...
- moving disconnected inodes to lost+found ...
Phase 7 - verify link counts...
No modify flag set, skipping filesystem flush and exiting.
>
> (Normally I'd say send a metadump too for us mere mortals to work with,
> though I'm about to plunge into weddingland so I likely won't be able to
> do much until the 18th.)
>
Attached (used xfs_metadump -ao)
Soon we will all be gods with powers to replay history ;)
> ((Eric: If this doesn't turn out to be a totally garbage patch, feel
> free to add it to xfsprogs.))
>
> --D
>
[-- Attachment #2: metadump.xfs.testfile5.mark0.bz2 --]
[-- Type: application/x-bzip2, Size: 80357 bytes --]
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs clones crash issue - illegal state 13 in block map
2017-09-08 8:34 ` Amir Goldstein
@ 2017-09-19 5:38 ` Darrick J. Wong
2017-09-19 6:16 ` Amir Goldstein
2017-10-09 12:48 ` Hou Tao
0 siblings, 2 replies; 8+ messages in thread
From: Darrick J. Wong @ 2017-09-19 5:38 UTC (permalink / raw)
To: Amir Goldstein; +Cc: Christoph Hellwig, linux-xfs
On Fri, Sep 08, 2017 at 11:34:58AM +0300, Amir Goldstein wrote:
> On Thu, Sep 7, 2017 at 7:13 PM, Darrick J. Wong <darrick.wong@oracle.com> wrote:
> > On Thu, Sep 07, 2017 at 03:58:56PM +0300, Amir Goldstein wrote:
> >> Hi guys,
> >>
> >> I am getting these errors often when running the crash tests
> >> with cloned files (generic/502 in my xfstests patches).
> >>
> >> Hitting these errors requires first fixing 2 other issues
> >> that shadow over this issue:
> >> "xfs: fix incorrect log_flushed on fsync" (in master)
> >> "xfs: fix leftover CoW extent after truncate"
> >> available on my tree based on Darrick's simple fix:
> >> https://github.com/amir73il/linux/commits/xfs-fsync
> >>
> >> I get the errors more often (1 out of 5) on a 100G fs on spinning disk.
> >> On a 10G fs on SSD they are less frequent.
> >> The log in this email was captured on patched stable 4.9.47 kernel,
> >> but I am getting the same errors on patched upstream kernel.
> >>
> >> I wasn't able to create a deterministic reproducer, so attaching
> >> the full log from a failed test along with an IO log that can be
> >> replayed on your disk to examine the outcome.
> >>
> >> Following is the output of fsx process #5, which is the process
> >> that wrote the problematic testfile5.mark0 to the log.
> >> This process performs only read,zero,fsync before creating
> >> the log mark.
> >> The file testfile5 was cloned from an origin 256K file before
> >> running fsx.
> >> Later, I used the random seed 35484 in this log for all
> >> processes and it seemed to increase the probability for failure.
> >>
> >> # /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P
> >> /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5
> >> /mnt/scratch/testfile5
> >> Seed set to 35484
> >> file_size=262144
> >> 5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
> >> 5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
> >> 5: 3 fsync
> >> 5: Dumped fsync buffer to testfile5.mark0
> >>
> >> In order to get to the crash state you need to get my
> >> xfstests replay-log patches and replay the attached log
> >> on a >= 100G scratch device:
> >>
> >> # ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
> >> $SCRATCH_DEV --end-mark testfile5.mark0
> >> # mount $SCRATCH_DEV $SCRATCH_MNT
> >> # umount $SCRATCH_MNT
> >> # xfs_repair -n $SCRATCH_DEV
> >> Phase 1 - find and verify superblock...
> >> Phase 2 - using internal log
> >> - zero log...
> >> - scan filesystem freespace and inode maps...
> >> - found root inode chunk
> >> Phase 3 - for each AG...
> >> - scan (but don't clear) agi unlinked lists...
> >> - process known inodes and perform inode discovery...
> >> - agno = 0
> >>
> >> fatal error -- illegal state 13 in block map 376
> >>
> >> Can anyone provide some insight?
> >
> > Looks like I missed a couple of extent states in process_bmbt_reclist_int.
> >
> > What happens if you add the following (only compile tested) patch to
> > xfsprogs?
>
> This is what happens:
>
> Phase 1 - find and verify superblock...
> Phase 2 - using internal log
> - zero log...
> - scan filesystem freespace and inode maps...
> - found root inode chunk
> Phase 3 - for each AG...
> - scan (but don't clear) agi unlinked lists...
> - process known inodes and perform inode discovery...
> - agno = 0
> data fork in regular inode 134 claims CoW block 376
> correcting nextents for inode 134
> bad data fork in inode 134
> would have cleared inode 134
> - agno = 1
> - agno = 2
> - agno = 3
> - process newly discovered inodes...
> Phase 4 - check for duplicate blocks...
> - setting up duplicate extent list...
> unknown block state, ag 0, block 376
> unknown block state, ag 1, block 16
> - check for inodes claiming duplicate blocks...
> - agno = 0
> - agno = 1
> - agno = 2
> entry "testfile2" in shortform directory 128 references free inode 134
> - agno = 3
> would have junked entry "testfile2" in directory inode 128
> imap claims in-use inode 134 is free, would correct imap
> Missing reverse-mapping record for (0/376) len 1 owner 134 off 19
> No modify flag set, skipping phase 5
> Phase 6 - check inode connectivity...
> - traversing filesystem ...
> - traversal finished ...
> - moving disconnected inodes to lost+found ...
> Phase 7 - verify link counts...
> No modify flag set, skipping filesystem flush and exiting.
Hmm.
# xfs_db bugs.img
xfs_db> inode 134
xfs_db> bmap
data offset 0 startblock 24 (0/24) count 19 flag 0
data offset 19 startblock 376 (0/376) count 1 flag 0
data offset 25 startblock 8388624 (1/16) count 4 flag 1
data offset 29 startblock 53 (0/53) count 35 flag 0
Ok, so inode 134 thinks it owns block 376.
xfs_db> agf 0
xfs_db> addr refcntroot
xfs_db> p
...
recs[1-22] = [startblock,blockcount,refcount,cowflag]
1:[24,1,11,0]
...
22:[87,1,6,0]
xfs_db>
Ok, so the refcountbt doesn't know about block 376, so it's neither
shared nor a cow staging extent.
xfs_db> agf 0
xfs_db> addr rmaproot
xfs_db> p
...
recs[1-38] = [startblock,blockcount,owner,offset,extentflag,attrfork,bmbtblock]
1:[0,1,-3,0,0,0,0]
...
38:[376,1,-9,0,0,0,0]
xfs_db>
So it seems that the rmapbt is behind the times, since record 38 should
be [376,1,134,19,0,0,0]. Either that's because there's something wrong
with the regular deferred ops mechanism, or log recovery of deferred ops.
Let's have a look at the log...
# xfs_logprint bugs.img | grep x178 -B3
Oper (426): tid: 5c75a3f len: 48 clientid: TRANS flags: none
CUI: #regs: 1 num_extents: 2 id: 0xffff8f0e842f74b8
(s: 0x2b, l: 1, f: 0x2)
(s: 0x178, l: 1, f: 0x4)
...ok, so we XFS_REFCOUNT_FREE_COW block 376, which removes it from from
the refcountbt...
----------------------------------------------------------------------------
Oper (427): tid: 5c75a3f len: 48 clientid: TRANS flags: none
BUI: #regs: 1 num_extents: 1 id: 0xffff8f0e81f39000
(s: 0x178, l: 1, own: 134, off: 19, f: 0x1)
...now we map block 376 into the data fork of inode 134 at offset 19...
--
----------------------------------------------------------------------------
Oper (447): tid: 5c75a3f len: 48 clientid: TRANS flags: none
RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254000
(s: 0x178, l: 1, own: -9, off: 0, f: 0x8)
...now we XFS_RMAP_EXTENT_FREE the CoW extent @ block 376 from the rmap,
which ought to remove the record...
--
----------------------------------------------------------------------------
Oper (453): tid: e0ecea6a len: 48 clientid: TRANS flags: none
RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
(s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
...and XFS_RMAP_EXTENT_MAP_SHARED a new rmapping for block 376, which
should add the [376,1,134,19,0,0,0] that we'd expect to be there...
--
----------------------------------------------------------------------------
Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
(s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
...strange, another rmap add? Did the RUIs fail to complete?
# xfs_logprint bugs.img | egrep '(0xffff8f0e48254530|0xffff925955341f20)'
RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
RUD: #regs: 1 id: 0xffff8f0e48254530
RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
RUD: #regs: 1 id: 0xffff925955341f20
...the first RUI is logged as operation 453 in tid e0ecea6a, and it has
an RUD at 460. However, I don't see a COMMIT, so I gather that log
recovery tried to replay the RUI as operation 13 in tid 17c5790c.
----------------------------------------------------------------------------
Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
(s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
----------------------------------------------------------------------------
Oper (14): tid: 17c5790c len: 16 clientid: TRANS flags: none
RUD: #regs: 1 id: 0xffff925955341f20
----------------------------------------------------------------------------
Oper (15): tid: 17c5790c len: 16 clientid: TRANS flags: none
RUD: #regs: 1 id: 0xffff8f0e48254000
----------------------------------------------------------------------------
Oper (16): tid: 17c5790c len: 24 clientid: TRANS flags: none
BUF: #regs: 3 start blkno: 40 (0x28) len: 8 bmap size: 1 flags: 0x2000
Oper (17): tid: 17c5790c len: 128 clientid: TRANS flags: none
BUF DATA
0 33424d52 31000000 ffffffff ffffffff 0 28000000 1000000 38000000
8 3674196c 564cfddf 7798e496 591b6410 0 42249385 0 1000000
10 ffffffff fdffffff 0 0 1000000 2000000 ffffffff fbffffff
18 0 0 3000000 2000000 ffffffff faffffff 0 0
Oper (18): tid: 17c5790c len: 128 clientid: TRANS flags: none
BUF DATA
0 0 0 4d010000 9000000 0 8a000000 0 2a000000
8 56010000 d000000 ffffffff f7ffffff 0 0 65010000 6b000000
10 ffffffff f7ffffff 0 0 78010000 1000000 0 86000000
18 0 13000000 0 0 0 0 0 0
----------------------------------------------------------------------------
Oper (19): tid: 17c5790c len: 0 clientid: TRANS flags: COMMIT
Ok, so those last two lines in operation 16 show that we've indeed added the
new record to the rmapbt... <shrug> <confused> <tired>??
Are we sure that the log recovery actions actually get checkpointed
correctly? And just to check my own sanity, we generate a snapshot and
then recover it and run xfs_repair, right?
--D
>
> >
> > (Normally I'd say send a metadump too for us mere mortals to work with,
> > though I'm about to plunge into weddingland so I likely won't be able to
> > do much until the 18th.)
> >
>
> Attached (used xfs_metadump -ao)
> Soon we will all be gods with powers to replay history ;)
>
> > ((Eric: If this doesn't turn out to be a totally garbage patch, feel
> > free to add it to xfsprogs.))
> >
> > --D
> >
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs clones crash issue - illegal state 13 in block map
2017-09-19 5:38 ` Darrick J. Wong
@ 2017-09-19 6:16 ` Amir Goldstein
2017-10-09 12:48 ` Hou Tao
1 sibling, 0 replies; 8+ messages in thread
From: Amir Goldstein @ 2017-09-19 6:16 UTC (permalink / raw)
To: Darrick J. Wong; +Cc: Christoph Hellwig, linux-xfs
On Tue, Sep 19, 2017 at 8:38 AM, Darrick J. Wong
<darrick.wong@oracle.com> wrote:
> On Fri, Sep 08, 2017 at 11:34:58AM +0300, Amir Goldstein wrote:
>> On Thu, Sep 7, 2017 at 7:13 PM, Darrick J. Wong <darrick.wong@oracle.com> wrote:
>> > On Thu, Sep 07, 2017 at 03:58:56PM +0300, Amir Goldstein wrote:
>> >> Hi guys,
>> >>
>> >> I am getting these errors often when running the crash tests
>> >> with cloned files (generic/502 in my xfstests patches).
>> >>
>> >> Hitting these errors requires first fixing 2 other issues
>> >> that shadow over this issue:
>> >> "xfs: fix incorrect log_flushed on fsync" (in master)
>> >> "xfs: fix leftover CoW extent after truncate"
>> >> available on my tree based on Darrick's simple fix:
>> >> https://github.com/amir73il/linux/commits/xfs-fsync
>> >>
>> >> I get the errors more often (1 out of 5) on a 100G fs on spinning disk.
>> >> On a 10G fs on SSD they are less frequent.
>> >> The log in this email was captured on patched stable 4.9.47 kernel,
>> >> but I am getting the same errors on patched upstream kernel.
>> >>
>> >> I wasn't able to create a deterministic reproducer, so attaching
>> >> the full log from a failed test along with an IO log that can be
>> >> replayed on your disk to examine the outcome.
>> >>
>> >> Following is the output of fsx process #5, which is the process
>> >> that wrote the problematic testfile5.mark0 to the log.
>> >> This process performs only read,zero,fsync before creating
>> >> the log mark.
>> >> The file testfile5 was cloned from an origin 256K file before
>> >> running fsx.
>> >> Later, I used the random seed 35484 in this log for all
>> >> processes and it seemed to increase the probability for failure.
>> >>
>> >> # /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P
>> >> /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5
>> >> /mnt/scratch/testfile5
>> >> Seed set to 35484
>> >> file_size=262144
>> >> 5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
>> >> 5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
>> >> 5: 3 fsync
>> >> 5: Dumped fsync buffer to testfile5.mark0
>> >>
>> >> In order to get to the crash state you need to get my
>> >> xfstests replay-log patches and replay the attached log
>> >> on a >= 100G scratch device:
>> >>
>> >> # ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
>> >> $SCRATCH_DEV --end-mark testfile5.mark0
>> >> # mount $SCRATCH_DEV $SCRATCH_MNT
>> >> # umount $SCRATCH_MNT
>> >> # xfs_repair -n $SCRATCH_DEV
>> >> Phase 1 - find and verify superblock...
>> >> Phase 2 - using internal log
>> >> - zero log...
>> >> - scan filesystem freespace and inode maps...
>> >> - found root inode chunk
>> >> Phase 3 - for each AG...
>> >> - scan (but don't clear) agi unlinked lists...
>> >> - process known inodes and perform inode discovery...
>> >> - agno = 0
>> >>
>> >> fatal error -- illegal state 13 in block map 376
>> >>
>> >> Can anyone provide some insight?
>> >
>> > Looks like I missed a couple of extent states in process_bmbt_reclist_int.
>> >
>> > What happens if you add the following (only compile tested) patch to
>> > xfsprogs?
>>
>> This is what happens:
>>
>> Phase 1 - find and verify superblock...
>> Phase 2 - using internal log
>> - zero log...
>> - scan filesystem freespace and inode maps...
>> - found root inode chunk
>> Phase 3 - for each AG...
>> - scan (but don't clear) agi unlinked lists...
>> - process known inodes and perform inode discovery...
>> - agno = 0
>> data fork in regular inode 134 claims CoW block 376
>> correcting nextents for inode 134
>> bad data fork in inode 134
>> would have cleared inode 134
>> - agno = 1
>> - agno = 2
>> - agno = 3
>> - process newly discovered inodes...
>> Phase 4 - check for duplicate blocks...
>> - setting up duplicate extent list...
>> unknown block state, ag 0, block 376
>> unknown block state, ag 1, block 16
>> - check for inodes claiming duplicate blocks...
>> - agno = 0
>> - agno = 1
>> - agno = 2
>> entry "testfile2" in shortform directory 128 references free inode 134
>> - agno = 3
>> would have junked entry "testfile2" in directory inode 128
>> imap claims in-use inode 134 is free, would correct imap
>> Missing reverse-mapping record for (0/376) len 1 owner 134 off 19
>> No modify flag set, skipping phase 5
>> Phase 6 - check inode connectivity...
>> - traversing filesystem ...
>> - traversal finished ...
>> - moving disconnected inodes to lost+found ...
>> Phase 7 - verify link counts...
>> No modify flag set, skipping filesystem flush and exiting.
>
> Hmm.
>
> # xfs_db bugs.img
> xfs_db> inode 134
> xfs_db> bmap
> data offset 0 startblock 24 (0/24) count 19 flag 0
> data offset 19 startblock 376 (0/376) count 1 flag 0
> data offset 25 startblock 8388624 (1/16) count 4 flag 1
> data offset 29 startblock 53 (0/53) count 35 flag 0
>
> Ok, so inode 134 thinks it owns block 376.
>
> xfs_db> agf 0
> xfs_db> addr refcntroot
> xfs_db> p
> ...
> recs[1-22] = [startblock,blockcount,refcount,cowflag]
> 1:[24,1,11,0]
> ...
> 22:[87,1,6,0]
> xfs_db>
>
> Ok, so the refcountbt doesn't know about block 376, so it's neither
> shared nor a cow staging extent.
>
> xfs_db> agf 0
> xfs_db> addr rmaproot
> xfs_db> p
> ...
> recs[1-38] = [startblock,blockcount,owner,offset,extentflag,attrfork,bmbtblock]
> 1:[0,1,-3,0,0,0,0]
> ...
> 38:[376,1,-9,0,0,0,0]
> xfs_db>
>
> So it seems that the rmapbt is behind the times, since record 38 should
> be [376,1,134,19,0,0,0]. Either that's because there's something wrong
> with the regular deferred ops mechanism, or log recovery of deferred ops.
> Let's have a look at the log...
>
> # xfs_logprint bugs.img | grep x178 -B3
> Oper (426): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> CUI: #regs: 1 num_extents: 2 id: 0xffff8f0e842f74b8
> (s: 0x2b, l: 1, f: 0x2)
> (s: 0x178, l: 1, f: 0x4)
>
> ...ok, so we XFS_REFCOUNT_FREE_COW block 376, which removes it from from
> the refcountbt...
>
> ----------------------------------------------------------------------------
> Oper (427): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> BUI: #regs: 1 num_extents: 1 id: 0xffff8f0e81f39000
> (s: 0x178, l: 1, own: 134, off: 19, f: 0x1)
>
> ...now we map block 376 into the data fork of inode 134 at offset 19...
>
> --
> ----------------------------------------------------------------------------
> Oper (447): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254000
> (s: 0x178, l: 1, own: -9, off: 0, f: 0x8)
>
> ...now we XFS_RMAP_EXTENT_FREE the CoW extent @ block 376 from the rmap,
> which ought to remove the record...
>
> --
> ----------------------------------------------------------------------------
> Oper (453): tid: e0ecea6a len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
> (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
>
> ...and XFS_RMAP_EXTENT_MAP_SHARED a new rmapping for block 376, which
> should add the [376,1,134,19,0,0,0] that we'd expect to be there...
>
> --
> ----------------------------------------------------------------------------
> Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
>
> ...strange, another rmap add? Did the RUIs fail to complete?
>
> # xfs_logprint bugs.img | egrep '(0xffff8f0e48254530|0xffff925955341f20)'
> RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
> RUD: #regs: 1 id: 0xffff8f0e48254530
> RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> RUD: #regs: 1 id: 0xffff925955341f20
>
> ...the first RUI is logged as operation 453 in tid e0ecea6a, and it has
> an RUD at 460. However, I don't see a COMMIT, so I gather that log
> recovery tried to replay the RUI as operation 13 in tid 17c5790c.
>
> ----------------------------------------------------------------------------
> Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
> ----------------------------------------------------------------------------
> Oper (14): tid: 17c5790c len: 16 clientid: TRANS flags: none
> RUD: #regs: 1 id: 0xffff925955341f20
> ----------------------------------------------------------------------------
> Oper (15): tid: 17c5790c len: 16 clientid: TRANS flags: none
> RUD: #regs: 1 id: 0xffff8f0e48254000
> ----------------------------------------------------------------------------
> Oper (16): tid: 17c5790c len: 24 clientid: TRANS flags: none
> BUF: #regs: 3 start blkno: 40 (0x28) len: 8 bmap size: 1 flags: 0x2000
> Oper (17): tid: 17c5790c len: 128 clientid: TRANS flags: none
> BUF DATA
> 0 33424d52 31000000 ffffffff ffffffff 0 28000000 1000000 38000000
> 8 3674196c 564cfddf 7798e496 591b6410 0 42249385 0 1000000
> 10 ffffffff fdffffff 0 0 1000000 2000000 ffffffff fbffffff
> 18 0 0 3000000 2000000 ffffffff faffffff 0 0
>
> Oper (18): tid: 17c5790c len: 128 clientid: TRANS flags: none
> BUF DATA
> 0 0 0 4d010000 9000000 0 8a000000 0 2a000000
> 8 56010000 d000000 ffffffff f7ffffff 0 0 65010000 6b000000
> 10 ffffffff f7ffffff 0 0 78010000 1000000 0 86000000
> 18 0 13000000 0 0 0 0 0 0
>
> ----------------------------------------------------------------------------
> Oper (19): tid: 17c5790c len: 0 clientid: TRANS flags: COMMIT
>
> Ok, so those last two lines in operation 16 show that we've indeed added the
> new record to the rmapbt... <shrug> <confused> <tired>??
>
> Are we sure that the log recovery actions actually get checkpointed
> correctly?
I'm not sure of anything. dm-log-writes may have bugs, but so far all
suspicions rebounded back to file system bugs.
I'm pretty sure, though, that dm-log-writes does not discriminate
log recovery actions, it is simply not smart enough for that.
To better understand what happenened on block level, I added the
range filter options --start-sector --end-sector to replay-log tool.
If you narrowed down the problem to a physical block whose content
is in dispute (which was the case with data corruption bug), you can
use replay-log --vv on the said physical range to study the case.
replay-log is now in upstream xfstests and so is test generic/457
which reproduces this error.
> And just to check my own sanity, we generate a snapshot and
> then recover it and run xfs_repair, right?
>
Let me rephrase that for clarity of terms:
- We record all IO since before mkfs
- We write a snapshot mark in the recording at times (post fsync in this test)
Then
- We replay IO on device until a mark (i.e. restore from snapshot)
- We mount to recover xfs log
- We verify content of fsynced file
- We umount and check fs
I sent you the metadump from this point in time. I can send you
metadump from before mount, so you can examine that as well.
Or you can do on a >= 100G scratch device:
# ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
$SCRATCH_DEV --end-mark testfile5.mark0
Let me know if you need anything else.
Amir.
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs clones crash issue - illegal state 13 in block map
2017-09-19 5:38 ` Darrick J. Wong
2017-09-19 6:16 ` Amir Goldstein
@ 2017-10-09 12:48 ` Hou Tao
2017-10-10 19:18 ` Darrick J. Wong
1 sibling, 1 reply; 8+ messages in thread
From: Hou Tao @ 2017-10-09 12:48 UTC (permalink / raw)
To: Darrick J. Wong, Amir Goldstein; +Cc: Christoph Hellwig, linux-xfs
Hi,
On 2017/9/19 13:38, Darrick J. Wong wrote:
> On Fri, Sep 08, 2017 at 11:34:58AM +0300, Amir Goldstein wrote:
>> On Thu, Sep 7, 2017 at 7:13 PM, Darrick J. Wong <darrick.wong@oracle.com> wrote:
>>> On Thu, Sep 07, 2017 at 03:58:56PM +0300, Amir Goldstein wrote:
>>>> Hi guys,
>>>>
>>>> I am getting these errors often when running the crash tests
>>>> with cloned files (generic/502 in my xfstests patches).
>>>>
>>>> Hitting these errors requires first fixing 2 other issues
>>>> that shadow over this issue:
>>>> "xfs: fix incorrect log_flushed on fsync" (in master)
>>>> "xfs: fix leftover CoW extent after truncate"
>>>> available on my tree based on Darrick's simple fix:
>>>> https://github.com/amir73il/linux/commits/xfs-fsync
>>>>
>>>> I get the errors more often (1 out of 5) on a 100G fs on spinning disk.
>>>> On a 10G fs on SSD they are less frequent.
>>>> The log in this email was captured on patched stable 4.9.47 kernel,
>>>> but I am getting the same errors on patched upstream kernel.
>>>>
>>>> I wasn't able to create a deterministic reproducer, so attaching
>>>> the full log from a failed test along with an IO log that can be
>>>> replayed on your disk to examine the outcome.
>>>>
>>>> Following is the output of fsx process #5, which is the process
>>>> that wrote the problematic testfile5.mark0 to the log.
>>>> This process performs only read,zero,fsync before creating
>>>> the log mark.
>>>> The file testfile5 was cloned from an origin 256K file before
>>>> running fsx.
>>>> Later, I used the random seed 35484 in this log for all
>>>> processes and it seemed to increase the probability for failure.
>>>>
>>>> # /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P
>>>> /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5
>>>> /mnt/scratch/testfile5
>>>> Seed set to 35484
>>>> file_size=262144
>>>> 5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
>>>> 5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
>>>> 5: 3 fsync
>>>> 5: Dumped fsync buffer to testfile5.mark0
>>>>
>>>> In order to get to the crash state you need to get my
>>>> xfstests replay-log patches and replay the attached log
>>>> on a >= 100G scratch device:
>>>>
>>>> # ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
>>>> $SCRATCH_DEV --end-mark testfile5.mark0
>>>> # mount $SCRATCH_DEV $SCRATCH_MNT
>>>> # umount $SCRATCH_MNT
>>>> # xfs_repair -n $SCRATCH_DEV
>>>> Phase 1 - find and verify superblock...
>>>> Phase 2 - using internal log
>>>> - zero log...
>>>> - scan filesystem freespace and inode maps...
>>>> - found root inode chunk
>>>> Phase 3 - for each AG...
>>>> - scan (but don't clear) agi unlinked lists...
>>>> - process known inodes and perform inode discovery...
>>>> - agno = 0
>>>>
>>>> fatal error -- illegal state 13 in block map 376
>>>>
>>>> Can anyone provide some insight?
>>>
>>> Looks like I missed a couple of extent states in process_bmbt_reclist_int.
>>>
>>> What happens if you add the following (only compile tested) patch to
>>> xfsprogs?
>>
>> This is what happens:
>>
>> Phase 1 - find and verify superblock...
>> Phase 2 - using internal log
>> - zero log...
>> - scan filesystem freespace and inode maps...
>> - found root inode chunk
>> Phase 3 - for each AG...
>> - scan (but don't clear) agi unlinked lists...
>> - process known inodes and perform inode discovery...
>> - agno = 0
>> data fork in regular inode 134 claims CoW block 376
>> correcting nextents for inode 134
>> bad data fork in inode 134
>> would have cleared inode 134
>> - agno = 1
>> - agno = 2
>> - agno = 3
>> - process newly discovered inodes...
>> Phase 4 - check for duplicate blocks...
>> - setting up duplicate extent list...
>> unknown block state, ag 0, block 376
>> unknown block state, ag 1, block 16
>> - check for inodes claiming duplicate blocks...
>> - agno = 0
>> - agno = 1
>> - agno = 2
>> entry "testfile2" in shortform directory 128 references free inode 134
>> - agno = 3
>> would have junked entry "testfile2" in directory inode 128
>> imap claims in-use inode 134 is free, would correct imap
>> Missing reverse-mapping record for (0/376) len 1 owner 134 off 19
>> No modify flag set, skipping phase 5
>> Phase 6 - check inode connectivity...
>> - traversing filesystem ...
>> - traversal finished ...
>> - moving disconnected inodes to lost+found ...
>> Phase 7 - verify link counts...
>> No modify flag set, skipping filesystem flush and exiting.
>
> Hmm.
>
> # xfs_db bugs.img
> xfs_db> inode 134
> xfs_db> bmap
> data offset 0 startblock 24 (0/24) count 19 flag 0
> data offset 19 startblock 376 (0/376) count 1 flag 0
> data offset 25 startblock 8388624 (1/16) count 4 flag 1
> data offset 29 startblock 53 (0/53) count 35 flag 0
>
> Ok, so inode 134 thinks it owns block 376.
>
> xfs_db> agf 0
> xfs_db> addr refcntroot
> xfs_db> p
> ...
> recs[1-22] = [startblock,blockcount,refcount,cowflag]
> 1:[24,1,11,0]
> ...
> 22:[87,1,6,0]
> xfs_db>
>
> Ok, so the refcountbt doesn't know about block 376, so it's neither
> shared nor a cow staging extent.
>
> xfs_db> agf 0
> xfs_db> addr rmaproot
> xfs_db> p
> ...
> recs[1-38] = [startblock,blockcount,owner,offset,extentflag,attrfork,bmbtblock]
> 1:[0,1,-3,0,0,0,0]
> ...
> 38:[376,1,-9,0,0,0,0]
> xfs_db>
>
> So it seems that the rmapbt is behind the times, since record 38 should
> be [376,1,134,19,0,0,0]. Either that's because there's something wrong
> with the regular deferred ops mechanism, or log recovery of deferred ops.
I think the log recovery of deferred ops is incorrect, and we also need to
add more checks when manipulating the b-tree of rmap.
I had reproduced the problem on my KVM VM, and i will explain the incorrectness of
log recovery of deferred ops by using my own example. If addition information is
needed, please just ask.
The phenomena is the same: a block extent had been assigned to a file, but in the
rmap b-tree the block extent belongs to COW procedure.
We can get the following output from xfs_db after mounting and umounting the device:
./src/log-writes/replay-log --replay /dev/vdd --end-mark testfile7.mark0 --log /dev/vde
xfs_logprint -o /dev/vdd > pre_mount.log
mount /dev/vdd /tmp/vdd
umount /tmp/vdd
xfs_logprint -o /dev/vdd > post_mount.log
xfs_db /dev/vdd
xfs_db> inode 137
xfs_db> p u3.bmx[3]
u3.bmx[3] = [startoff,startblock,blockcount,extentflag]
3:[58,341,2,0]
xfs_db> agf 0
xfs_db> addr rmaproot
xfs_db> p recs[44]
recs[44] = [startblock,blockcount,owner,offset,extentflag,attrfork,bmbtblock]
44:[341,2,-9,0,0,0,0]
The last log record in pre_mount.log (generated before mount) has the following ops
which are related with inode 137:
# from pre_mount.log
# initiate by xfs_reflink_end_cow()
# decrease ref: [0x52, +2]
# free cow: [0x155, +2]
----------------------------------------------------------------------------
Oper (160): tid: c2350d60 len: 48 clientid: TRANS flags: none
CUI: #regs: 1 num_extents: 2 id: 0xffff88011b37c680
(s: 0x52, l: 2, f: 0x2)
(s: 0x155, l: 2, f: 0x4)
----------------------------------------------------------------------------
# map shared: [0x155, +2] to inode 137
----------------------------------------------------------------------------
Oper (161): tid: c2350d60 len: 48 clientid: TRANS flags: none
BUI: #regs: 1 num_extents: 1 id: 0xffff880117f0c300
(s: 0x155, l: 2, own: 137, off: 58, f: 0x1)
----------------------------------------------------------------------------
# for CUI Oper (160)
----------------------------------------------------------------------------
Oper (194): tid: c2350d60 len: 16 clientid: TRANS flags: none
CUD: #regs: 1 id: 0xffff88011b37c680
----------------------------------------------------------------------------
# free rmap: [0x155, +2]
----------------------------------------------------------------------------
Oper (197): tid: c2350d60 len: 48 clientid: TRANS flags: none
RUI: #regs: 1 num_extents: 1 id: 0xffff880124a3ea00
(s: 0x155, l: 2, own: -9, off: 0, f: 0x8)
----------------------------------------------------------------------------
Oper (198): tid: c2350d60 len: 0 clientid: TRANS flags: COMMIT
============================================================================
According to the implementation of xfs_defer_finish(), these ops should be completed
in the following sequence:
Have been done:
(1) CUI: Oper (160)
(2) BUI: Oper (161)
(3) CUD: Oper (194), for CUI Oper (160)
(4) RUI A: Oper (197), free rmap [0x155, 2, -9]
Should be done:
(5) BUD: for BUI Oper (161)
(6) RUI B: add rmap [0x155, 2, 137]
(7) RUD: for RUI A
(8) RUD: for RUI B
Actually be done by xlog_recover_process_intents()
(5) BUD: for BUI Oper (161)
(6) RUI B: add rmap [0x155, 2, 137]
(7) RUD: for RUI B
(8) RUD: for RUI A
So the rmap entry [0x155, 2, -9] for COW should be freed firstly,
then a new rmap entry [0x155, 2, 137] will be added. However, as we can see
from the log record in post_mount.log (generated after umount) and the trace
print, the new rmap entry [0x155, 2, 137] are added firstly, then the rmap
entry [0x155, 2, -9] are freed.
# from post_mount.log
----------------------------------------------------------------------------
Oper (2): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
BUD: #regs: 1 id: 0xffff880117f0c300
----------------------------------------------------------------------------
# add rmap [0x155, 2, 137]
----------------------------------------------------------------------------
Oper (6): tid: 3c5adcc1 len: 48 clientid: TRANS flags: none
RUI: #regs: 1 num_extents: 1 id: 0xffff880125bdc2a0
(s: 0x155, l: 2, own: 137, off: 58, f: 0x2)
----------------------------------------------------------------------------
Oper (7): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
RUD: #regs: 1 id: 0xffff880125bdc2a0
----------------------------------------------------------------------------
# remove rmap [0x155, 2, -9]
----------------------------------------------------------------------------
Oper (20): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
RUD: #regs: 1 id: 0xffff880124a3ea00
----------------------------------------------------------------------------
# from trace print
# add rmap [0x155, 2, 137], find [0x12d, 46, -9], and insert [0x155, 2, 137]
xfs_rmap_defer: dev 253:48 op 1 agno 0 agbno 341 owner 137 data offset 58 len 2 state 0
xfs_rmap_deferred: dev 253:48 op 1 agno 0 agbno 341 owner 137 data offset 58 len 2 state 0
xfs_rmap_map: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
xfs_rmap_find_left_neighbor_query: dev 253:48 agno 0 agbno 341 len 0 owner 137 offset 58 flags 0x0
xfs_rmap_find_left_neighbor_candidate: dev 253:48 agno 0 agbno 301 len 46 owner -9 offset 0 flags 0x0
xfs_rmap_insert: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
xfs_rmap_map_done: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
# del rmap [0x155, 2, -9], find [0x155, 2, 137], and remove [0x155, 2, 137]
xfs_rmap_deferred: dev 253:48 op 7 agno 0 agbno 341 owner -9 data offset 0 len 2 state 0
xfs_rmap_unmap: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
xfs_rmap_lookup_le_range_result: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
xfs_rmap_delete: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
xfs_rmap_unmap_done: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
# del rmap [0x12d, 40, -9]
xfs_rmap_unmap: dev 253:48 agno 0 agbno 301 len 40 owner -9 offset 0 flags 0x0
# del rmap [0x157, 4, -9]
xfs_rmap_unmap: dev 253:48 agno 0 agbno 343 len 4 owner -9 offset 0 flags 0x0
xfs_rmap_update: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
Regards,
Tao
> Let's have a look at the log...
>
> # xfs_logprint bugs.img | grep x178 -B3
> Oper (426): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> CUI: #regs: 1 num_extents: 2 id: 0xffff8f0e842f74b8
> (s: 0x2b, l: 1, f: 0x2)
> (s: 0x178, l: 1, f: 0x4)
>
> ...ok, so we XFS_REFCOUNT_FREE_COW block 376, which removes it from from
> the refcountbt...
>
> ----------------------------------------------------------------------------
> Oper (427): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> BUI: #regs: 1 num_extents: 1 id: 0xffff8f0e81f39000
> (s: 0x178, l: 1, own: 134, off: 19, f: 0x1)
>
> ...now we map block 376 into the data fork of inode 134 at offset 19...
>
> --
> ----------------------------------------------------------------------------
> Oper (447): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254000
> (s: 0x178, l: 1, own: -9, off: 0, f: 0x8)
>
> ...now we XFS_RMAP_EXTENT_FREE the CoW extent @ block 376 from the rmap,
> which ought to remove the record...
>
> --
> ----------------------------------------------------------------------------
> Oper (453): tid: e0ecea6a len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
> (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
>
> ...and XFS_RMAP_EXTENT_MAP_SHARED a new rmapping for block 376, which
> should add the [376,1,134,19,0,0,0] that we'd expect to be there...
>
> --
> ----------------------------------------------------------------------------
> Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
>
> ...strange, another rmap add? Did the RUIs fail to complete?
>
> # xfs_logprint bugs.img | egrep '(0xffff8f0e48254530|0xffff925955341f20)'
> RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
> RUD: #regs: 1 id: 0xffff8f0e48254530
> RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> RUD: #regs: 1 id: 0xffff925955341f20
>
> ...the first RUI is logged as operation 453 in tid e0ecea6a, and it has
> an RUD at 460. However, I don't see a COMMIT, so I gather that log
> recovery tried to replay the RUI as operation 13 in tid 17c5790c.
>
> ----------------------------------------------------------------------------
> Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
> ----------------------------------------------------------------------------
> Oper (14): tid: 17c5790c len: 16 clientid: TRANS flags: none
> RUD: #regs: 1 id: 0xffff925955341f20
> ----------------------------------------------------------------------------
> Oper (15): tid: 17c5790c len: 16 clientid: TRANS flags: none
> RUD: #regs: 1 id: 0xffff8f0e48254000
> ----------------------------------------------------------------------------
> Oper (16): tid: 17c5790c len: 24 clientid: TRANS flags: none
> BUF: #regs: 3 start blkno: 40 (0x28) len: 8 bmap size: 1 flags: 0x2000
> Oper (17): tid: 17c5790c len: 128 clientid: TRANS flags: none
> BUF DATA
> 0 33424d52 31000000 ffffffff ffffffff 0 28000000 1000000 38000000
> 8 3674196c 564cfddf 7798e496 591b6410 0 42249385 0 1000000
> 10 ffffffff fdffffff 0 0 1000000 2000000 ffffffff fbffffff
> 18 0 0 3000000 2000000 ffffffff faffffff 0 0
>
> Oper (18): tid: 17c5790c len: 128 clientid: TRANS flags: none
> BUF DATA
> 0 0 0 4d010000 9000000 0 8a000000 0 2a000000
> 8 56010000 d000000 ffffffff f7ffffff 0 0 65010000 6b000000
> 10 ffffffff f7ffffff 0 0 78010000 1000000 0 86000000
> 18 0 13000000 0 0 0 0 0 0
>
> ----------------------------------------------------------------------------
> Oper (19): tid: 17c5790c len: 0 clientid: TRANS flags: COMMIT
>
> Ok, so those last two lines in operation 16 show that we've indeed added the
> new record to the rmapbt... <shrug> <confused> <tired>??
>
> Are we sure that the log recovery actions actually get checkpointed
> correctly? And just to check my own sanity, we generate a snapshot and
> then recover it and run xfs_repair, right?
>
> --D
>
>>
>>>
>>> (Normally I'd say send a metadump too for us mere mortals to work with,
>>> though I'm about to plunge into weddingland so I likely won't be able to
>>> do much until the 18th.)
>>>
>>
>> Attached (used xfs_metadump -ao)
>> Soon we will all be gods with powers to replay history ;)
>>
>>> ((Eric: If this doesn't turn out to be a totally garbage patch, feel
>>> free to add it to xfsprogs.))
>>>
>>> --D
>>>
>
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
>
> .
>
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs clones crash issue - illegal state 13 in block map
2017-10-09 12:48 ` Hou Tao
@ 2017-10-10 19:18 ` Darrick J. Wong
2017-11-22 18:25 ` Darrick J. Wong
0 siblings, 1 reply; 8+ messages in thread
From: Darrick J. Wong @ 2017-10-10 19:18 UTC (permalink / raw)
To: Hou Tao; +Cc: Amir Goldstein, Christoph Hellwig, linux-xfs
On Mon, Oct 09, 2017 at 08:48:34PM +0800, Hou Tao wrote:
> Hi,
>
> On 2017/9/19 13:38, Darrick J. Wong wrote:
> > On Fri, Sep 08, 2017 at 11:34:58AM +0300, Amir Goldstein wrote:
> >> On Thu, Sep 7, 2017 at 7:13 PM, Darrick J. Wong <darrick.wong@oracle.com> wrote:
> >>> On Thu, Sep 07, 2017 at 03:58:56PM +0300, Amir Goldstein wrote:
> >>>> Hi guys,
> >>>>
> >>>> I am getting these errors often when running the crash tests
> >>>> with cloned files (generic/502 in my xfstests patches).
> >>>>
> >>>> Hitting these errors requires first fixing 2 other issues
> >>>> that shadow over this issue:
> >>>> "xfs: fix incorrect log_flushed on fsync" (in master)
> >>>> "xfs: fix leftover CoW extent after truncate"
> >>>> available on my tree based on Darrick's simple fix:
> >>>> https://github.com/amir73il/linux/commits/xfs-fsync
> >>>>
> >>>> I get the errors more often (1 out of 5) on a 100G fs on spinning disk.
> >>>> On a 10G fs on SSD they are less frequent.
> >>>> The log in this email was captured on patched stable 4.9.47 kernel,
> >>>> but I am getting the same errors on patched upstream kernel.
> >>>>
> >>>> I wasn't able to create a deterministic reproducer, so attaching
> >>>> the full log from a failed test along with an IO log that can be
> >>>> replayed on your disk to examine the outcome.
> >>>>
> >>>> Following is the output of fsx process #5, which is the process
> >>>> that wrote the problematic testfile5.mark0 to the log.
> >>>> This process performs only read,zero,fsync before creating
> >>>> the log mark.
> >>>> The file testfile5 was cloned from an origin 256K file before
> >>>> running fsx.
> >>>> Later, I used the random seed 35484 in this log for all
> >>>> processes and it seemed to increase the probability for failure.
> >>>>
> >>>> # /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P
> >>>> /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5
> >>>> /mnt/scratch/testfile5
> >>>> Seed set to 35484
> >>>> file_size=262144
> >>>> 5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
> >>>> 5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
> >>>> 5: 3 fsync
> >>>> 5: Dumped fsync buffer to testfile5.mark0
> >>>>
> >>>> In order to get to the crash state you need to get my
> >>>> xfstests replay-log patches and replay the attached log
> >>>> on a >= 100G scratch device:
> >>>>
> >>>> # ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
> >>>> $SCRATCH_DEV --end-mark testfile5.mark0
> >>>> # mount $SCRATCH_DEV $SCRATCH_MNT
> >>>> # umount $SCRATCH_MNT
> >>>> # xfs_repair -n $SCRATCH_DEV
> >>>> Phase 1 - find and verify superblock...
> >>>> Phase 2 - using internal log
> >>>> - zero log...
> >>>> - scan filesystem freespace and inode maps...
> >>>> - found root inode chunk
> >>>> Phase 3 - for each AG...
> >>>> - scan (but don't clear) agi unlinked lists...
> >>>> - process known inodes and perform inode discovery...
> >>>> - agno = 0
> >>>>
> >>>> fatal error -- illegal state 13 in block map 376
> >>>>
> >>>> Can anyone provide some insight?
> >>>
> >>> Looks like I missed a couple of extent states in process_bmbt_reclist_int.
> >>>
> >>> What happens if you add the following (only compile tested) patch to
> >>> xfsprogs?
> >>
> >> This is what happens:
> >>
> >> Phase 1 - find and verify superblock...
> >> Phase 2 - using internal log
> >> - zero log...
> >> - scan filesystem freespace and inode maps...
> >> - found root inode chunk
> >> Phase 3 - for each AG...
> >> - scan (but don't clear) agi unlinked lists...
> >> - process known inodes and perform inode discovery...
> >> - agno = 0
> >> data fork in regular inode 134 claims CoW block 376
> >> correcting nextents for inode 134
> >> bad data fork in inode 134
> >> would have cleared inode 134
> >> - agno = 1
> >> - agno = 2
> >> - agno = 3
> >> - process newly discovered inodes...
> >> Phase 4 - check for duplicate blocks...
> >> - setting up duplicate extent list...
> >> unknown block state, ag 0, block 376
> >> unknown block state, ag 1, block 16
> >> - check for inodes claiming duplicate blocks...
> >> - agno = 0
> >> - agno = 1
> >> - agno = 2
> >> entry "testfile2" in shortform directory 128 references free inode 134
> >> - agno = 3
> >> would have junked entry "testfile2" in directory inode 128
> >> imap claims in-use inode 134 is free, would correct imap
> >> Missing reverse-mapping record for (0/376) len 1 owner 134 off 19
> >> No modify flag set, skipping phase 5
> >> Phase 6 - check inode connectivity...
> >> - traversing filesystem ...
> >> - traversal finished ...
> >> - moving disconnected inodes to lost+found ...
> >> Phase 7 - verify link counts...
> >> No modify flag set, skipping filesystem flush and exiting.
> >
> > Hmm.
> >
> > # xfs_db bugs.img
> > xfs_db> inode 134
> > xfs_db> bmap
> > data offset 0 startblock 24 (0/24) count 19 flag 0
> > data offset 19 startblock 376 (0/376) count 1 flag 0
> > data offset 25 startblock 8388624 (1/16) count 4 flag 1
> > data offset 29 startblock 53 (0/53) count 35 flag 0
> >
> > Ok, so inode 134 thinks it owns block 376.
> >
> > xfs_db> agf 0
> > xfs_db> addr refcntroot
> > xfs_db> p
> > ...
> > recs[1-22] = [startblock,blockcount,refcount,cowflag]
> > 1:[24,1,11,0]
> > ...
> > 22:[87,1,6,0]
> > xfs_db>
> >
> > Ok, so the refcountbt doesn't know about block 376, so it's neither
> > shared nor a cow staging extent.
> >
> > xfs_db> agf 0
> > xfs_db> addr rmaproot
> > xfs_db> p
> > ...
> > recs[1-38] = [startblock,blockcount,owner,offset,extentflag,attrfork,bmbtblock]
> > 1:[0,1,-3,0,0,0,0]
> > ...
> > 38:[376,1,-9,0,0,0,0]
> > xfs_db>
> >
> > So it seems that the rmapbt is behind the times, since record 38 should
> > be [376,1,134,19,0,0,0]. Either that's because there's something wrong
> > with the regular deferred ops mechanism, or log recovery of deferred ops.
> I think the log recovery of deferred ops is incorrect, and we also need to
> add more checks when manipulating the b-tree of rmap.
>
> I had reproduced the problem on my KVM VM, and i will explain the incorrectness of
> log recovery of deferred ops by using my own example. If addition information is
> needed, please just ask.
>
> The phenomena is the same: a block extent had been assigned to a file, but in the
> rmap b-tree the block extent belongs to COW procedure.
>
> We can get the following output from xfs_db after mounting and umounting the device:
>
> ./src/log-writes/replay-log --replay /dev/vdd --end-mark testfile7.mark0 --log /dev/vde
>
> xfs_logprint -o /dev/vdd > pre_mount.log
> mount /dev/vdd /tmp/vdd
> umount /tmp/vdd
> xfs_logprint -o /dev/vdd > post_mount.log
>
> xfs_db /dev/vdd
> xfs_db> inode 137
> xfs_db> p u3.bmx[3]
> u3.bmx[3] = [startoff,startblock,blockcount,extentflag]
> 3:[58,341,2,0]
>
> xfs_db> agf 0
> xfs_db> addr rmaproot
> xfs_db> p recs[44]
> recs[44] = [startblock,blockcount,owner,offset,extentflag,attrfork,bmbtblock]
> 44:[341,2,-9,0,0,0,0]
>
> The last log record in pre_mount.log (generated before mount) has the following ops
> which are related with inode 137:
>
> # from pre_mount.log
> # initiate by xfs_reflink_end_cow()
> # decrease ref: [0x52, +2]
> # free cow: [0x155, +2]
> ----------------------------------------------------------------------------
> Oper (160): tid: c2350d60 len: 48 clientid: TRANS flags: none
> CUI: #regs: 1 num_extents: 2 id: 0xffff88011b37c680
> (s: 0x52, l: 2, f: 0x2)
> (s: 0x155, l: 2, f: 0x4)
> ----------------------------------------------------------------------------
>
> # map shared: [0x155, +2] to inode 137
> ----------------------------------------------------------------------------
> Oper (161): tid: c2350d60 len: 48 clientid: TRANS flags: none
> BUI: #regs: 1 num_extents: 1 id: 0xffff880117f0c300
> (s: 0x155, l: 2, own: 137, off: 58, f: 0x1)
> ----------------------------------------------------------------------------
>
> # for CUI Oper (160)
> ----------------------------------------------------------------------------
> Oper (194): tid: c2350d60 len: 16 clientid: TRANS flags: none
> CUD: #regs: 1 id: 0xffff88011b37c680
> ----------------------------------------------------------------------------
>
> # free rmap: [0x155, +2]
> ----------------------------------------------------------------------------
> Oper (197): tid: c2350d60 len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff880124a3ea00
> (s: 0x155, l: 2, own: -9, off: 0, f: 0x8)
> ----------------------------------------------------------------------------
> Oper (198): tid: c2350d60 len: 0 clientid: TRANS flags: COMMIT
> ============================================================================
>
> According to the implementation of xfs_defer_finish(), these ops should be completed
> in the following sequence:
>
> Have been done:
> (1) CUI: Oper (160)
> (2) BUI: Oper (161)
> (3) CUD: Oper (194), for CUI Oper (160)
> (4) RUI A: Oper (197), free rmap [0x155, 2, -9]
>
> Should be done:
> (5) BUD: for BUI Oper (161)
> (6) RUI B: add rmap [0x155, 2, 137]
> (7) RUD: for RUI A
> (8) RUD: for RUI B
>
> Actually be done by xlog_recover_process_intents()
> (5) BUD: for BUI Oper (161)
> (6) RUI B: add rmap [0x155, 2, 137]
> (7) RUD: for RUI B
> (8) RUD: for RUI A
>
> So the rmap entry [0x155, 2, -9] for COW should be freed firstly,
> then a new rmap entry [0x155, 2, 137] will be added. However, as we can see
> from the log record in post_mount.log (generated after umount) and the trace
> print, the new rmap entry [0x155, 2, 137] are added firstly, then the rmap
> entry [0x155, 2, -9] are freed.
Hmm, yes, the BUI replay causes RUI B to be created and attached to the
transaction it created to replay the BUI... and then we make the fatal
mistake to finish the BUI's accumulated defer_ops before replaying RUI
A. If we were /not/ in log recovery we'd append the new intent items to
the end of the defer_ops that's coordinating all the intent items, but
in log recovery each intent starts its own transaction and manages its
own defer_ops, so everything runs out of order.
A way to solve this is if xlog_recover_process_intents instead creates
its own defer_ops and passes that into xlog_recover_process_*ui to
collect all the /new/ intent items. Once we're done dealing with the
intent items that were already in the log, we can create another
transaction and xfs_defer_finish all the new defer_ops.
Hard questions: We'd also have to collect block usage requirements for
the transaction and it's not clear if it's problematic to be collecting
all these follow-on intents (which may have come from totally different
defer_ops pre-crash) in a single defer_ops. I'll have to go have a
think about this one.
> # from post_mount.log
> ----------------------------------------------------------------------------
> Oper (2): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
> BUD: #regs: 1 id: 0xffff880117f0c300
> ----------------------------------------------------------------------------
>
> # add rmap [0x155, 2, 137]
> ----------------------------------------------------------------------------
> Oper (6): tid: 3c5adcc1 len: 48 clientid: TRANS flags: none
> RUI: #regs: 1 num_extents: 1 id: 0xffff880125bdc2a0
> (s: 0x155, l: 2, own: 137, off: 58, f: 0x2)
> ----------------------------------------------------------------------------
> Oper (7): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
> RUD: #regs: 1 id: 0xffff880125bdc2a0
> ----------------------------------------------------------------------------
>
> # remove rmap [0x155, 2, -9]
> ----------------------------------------------------------------------------
> Oper (20): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
> RUD: #regs: 1 id: 0xffff880124a3ea00
> ----------------------------------------------------------------------------
>
> # from trace print
>
> # add rmap [0x155, 2, 137], find [0x12d, 46, -9], and insert [0x155, 2, 137]
> xfs_rmap_defer: dev 253:48 op 1 agno 0 agbno 341 owner 137 data offset 58 len 2 state 0
> xfs_rmap_deferred: dev 253:48 op 1 agno 0 agbno 341 owner 137 data offset 58 len 2 state 0
> xfs_rmap_map: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
> xfs_rmap_find_left_neighbor_query: dev 253:48 agno 0 agbno 341 len 0 owner 137 offset 58 flags 0x0
> xfs_rmap_find_left_neighbor_candidate: dev 253:48 agno 0 agbno 301 len 46 owner -9 offset 0 flags 0x0
> xfs_rmap_insert: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
> xfs_rmap_map_done: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
>
> # del rmap [0x155, 2, -9], find [0x155, 2, 137], and remove [0x155, 2, 137]
> xfs_rmap_deferred: dev 253:48 op 7 agno 0 agbno 341 owner -9 data offset 0 len 2 state 0
> xfs_rmap_unmap: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
> xfs_rmap_lookup_le_range_result: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
So we do a non-overlapped lookup for [0x155, 2, -9] and we get [0x155,
2, 137] because the non-overlapped lookups stop when they get to the
first record for the block number, and -9 comes after 137. We /ought/
at least to bail out of _rmap_unmap except for this garbled check:
/* Make sure the owner matches what we expect to find in the tree. */
XFS_WANT_CORRUPTED_GOTO(mp, owner == ltrec.rm_owner ||
XFS_RMAP_NON_INODE_OWNER(owner), out_error);
I think that really ought to be "owner == ltrec.rm_owner || owner ==
XFS_RMAP_OWN_UNKNOWN" instead of what's there.
Ofc that will just make it so that recovery blows up and the fs is
unmountable, which doesn't get us very far if we don't fix the problem
of the misordered intent item replays.
--D
> xfs_rmap_delete: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
> xfs_rmap_unmap_done: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
>
> # del rmap [0x12d, 40, -9]
> xfs_rmap_unmap: dev 253:48 agno 0 agbno 301 len 40 owner -9 offset 0 flags 0x0
> # del rmap [0x157, 4, -9]
> xfs_rmap_unmap: dev 253:48 agno 0 agbno 343 len 4 owner -9 offset 0 flags 0x0
> xfs_rmap_update: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
>
> Regards,
>
> Tao
>
> > Let's have a look at the log...
> >
> > # xfs_logprint bugs.img | grep x178 -B3
> > Oper (426): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> > CUI: #regs: 1 num_extents: 2 id: 0xffff8f0e842f74b8
> > (s: 0x2b, l: 1, f: 0x2)
> > (s: 0x178, l: 1, f: 0x4)
> >
> > ...ok, so we XFS_REFCOUNT_FREE_COW block 376, which removes it from from
> > the refcountbt...
> >
> > ----------------------------------------------------------------------------
> > Oper (427): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> > BUI: #regs: 1 num_extents: 1 id: 0xffff8f0e81f39000
> > (s: 0x178, l: 1, own: 134, off: 19, f: 0x1)
> >
> > ...now we map block 376 into the data fork of inode 134 at offset 19...
> >
> > --
> > ----------------------------------------------------------------------------
> > Oper (447): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> > RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254000
> > (s: 0x178, l: 1, own: -9, off: 0, f: 0x8)
> >
> > ...now we XFS_RMAP_EXTENT_FREE the CoW extent @ block 376 from the rmap,
> > which ought to remove the record...
> >
> > --
> > ----------------------------------------------------------------------------
> > Oper (453): tid: e0ecea6a len: 48 clientid: TRANS flags: none
> > RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
> > (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
> >
> > ...and XFS_RMAP_EXTENT_MAP_SHARED a new rmapping for block 376, which
> > should add the [376,1,134,19,0,0,0] that we'd expect to be there...
> >
> > --
> > ----------------------------------------------------------------------------
> > Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
> > RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> > (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
> >
> > ...strange, another rmap add? Did the RUIs fail to complete?
> >
> > # xfs_logprint bugs.img | egrep '(0xffff8f0e48254530|0xffff925955341f20)'
> > RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
> > RUD: #regs: 1 id: 0xffff8f0e48254530
> > RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> > RUD: #regs: 1 id: 0xffff925955341f20
> >
> > ...the first RUI is logged as operation 453 in tid e0ecea6a, and it has
> > an RUD at 460. However, I don't see a COMMIT, so I gather that log
> > recovery tried to replay the RUI as operation 13 in tid 17c5790c.
> >
> > ----------------------------------------------------------------------------
> > Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
> > RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> > (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
> > ----------------------------------------------------------------------------
> > Oper (14): tid: 17c5790c len: 16 clientid: TRANS flags: none
> > RUD: #regs: 1 id: 0xffff925955341f20
> > ----------------------------------------------------------------------------
> > Oper (15): tid: 17c5790c len: 16 clientid: TRANS flags: none
> > RUD: #regs: 1 id: 0xffff8f0e48254000
> > ----------------------------------------------------------------------------
> > Oper (16): tid: 17c5790c len: 24 clientid: TRANS flags: none
> > BUF: #regs: 3 start blkno: 40 (0x28) len: 8 bmap size: 1 flags: 0x2000
> > Oper (17): tid: 17c5790c len: 128 clientid: TRANS flags: none
> > BUF DATA
> > 0 33424d52 31000000 ffffffff ffffffff 0 28000000 1000000 38000000
> > 8 3674196c 564cfddf 7798e496 591b6410 0 42249385 0 1000000
> > 10 ffffffff fdffffff 0 0 1000000 2000000 ffffffff fbffffff
> > 18 0 0 3000000 2000000 ffffffff faffffff 0 0
> >
> > Oper (18): tid: 17c5790c len: 128 clientid: TRANS flags: none
> > BUF DATA
> > 0 0 0 4d010000 9000000 0 8a000000 0 2a000000
> > 8 56010000 d000000 ffffffff f7ffffff 0 0 65010000 6b000000
> > 10 ffffffff f7ffffff 0 0 78010000 1000000 0 86000000
> > 18 0 13000000 0 0 0 0 0 0
> >
> > ----------------------------------------------------------------------------
> > Oper (19): tid: 17c5790c len: 0 clientid: TRANS flags: COMMIT
> >
> > Ok, so those last two lines in operation 16 show that we've indeed added the
> > new record to the rmapbt... <shrug> <confused> <tired>??
> >
> > Are we sure that the log recovery actions actually get checkpointed
> > correctly? And just to check my own sanity, we generate a snapshot and
> > then recover it and run xfs_repair, right?
> >
> > --D
> >
> >>
> >>>
> >>> (Normally I'd say send a metadump too for us mere mortals to work with,
> >>> though I'm about to plunge into weddingland so I likely won't be able to
> >>> do much until the 18th.)
> >>>
> >>
> >> Attached (used xfs_metadump -ao)
> >> Soon we will all be gods with powers to replay history ;)
> >>
> >>> ((Eric: If this doesn't turn out to be a totally garbage patch, feel
> >>> free to add it to xfsprogs.))
> >>>
> >>> --D
> >>>
> >
> >
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at http://vger.kernel.org/majordomo-info.html
> >
> > .
> >
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: xfs clones crash issue - illegal state 13 in block map
2017-10-10 19:18 ` Darrick J. Wong
@ 2017-11-22 18:25 ` Darrick J. Wong
0 siblings, 0 replies; 8+ messages in thread
From: Darrick J. Wong @ 2017-11-22 18:25 UTC (permalink / raw)
To: Hou Tao; +Cc: Amir Goldstein, Christoph Hellwig, linux-xfs
On Tue, Oct 10, 2017 at 12:18:25PM -0700, Darrick J. Wong wrote:
> On Mon, Oct 09, 2017 at 08:48:34PM +0800, Hou Tao wrote:
> > Hi,
> >
> > On 2017/9/19 13:38, Darrick J. Wong wrote:
> > > On Fri, Sep 08, 2017 at 11:34:58AM +0300, Amir Goldstein wrote:
> > >> On Thu, Sep 7, 2017 at 7:13 PM, Darrick J. Wong <darrick.wong@oracle.com> wrote:
> > >>> On Thu, Sep 07, 2017 at 03:58:56PM +0300, Amir Goldstein wrote:
> > >>>> Hi guys,
> > >>>>
> > >>>> I am getting these errors often when running the crash tests
> > >>>> with cloned files (generic/502 in my xfstests patches).
> > >>>>
> > >>>> Hitting these errors requires first fixing 2 other issues
> > >>>> that shadow over this issue:
> > >>>> "xfs: fix incorrect log_flushed on fsync" (in master)
> > >>>> "xfs: fix leftover CoW extent after truncate"
> > >>>> available on my tree based on Darrick's simple fix:
> > >>>> https://github.com/amir73il/linux/commits/xfs-fsync
> > >>>>
> > >>>> I get the errors more often (1 out of 5) on a 100G fs on spinning disk.
> > >>>> On a 10G fs on SSD they are less frequent.
> > >>>> The log in this email was captured on patched stable 4.9.47 kernel,
> > >>>> but I am getting the same errors on patched upstream kernel.
> > >>>>
> > >>>> I wasn't able to create a deterministic reproducer, so attaching
> > >>>> the full log from a failed test along with an IO log that can be
> > >>>> replayed on your disk to examine the outcome.
> > >>>>
> > >>>> Following is the output of fsx process #5, which is the process
> > >>>> that wrote the problematic testfile5.mark0 to the log.
> > >>>> This process performs only read,zero,fsync before creating
> > >>>> the log mark.
> > >>>> The file testfile5 was cloned from an origin 256K file before
> > >>>> running fsx.
> > >>>> Later, I used the random seed 35484 in this log for all
> > >>>> processes and it seemed to increase the probability for failure.
> > >>>>
> > >>>> # /old/home/amir/src/xfstests-dev/ltp/fsx -N 100 -d -k -P
> > >>>> /mnt/test/fsxtests -i /dev/mapper/logwrites-test -S 0 -j 5
> > >>>> /mnt/scratch/testfile5
> > >>>> Seed set to 35484
> > >>>> file_size=262144
> > >>>> 5: 1 read 0x3f959 thru 0x3ffff (0x6a7 bytes)
> > >>>> 5: 2 zero from 0x3307e to 0x34f74, (0x1ef6 bytes)
> > >>>> 5: 3 fsync
> > >>>> 5: Dumped fsync buffer to testfile5.mark0
> > >>>>
> > >>>> In order to get to the crash state you need to get my
> > >>>> xfstests replay-log patches and replay the attached log
> > >>>> on a >= 100G scratch device:
> > >>>>
> > >>>> # ./src/log-writes/replay-log --log log.xfs.testfile5.mark0 --replay
> > >>>> $SCRATCH_DEV --end-mark testfile5.mark0
> > >>>> # mount $SCRATCH_DEV $SCRATCH_MNT
> > >>>> # umount $SCRATCH_MNT
> > >>>> # xfs_repair -n $SCRATCH_DEV
> > >>>> Phase 1 - find and verify superblock...
> > >>>> Phase 2 - using internal log
> > >>>> - zero log...
> > >>>> - scan filesystem freespace and inode maps...
> > >>>> - found root inode chunk
> > >>>> Phase 3 - for each AG...
> > >>>> - scan (but don't clear) agi unlinked lists...
> > >>>> - process known inodes and perform inode discovery...
> > >>>> - agno = 0
> > >>>>
> > >>>> fatal error -- illegal state 13 in block map 376
> > >>>>
> > >>>> Can anyone provide some insight?
> > >>>
> > >>> Looks like I missed a couple of extent states in process_bmbt_reclist_int.
> > >>>
> > >>> What happens if you add the following (only compile tested) patch to
> > >>> xfsprogs?
> > >>
> > >> This is what happens:
> > >>
> > >> Phase 1 - find and verify superblock...
> > >> Phase 2 - using internal log
> > >> - zero log...
> > >> - scan filesystem freespace and inode maps...
> > >> - found root inode chunk
> > >> Phase 3 - for each AG...
> > >> - scan (but don't clear) agi unlinked lists...
> > >> - process known inodes and perform inode discovery...
> > >> - agno = 0
> > >> data fork in regular inode 134 claims CoW block 376
> > >> correcting nextents for inode 134
> > >> bad data fork in inode 134
> > >> would have cleared inode 134
> > >> - agno = 1
> > >> - agno = 2
> > >> - agno = 3
> > >> - process newly discovered inodes...
> > >> Phase 4 - check for duplicate blocks...
> > >> - setting up duplicate extent list...
> > >> unknown block state, ag 0, block 376
> > >> unknown block state, ag 1, block 16
> > >> - check for inodes claiming duplicate blocks...
> > >> - agno = 0
> > >> - agno = 1
> > >> - agno = 2
> > >> entry "testfile2" in shortform directory 128 references free inode 134
> > >> - agno = 3
> > >> would have junked entry "testfile2" in directory inode 128
> > >> imap claims in-use inode 134 is free, would correct imap
> > >> Missing reverse-mapping record for (0/376) len 1 owner 134 off 19
> > >> No modify flag set, skipping phase 5
> > >> Phase 6 - check inode connectivity...
> > >> - traversing filesystem ...
> > >> - traversal finished ...
> > >> - moving disconnected inodes to lost+found ...
> > >> Phase 7 - verify link counts...
> > >> No modify flag set, skipping filesystem flush and exiting.
> > >
> > > Hmm.
> > >
> > > # xfs_db bugs.img
> > > xfs_db> inode 134
> > > xfs_db> bmap
> > > data offset 0 startblock 24 (0/24) count 19 flag 0
> > > data offset 19 startblock 376 (0/376) count 1 flag 0
> > > data offset 25 startblock 8388624 (1/16) count 4 flag 1
> > > data offset 29 startblock 53 (0/53) count 35 flag 0
> > >
> > > Ok, so inode 134 thinks it owns block 376.
> > >
> > > xfs_db> agf 0
> > > xfs_db> addr refcntroot
> > > xfs_db> p
> > > ...
> > > recs[1-22] = [startblock,blockcount,refcount,cowflag]
> > > 1:[24,1,11,0]
> > > ...
> > > 22:[87,1,6,0]
> > > xfs_db>
> > >
> > > Ok, so the refcountbt doesn't know about block 376, so it's neither
> > > shared nor a cow staging extent.
> > >
> > > xfs_db> agf 0
> > > xfs_db> addr rmaproot
> > > xfs_db> p
> > > ...
> > > recs[1-38] = [startblock,blockcount,owner,offset,extentflag,attrfork,bmbtblock]
> > > 1:[0,1,-3,0,0,0,0]
> > > ...
> > > 38:[376,1,-9,0,0,0,0]
> > > xfs_db>
> > >
> > > So it seems that the rmapbt is behind the times, since record 38 should
> > > be [376,1,134,19,0,0,0]. Either that's because there's something wrong
> > > with the regular deferred ops mechanism, or log recovery of deferred ops.
> > I think the log recovery of deferred ops is incorrect, and we also need to
> > add more checks when manipulating the b-tree of rmap.
> >
> > I had reproduced the problem on my KVM VM, and i will explain the incorrectness of
> > log recovery of deferred ops by using my own example. If addition information is
> > needed, please just ask.
> >
> > The phenomena is the same: a block extent had been assigned to a file, but in the
> > rmap b-tree the block extent belongs to COW procedure.
> >
> > We can get the following output from xfs_db after mounting and umounting the device:
> >
> > ./src/log-writes/replay-log --replay /dev/vdd --end-mark testfile7.mark0 --log /dev/vde
> >
> > xfs_logprint -o /dev/vdd > pre_mount.log
> > mount /dev/vdd /tmp/vdd
> > umount /tmp/vdd
> > xfs_logprint -o /dev/vdd > post_mount.log
> >
> > xfs_db /dev/vdd
> > xfs_db> inode 137
> > xfs_db> p u3.bmx[3]
> > u3.bmx[3] = [startoff,startblock,blockcount,extentflag]
> > 3:[58,341,2,0]
> >
> > xfs_db> agf 0
> > xfs_db> addr rmaproot
> > xfs_db> p recs[44]
> > recs[44] = [startblock,blockcount,owner,offset,extentflag,attrfork,bmbtblock]
> > 44:[341,2,-9,0,0,0,0]
> >
> > The last log record in pre_mount.log (generated before mount) has the following ops
> > which are related with inode 137:
> >
> > # from pre_mount.log
> > # initiate by xfs_reflink_end_cow()
> > # decrease ref: [0x52, +2]
> > # free cow: [0x155, +2]
> > ----------------------------------------------------------------------------
> > Oper (160): tid: c2350d60 len: 48 clientid: TRANS flags: none
> > CUI: #regs: 1 num_extents: 2 id: 0xffff88011b37c680
> > (s: 0x52, l: 2, f: 0x2)
> > (s: 0x155, l: 2, f: 0x4)
> > ----------------------------------------------------------------------------
> >
> > # map shared: [0x155, +2] to inode 137
> > ----------------------------------------------------------------------------
> > Oper (161): tid: c2350d60 len: 48 clientid: TRANS flags: none
> > BUI: #regs: 1 num_extents: 1 id: 0xffff880117f0c300
> > (s: 0x155, l: 2, own: 137, off: 58, f: 0x1)
> > ----------------------------------------------------------------------------
> >
> > # for CUI Oper (160)
> > ----------------------------------------------------------------------------
> > Oper (194): tid: c2350d60 len: 16 clientid: TRANS flags: none
> > CUD: #regs: 1 id: 0xffff88011b37c680
> > ----------------------------------------------------------------------------
> >
> > # free rmap: [0x155, +2]
> > ----------------------------------------------------------------------------
> > Oper (197): tid: c2350d60 len: 48 clientid: TRANS flags: none
> > RUI: #regs: 1 num_extents: 1 id: 0xffff880124a3ea00
> > (s: 0x155, l: 2, own: -9, off: 0, f: 0x8)
> > ----------------------------------------------------------------------------
> > Oper (198): tid: c2350d60 len: 0 clientid: TRANS flags: COMMIT
> > ============================================================================
> >
> > According to the implementation of xfs_defer_finish(), these ops should be completed
> > in the following sequence:
> >
> > Have been done:
> > (1) CUI: Oper (160)
> > (2) BUI: Oper (161)
> > (3) CUD: Oper (194), for CUI Oper (160)
> > (4) RUI A: Oper (197), free rmap [0x155, 2, -9]
> >
> > Should be done:
> > (5) BUD: for BUI Oper (161)
> > (6) RUI B: add rmap [0x155, 2, 137]
> > (7) RUD: for RUI A
> > (8) RUD: for RUI B
> >
> > Actually be done by xlog_recover_process_intents()
> > (5) BUD: for BUI Oper (161)
> > (6) RUI B: add rmap [0x155, 2, 137]
> > (7) RUD: for RUI B
> > (8) RUD: for RUI A
> >
> > So the rmap entry [0x155, 2, -9] for COW should be freed firstly,
> > then a new rmap entry [0x155, 2, 137] will be added. However, as we can see
> > from the log record in post_mount.log (generated after umount) and the trace
> > print, the new rmap entry [0x155, 2, 137] are added firstly, then the rmap
> > entry [0x155, 2, -9] are freed.
>
> Hmm, yes, the BUI replay causes RUI B to be created and attached to the
> transaction it created to replay the BUI... and then we make the fatal
> mistake to finish the BUI's accumulated defer_ops before replaying RUI
> A. If we were /not/ in log recovery we'd append the new intent items to
> the end of the defer_ops that's coordinating all the intent items, but
> in log recovery each intent starts its own transaction and manages its
> own defer_ops, so everything runs out of order.
>
> A way to solve this is if xlog_recover_process_intents instead creates
> its own defer_ops and passes that into xlog_recover_process_*ui to
> collect all the /new/ intent items. Once we're done dealing with the
> intent items that were already in the log, we can create another
> transaction and xfs_defer_finish all the new defer_ops.
>
> Hard questions: We'd also have to collect block usage requirements for
> the transaction and it's not clear if it's problematic to be collecting
> all these follow-on intents (which may have come from totally different
> defer_ops pre-crash) in a single defer_ops. I'll have to go have a
> think about this one.
Sorry for letting this one drag on for a month. It occurred to me that
log recovery is the only user of the filesystem at this point, so we
could simply throw all the free space at the defer_ops cleanup
transaction. I've come up with a RFC-quality patch that restructures
the intent item replay code and will start a new thread to discuss it.
--D
> > # from post_mount.log
> > ----------------------------------------------------------------------------
> > Oper (2): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
> > BUD: #regs: 1 id: 0xffff880117f0c300
> > ----------------------------------------------------------------------------
> >
> > # add rmap [0x155, 2, 137]
> > ----------------------------------------------------------------------------
> > Oper (6): tid: 3c5adcc1 len: 48 clientid: TRANS flags: none
> > RUI: #regs: 1 num_extents: 1 id: 0xffff880125bdc2a0
> > (s: 0x155, l: 2, own: 137, off: 58, f: 0x2)
> > ----------------------------------------------------------------------------
> > Oper (7): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
> > RUD: #regs: 1 id: 0xffff880125bdc2a0
> > ----------------------------------------------------------------------------
> >
> > # remove rmap [0x155, 2, -9]
> > ----------------------------------------------------------------------------
> > Oper (20): tid: 3c5adcc1 len: 16 clientid: TRANS flags: none
> > RUD: #regs: 1 id: 0xffff880124a3ea00
> > ----------------------------------------------------------------------------
> >
> > # from trace print
> >
> > # add rmap [0x155, 2, 137], find [0x12d, 46, -9], and insert [0x155, 2, 137]
> > xfs_rmap_defer: dev 253:48 op 1 agno 0 agbno 341 owner 137 data offset 58 len 2 state 0
> > xfs_rmap_deferred: dev 253:48 op 1 agno 0 agbno 341 owner 137 data offset 58 len 2 state 0
> > xfs_rmap_map: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
> > xfs_rmap_find_left_neighbor_query: dev 253:48 agno 0 agbno 341 len 0 owner 137 offset 58 flags 0x0
> > xfs_rmap_find_left_neighbor_candidate: dev 253:48 agno 0 agbno 301 len 46 owner -9 offset 0 flags 0x0
> > xfs_rmap_insert: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
> > xfs_rmap_map_done: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
> >
> > # del rmap [0x155, 2, -9], find [0x155, 2, 137], and remove [0x155, 2, 137]
> > xfs_rmap_deferred: dev 253:48 op 7 agno 0 agbno 341 owner -9 data offset 0 len 2 state 0
> > xfs_rmap_unmap: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
> > xfs_rmap_lookup_le_range_result: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
>
> So we do a non-overlapped lookup for [0x155, 2, -9] and we get [0x155,
> 2, 137] because the non-overlapped lookups stop when they get to the
> first record for the block number, and -9 comes after 137. We /ought/
> at least to bail out of _rmap_unmap except for this garbled check:
>
> /* Make sure the owner matches what we expect to find in the tree. */
> XFS_WANT_CORRUPTED_GOTO(mp, owner == ltrec.rm_owner ||
> XFS_RMAP_NON_INODE_OWNER(owner), out_error);
>
> I think that really ought to be "owner == ltrec.rm_owner || owner ==
> XFS_RMAP_OWN_UNKNOWN" instead of what's there.
>
> Ofc that will just make it so that recovery blows up and the fs is
> unmountable, which doesn't get us very far if we don't fix the problem
> of the misordered intent item replays.
>
> --D
>
> > xfs_rmap_delete: dev 253:48 agno 0 agbno 341 len 2 owner 137 offset 58 flags 0x0
> > xfs_rmap_unmap_done: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
> >
> > # del rmap [0x12d, 40, -9]
> > xfs_rmap_unmap: dev 253:48 agno 0 agbno 301 len 40 owner -9 offset 0 flags 0x0
> > # del rmap [0x157, 4, -9]
> > xfs_rmap_unmap: dev 253:48 agno 0 agbno 343 len 4 owner -9 offset 0 flags 0x0
> > xfs_rmap_update: dev 253:48 agno 0 agbno 341 len 2 owner -9 offset 0 flags 0x0
> >
> > Regards,
> >
> > Tao
> >
> > > Let's have a look at the log...
> > >
> > > # xfs_logprint bugs.img | grep x178 -B3
> > > Oper (426): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> > > CUI: #regs: 1 num_extents: 2 id: 0xffff8f0e842f74b8
> > > (s: 0x2b, l: 1, f: 0x2)
> > > (s: 0x178, l: 1, f: 0x4)
> > >
> > > ...ok, so we XFS_REFCOUNT_FREE_COW block 376, which removes it from from
> > > the refcountbt...
> > >
> > > ----------------------------------------------------------------------------
> > > Oper (427): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> > > BUI: #regs: 1 num_extents: 1 id: 0xffff8f0e81f39000
> > > (s: 0x178, l: 1, own: 134, off: 19, f: 0x1)
> > >
> > > ...now we map block 376 into the data fork of inode 134 at offset 19...
> > >
> > > --
> > > ----------------------------------------------------------------------------
> > > Oper (447): tid: 5c75a3f len: 48 clientid: TRANS flags: none
> > > RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254000
> > > (s: 0x178, l: 1, own: -9, off: 0, f: 0x8)
> > >
> > > ...now we XFS_RMAP_EXTENT_FREE the CoW extent @ block 376 from the rmap,
> > > which ought to remove the record...
> > >
> > > --
> > > ----------------------------------------------------------------------------
> > > Oper (453): tid: e0ecea6a len: 48 clientid: TRANS flags: none
> > > RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
> > > (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
> > >
> > > ...and XFS_RMAP_EXTENT_MAP_SHARED a new rmapping for block 376, which
> > > should add the [376,1,134,19,0,0,0] that we'd expect to be there...
> > >
> > > --
> > > ----------------------------------------------------------------------------
> > > Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
> > > RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> > > (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
> > >
> > > ...strange, another rmap add? Did the RUIs fail to complete?
> > >
> > > # xfs_logprint bugs.img | egrep '(0xffff8f0e48254530|0xffff925955341f20)'
> > > RUI: #regs: 1 num_extents: 1 id: 0xffff8f0e48254530
> > > RUD: #regs: 1 id: 0xffff8f0e48254530
> > > RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> > > RUD: #regs: 1 id: 0xffff925955341f20
> > >
> > > ...the first RUI is logged as operation 453 in tid e0ecea6a, and it has
> > > an RUD at 460. However, I don't see a COMMIT, so I gather that log
> > > recovery tried to replay the RUI as operation 13 in tid 17c5790c.
> > >
> > > ----------------------------------------------------------------------------
> > > Oper (13): tid: 17c5790c len: 48 clientid: TRANS flags: none
> > > RUI: #regs: 1 num_extents: 1 id: 0xffff925955341f20
> > > (s: 0x178, l: 1, own: 134, off: 19, f: 0x2)
> > > ----------------------------------------------------------------------------
> > > Oper (14): tid: 17c5790c len: 16 clientid: TRANS flags: none
> > > RUD: #regs: 1 id: 0xffff925955341f20
> > > ----------------------------------------------------------------------------
> > > Oper (15): tid: 17c5790c len: 16 clientid: TRANS flags: none
> > > RUD: #regs: 1 id: 0xffff8f0e48254000
> > > ----------------------------------------------------------------------------
> > > Oper (16): tid: 17c5790c len: 24 clientid: TRANS flags: none
> > > BUF: #regs: 3 start blkno: 40 (0x28) len: 8 bmap size: 1 flags: 0x2000
> > > Oper (17): tid: 17c5790c len: 128 clientid: TRANS flags: none
> > > BUF DATA
> > > 0 33424d52 31000000 ffffffff ffffffff 0 28000000 1000000 38000000
> > > 8 3674196c 564cfddf 7798e496 591b6410 0 42249385 0 1000000
> > > 10 ffffffff fdffffff 0 0 1000000 2000000 ffffffff fbffffff
> > > 18 0 0 3000000 2000000 ffffffff faffffff 0 0
> > >
> > > Oper (18): tid: 17c5790c len: 128 clientid: TRANS flags: none
> > > BUF DATA
> > > 0 0 0 4d010000 9000000 0 8a000000 0 2a000000
> > > 8 56010000 d000000 ffffffff f7ffffff 0 0 65010000 6b000000
> > > 10 ffffffff f7ffffff 0 0 78010000 1000000 0 86000000
> > > 18 0 13000000 0 0 0 0 0 0
> > >
> > > ----------------------------------------------------------------------------
> > > Oper (19): tid: 17c5790c len: 0 clientid: TRANS flags: COMMIT
> > >
> > > Ok, so those last two lines in operation 16 show that we've indeed added the
> > > new record to the rmapbt... <shrug> <confused> <tired>??
> > >
> > > Are we sure that the log recovery actions actually get checkpointed
> > > correctly? And just to check my own sanity, we generate a snapshot and
> > > then recover it and run xfs_repair, right?
> > >
> > > --D
> > >
> > >>
> > >>>
> > >>> (Normally I'd say send a metadump too for us mere mortals to work with,
> > >>> though I'm about to plunge into weddingland so I likely won't be able to
> > >>> do much until the 18th.)
> > >>>
> > >>
> > >> Attached (used xfs_metadump -ao)
> > >> Soon we will all be gods with powers to replay history ;)
> > >>
> > >>> ((Eric: If this doesn't turn out to be a totally garbage patch, feel
> > >>> free to add it to xfsprogs.))
> > >>>
> > >>> --D
> > >>>
> > >
> > >
> > > --
> > > To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> > > the body of a message to majordomo@vger.kernel.org
> > > More majordomo info at http://vger.kernel.org/majordomo-info.html
> > >
> > > .
> > >
> >
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at http://vger.kernel.org/majordomo-info.html
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2017-11-22 18:26 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-09-07 12:58 xfs clones crash issue - illegal state 13 in block map Amir Goldstein
2017-09-07 16:13 ` Darrick J. Wong
2017-09-08 8:34 ` Amir Goldstein
2017-09-19 5:38 ` Darrick J. Wong
2017-09-19 6:16 ` Amir Goldstein
2017-10-09 12:48 ` Hou Tao
2017-10-10 19:18 ` Darrick J. Wong
2017-11-22 18:25 ` Darrick J. Wong
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).