On Mon, Jul 20, 2015 at 08:55:32AM -0400, Josef Bacik wrote: > On 07/19/2015 07:54 PM, Dave Chinner wrote: > >On Fri, Jul 17, 2015 at 05:10:50PM +0530, Chandan Rajendra wrote: > >>On Friday 17 Jul 2015 06:16:02 Brian Foster wrote: > >>>On Fri, Jul 17, 2015 at 12:56:43AM -0400, Chandan Rajendra wrote: > >>>>When running generic/311 on Btrfs' subpagesize-blocksize patchset (on > >>>>ppc64 > >>>>with 4k sectorsize and 16k node/leaf size) I noticed the following call > >>>>trace, > >>>> > >>>>BTRFS (device dm-0): parent transid verify failed on 29720576 wanted 160 > >>>>found 158 BTRFS (device dm-0): parent transid verify failed on 29720576 > >>>>wanted 160 found 158 BTRFS: Transaction aborted (error -5) > >>>> > >>>>WARNING: at /root/repos/linux/fs/btrfs/super.c:260 > >>>>Modules linked in: > >>>>CPU: 3 PID: 30769 Comm: umount Tainted: G W L > >>>>4.0.0-rc5-11671-g8b82e73e #63 task: c000000079aaddb0 ti: c000000079a48000 > >>>>task.ti: c000000079a48000 NIP: c000000000499aa0 LR: c000000000499a9c CTR: > >>>>c000000000779630 > >>>>REGS: c000000079a4b480 TRAP: 0700 Tainted: G W L > >>>>(4.0.0-rc5-11671-g8b82e73e) MSR: 8000000100029032 <SF,EE,ME,IR,DR,RI> > >>>>CR: 28008828 XER: 20000000 CFAR: c000000000a23914 SOFTE: 1 > >>>>GPR00: c000000000499a9c c000000079a4b700 c00000000103bdf8 0000000000000025 > >>>>GPR04: 0000000000000001 0000000000000502 c00000000107e918 0000000000000cda > >>>>GPR08: 0000000000000007 0000000000000007 0000000000000001 c0000000010f5044 > >>>>GPR12: 0000000028008822 c00000000fdc0d80 0000000020000000 0000000010152e00 > >>>>GPR16: 0000010002979380 0000000010140724 0000000000000000 0000000000000000 > >>>>GPR20: ffffffffffffffff 0000000000000000 0000000000000000 0000000000000000 > >>>>GPR24: c0000000151f61a8 0000000000000000 c000000055e5e800 c000000000aac270 > >>>>GPR28: 00000000000004a4 fffffffffffffffb c000000055e5e800 c0000000679204d0 > >>>>NIP [c000000000499aa0] .__btrfs_abort_transaction+0x180/0x190 > >>>>LR [c000000000499a9c] .__btrfs_abort_transaction+0x17c/0x190 > >>>>Call Trace: > >>>>[c000000079a4b700] [c000000000499a9c] > >>>>.__btrfs_abort_transaction+0x17c/0x190 (unreliable) [c000000079a4b7a0] > >>>>[c000000000541678] .__btrfs_run_delayed_items+0xe8/0x220 > >>>>[c000000079a4b850] [c0000000004d5b3c] > >>>>.btrfs_commit_transaction+0x37c/0xca0 [c000000079a4b960] > >>>>[c00000000049824c] .btrfs_sync_fs+0x6c/0x1a0 > >>>>[c000000079a4ba00] [c000000000255270] .sync_filesystem+0xd0/0x100 > >>>>[c000000079a4ba80] [c000000000218070] .generic_shutdown_super+0x40/0x170 > >>>>[c000000079a4bb10] [c000000000218598] .kill_anon_super+0x18/0x30 > >>>>[c000000079a4bb90] [c000000000498418] .btrfs_kill_super+0x18/0xc0 > >>>>[c000000079a4bc10] [c000000000218ac8] .deactivate_locked_super+0x98/0xe0 > >>>>[c000000079a4bc90] [c00000000023e744] .cleanup_mnt+0x54/0xa0 > >>>>[c000000079a4bd10] [c0000000000b7d14] .task_work_run+0x114/0x150 > >>>>[c000000079a4bdb0] [c000000000015f84] .do_notify_resume+0x74/0x80 > >>>>[c000000079a4be30] [c000000000009838] .ret_from_except_lite+0x64/0x68 > >>>>Instruction dump: > >>>>ebc1fff0 ebe1fff8 4bfffb28 60000000 3ce2ffcd 38e7e818 4bffffbc 3c62ffd2 > >>>>7fa4eb78 3863b808 48589e1d 60000000 <0fe00000> 4bfffedc 60000000 60000000 > >>>>BTRFS: error (device dm-0) in __btrfs_run_delayed_items:1188: errno=-5 IO > >>>>failure > >>>> > >>>> > >>>>The call trace is seen when executing _run_test() for the 8th time. > >>>>The above trace is actually a false-positive failure as indicated below, > >>>> > >>>> fsync-tester > >>>> > >>>> fsync(fd) > >>>> Write delayed inode item to fs tree > >>>> > >>>> (assume transid to be 160) > >>>> (assume tree block to start at logical address 29720576) > >>>> > >>>> md5sum $testfile > >>>> > >>>> This causes a delayed inode to be added > >>>> > >>>> Load flakey table > >>>> > >>>> i.e. drop writes that are initiated from now onwards > >>>> > >>>> Unmount filesystem > >>>> > >>>> btrfs_sync_fs is invoked > >>>> > >>>> Write 29720576 metadata block to disk > >>>> free_extent_buffer(29720576) > >>>> > >>>> release_extent_buffer(29720576) > >>>> > >>>> Start writing delayed inode > >>>> > >>>> Traverse the fs tree > >>>> > >>>> (assume the parent tree block of 29720576 is still in memory) > >>>> When reading 29720576 from disk, parent's blkptr will have > >>>> generation > >>>> set to 160. But the on-disk tree block will have an older > >>>> generation (say, 158). Transid verification fails and hence the > >>>> transaction gets aborted > >>>> > >>>>The test only cares about the FS instance before the unmount > >>>>operation (i.e. the synced FS). Hence to get the test to pass, ignore the > >>>>false-positive trace that could be generated. > >>>> > >>>>Signed-off-by: Chandan Rajendra <chandan@xxxxxxxxxxxxxxxxxx> > >>>>--- > >>>> > >>>> tests/generic/311 | 2 ++ > >>>> 1 file changed, 2 insertions(+) > >>>> > >>>>diff --git a/tests/generic/311 b/tests/generic/311 > >>>>index d21b6eb..cd6391d 100755 > >>>>--- a/tests/generic/311 > >>>>+++ b/tests/generic/311 > >>>>@@ -64,6 +64,8 @@ _require_xfs_io_command "falloc" > >>>> > >>>> [ -x $here/src/fsync-tester ] || _notrun "fsync-tester not built" > >>>> > >>>>+_disable_dmesg_check > >>>>+ > >>> > >>>Hmm, I don't think this is something we'd want to do unconditionally. > >>>E.g., if something hits the logs for xfs or ext4, we probably want to > >>>hear about it. > >>Sorry, I forgot that I was dealing with generic tests. I agree with what you > >>say. > >> > >>> > >>>Perhaps check that the fs is btrfs and possibly the fs params are such > >>>that the known warning occurs..? I'd defer to the btrfs folks on how > >>>best to check that, so long as it doesn't affect other fs'. > >>> > >>The above trace is independent of any Btrfs parameters. Its just that it was > >>easily reproducible on ppc64 with the subpagesize-blocksize patchset > >>applied. So IMHO disabling call trace check when testing Btrfs filesystem is > >>the way to go. But again, as you said, we can wait for comments from other > >>Btrfs devs. > > > >As a general principle, we don't disable warnings/errors in tests > >just to make tests pass. The bug in the code being tested should be > >fixed so the warning/error is not generated. If you do not want > >to see the error, then expung the test from your > >subpagesize-blocksize test runs. > > > > The same problem would happen if you did echo 3> > /proc/sys/vm/drop_caches right after dropping writes before doing > the unmount. Nice, you have multiple ways of reproducing the problem.... > The sub page blocksize stuff is just exposing the race > and thus causing this warning to happen. The warning has nothing to > do with the test, it happens after drop writes so I think it's fine > to ignore it. Maybe a different mechanism could be put into place > to say "hey ignore dmesg for this part" or something like that. > > That all being said, it is a little weird that the sub page > blocksize stuff hits this so consistently, I wonder why things are > getting evicted that quickly. Thanks, Josef, you've just explained exactly why silencing/ignoring dmesg is the wrong thing to do. The test is exposing some problem (even a known problem) via a behaviour that is not understood. And when I hear "there's a race condition, and this test hits it easily" I see a test that can be used to verify that the problem has been fixed. i.e. we don't silence warnings just because a test triggers it easily; having a test fail is a clear reminder that either: a) there is a problem that needs fixing; or b) there is a warning being emitted under normal operating situations that users are going to notice and report. And if users can see it, then see a). Cheers, Dave. -- Dave Chinner david@xxxxxxxxxxxxx -- To unsubscribe from this list: send the line "unsubscribe fstests" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
