On 12/6/2017 12:07 AM, Theodore Ts'o wrote:
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
OK, I will check it.
Thanks for informing the way to test.
- 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
--
Thanks,
Byungchul
