On Tue, Dec 05, 2017 at 02:16:45PM +0900, Byungchul Park wrote: > > Hello, > > I believe that the commit e319e1fbd9d42 "block, locking/lockdep: Assign > a lock_class per gendisk used for wait_for_completion()" solved the > false positive. > > Could you tell me if it doesn't handle it, with the report? Then, I > will follow up and try to solve it. No, it doesn't handle it. And there was some discussion in the linked thread on the xfs mailing list that seemed to indicate that it was not a complete fix. The following is a run of shared/298[1] using the dev branch of ext4.git on kernel.org. The kvm-xfstests appliance can be found at [2], with instructions on how to use it at [3]. [1] https://git.kernel.org/pub/scm/fs/xfs/xfstests-dev.git/tree/tests/shared/298 [2] https://www.kernel.org/pub/linux/kernel/people/tytso/kvm-xfstests [3] https://github.com/tytso/xfstests-bld/blob/master/Documentation/kvm-quickstart.md - Ted KERNEL: kernel 4.15.0-rc2-xfstests-00002-ge243560f12d7 #439 SMP Tue Dec 5 09:30:08 EST 2017 i686 FSTESTVER: e2fsprogs v1.43.6-85-g7595699d0 (Wed, 6 Sep 2017 22:04:14 -0400) FSTESTVER: fio fio-3.2 (Fri, 3 Nov 2017 15:23:49 -0600) FSTESTVER: quota 4d81e8b (Mon, 16 Oct 2017 09:42:44 +0200) FSTESTVER: stress-ng 977ae35 (Wed, 6 Sep 2017 23:45:03 -0400) FSTESTVER: xfsprogs v4.14.0-rc2-1-g19ca9b0b (Mon, 27 Nov 2017 10:56:21 -0600) FSTESTVER: xfstests-bld 0b27af9 (Tue, 28 Nov 2017 16:28:51 -0500) FSTESTVER: xfstests linux-v3.8-1797-g4f1eaa02 (Tue, 28 Nov 2017 15:49:06 -0500) FSTESTCFG: "4k" FSTESTSET: "shared/298" FSTESTEXC: "" FSTESTOPT: "aex" MNTOPTS: "" CPUS: "2" MEM: "2008.27" total used free shared buff/cache available Mem: 2008 29 1926 8 51 1904 Swap: 0 0 0 BEGIN TEST 4k (1 test): Ext4 4k block Tue Dec 5 10:01:43 EST 2017 DEVICE: /dev/vdd EXT_MKFS_OPTIONS: -b 4096 EXT_MOUNT_OPTIONS: -o block_validity FSTYP -- ext4 PLATFORM -- Linux/i686 kvm-xfstests 4.15.0-rc2-xfstests-00002-ge243560f12d7 MKFS_OPTIONS -- -b 4096 /dev/vdc MOUNT_OPTIONS -- -o acl,user_xattr -o block_validity /dev/vdc /vdc shared/298 7s ... [10:01:45][ 11.697717] run fstests shared/298 at 2017-12-05 10:01:45 [ 15.151631] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 16.183394] [ 16.184011] ====================================================== [ 16.186040] WARNING: possible circular locking dependency detected [ 16.187693] 4.15.0-rc2-xfstests-00002-ge243560f12d7 #439 Not tainted [ 16.189044] ------------------------------------------------------ [ 16.190198] ext4lazyinit/648 is trying to acquire lock: [ 16.191201] ((gendisk_completion)1 << part_shift(NUMA_NO_NODE)){+.+.}, at: [<8a1ebe9d>] wait_for_completion_io+0x12/0x20 [ 16.193226] [ 16.193226] but task is already holding lock: [ 16.194316] (&meta_group_info[i]->alloc_sem){++++}, at: [<6495768c>] ext4_init_inode_table+0xb3/0x340 [ 16.196090] [ 16.196090] which lock already depends on the new lock. [ 16.196090] [ 16.197603] [ 16.197603] the existing dependency chain (in reverse order) is: [ 16.198989] [ 16.198989] -> #2 (&meta_group_info[i]->alloc_sem){++++}: [ 16.200270] lock_acquire+0x7d/0x1a0 [ 16.201067] down_read+0x34/0x90 [ 16.201783] __ext4_new_inode+0xcc2/0x14b0 [ 16.202853] ext4_create+0x8f/0x170 [ 16.203613] lookup_open+0x284/0x600 [ 16.204409] path_openat+0x33a/0xa40 [ 16.205230] do_filp_open+0x5e/0xb0 [ 16.205990] do_sys_open+0x1a4/0x230 [ 16.206766] SyS_open+0x1d/0x20 [ 16.207459] do_fast_syscall_32+0x85/0x2d0 [ 16.208326] entry_SYSENTER_32+0x4c/0x7b [ 16.209161] [ 16.209161] -> #1 (jbd2_handle){++++}: [ 16.210142] page_address+0x69/0xd0 [ 16.211048] copy_page_to_iter+0x32/0x3e0 [ 16.212524] generic_file_buffered_read+0x308/0x760 [ 16.214279] generic_file_read_iter+0x15e/0x1f0 [ 16.215957] ext4_file_read_iter+0x43/0xe0 [ 16.217478] [ 16.217478] -> #0 ((gendisk_completion)1 << part_shift(NUMA_NO_NODE)){+.+.}: [ 16.220266] __lock_acquire+0x1235/0x1300 [ 16.221758] lock_acquire+0x7d/0x1a0 [ 16.223102] wait_for_common_io.constprop.0+0x3e/0x150 [ 16.224893] wait_for_completion_io+0x12/0x20 [ 16.225793] submit_bio_wait+0x6f/0x80 [ 16.226574] blkdev_issue_zeroout+0xa6/0x1e0 [ 16.227445] ext4_init_inode_table+0x173/0x340 [ 16.228347] ext4_lazyinit_thread+0x263/0x320 [ 16.229233] kthread+0x12e/0x150 [ 16.229919] ret_from_fork+0x19/0x24 [ 16.230665] [ 16.230665] other info that might help us debug this: [ 16.230665] [ 16.232104] Chain exists of: [ 16.232104] (gendisk_completion)1 << part_shift(NUMA_NO_NODE) --> jbd2_handle --> &meta_group_info[i]->alloc_sem [ 16.232104] [ 16.234726] Possible unsafe locking scenario: [ 16.234726] [ 16.236617] CPU0 CPU1 [ 16.238109] ---- ---- [ 16.239598] lock(&meta_group_info[i]->alloc_sem); [ 16.241208] lock(jbd2_handle); [ 16.243061] lock(&meta_group_info[i]->alloc_sem); [ 16.245496] lock((gendisk_completion)1 << part_shift(NUMA_NO_NODE)); [ 16.247642] [ 16.247642] *** DEADLOCK *** [ 16.247642] [ 16.249587] 4 locks held by ext4lazyinit/648: [ 16.250970] #0: (&type->s_umount_key#26){++++}, at: [<8c13b129>] ext4_lazyinit_thread+0x6b/0x320 [ 16.252630] #1: (sb_writers#3){.+.+}, at: [<4cd23367>] ext4_lazyinit_thread+0x14f/0x320 [ 16.254109] #2: (jbd2_handle){++++}, at: [<327c6fca>] start_this_handle+0x303/0x790 [ 16.256235] #3: (&meta_group_info[i]->alloc_sem){++++}, at: [<6495768c>] ext4_init_inode_table+0xb3/0x340 [ 16.259407] [ 16.259407] stack backtrace: [ 16.260839] CPU: 0 PID: 648 Comm: ext4lazyinit Not tainted 4.15.0-rc2-xfstests-00002-ge243560f12d7 #439 [ 16.263789] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014 [ 16.266438] Call Trace: [ 16.267068] dump_stack+0x7d/0xb2 [ 16.267685] print_circular_bug+0x1d2/0x340 [ 16.268453] check_prev_add+0x310/0x6b0 [ 16.269161] ? kvm_sched_clock_read+0x1f/0x40 [ 16.269961] ? sched_clock+0x9/0x10 [ 16.270607] __lock_acquire+0x1235/0x1300 [ 16.271345] ? copy_trace+0x90/0x90 [ 16.272131] lock_acquire+0x7d/0x1a0 [ 16.273269] ? wait_for_completion_io+0x12/0x20 [ 16.274777] wait_for_common_io.constprop.0+0x3e/0x150 [ 16.276452] ? wait_for_completion_io+0x12/0x20 [ 16.277933] ? lockdep_init_map+0x12/0x20 [ 16.279246] wait_for_completion_io+0x12/0x20 [ 16.280682] submit_bio_wait+0x6f/0x80 [ 16.281910] ? _cond_resched+0x17/0x30 [ 16.283150] ? blkdev_issue_zeroout+0x91/0x1e0 [ 16.284576] blkdev_issue_zeroout+0xa6/0x1e0 [ 16.285976] ext4_init_inode_table+0x173/0x340 [ 16.287434] ext4_lazyinit_thread+0x263/0x320 [ 16.288858] kthread+0x12e/0x150 [ 16.289936] ? ext4_unregister_li_request.isra.89+0x60/0x60 [ 16.291770] ? __kthread_create_on_node+0x170/0x170 [ 16.293370] ret_from_fork+0x19/0x24 [10:01:55] 10s [ 21.970265] EXT4-fs (vdd): mounted filesystem with ordered data mode. Opts: acl,user_xattr,block_validity _check_dmesg: something found in dmesg (see /results/ext4/results-4k/shared/298.dmesg) Ran: shared/298 Failures: shared/298 Failed 1 of 1 tests Xunit report: /results/ext4/results-4k/result.xml [ 22.876380] runtests.sh (230): drop_caches: 3 total used free shared buff/cache available Mem: 2008 35 1939 8 33 1899 Swap: 0 0 0 END TEST: Ext4 4k block Tue Dec 5 10:01:56 EST 2017
