On Tue, May 07, 2024 at 03:20:39PM -0700, Darrick J. Wong wrote: > On Mon, May 06, 2024 at 09:47:33AM +0530, Chandan Babu R wrote: > > Hi, > > > > Executing xfs/708 on xfs-linux's current for-next (commit > > 25576c5420e61dea4c2b52942460f2221b8e46e8) causes the following hung task > > timeout to be printed, > > Do you have any odd kasan/lockdep features enabled? Never mind that. I /think/ I figured this out -- the xfarray_sort_scan function can return an error if a fatal signal has been received. Unfortunately the callsites all assume that an error return means that si->folio doesn't point at a folio, so they don't bother calling xfarray_sort_scan_done, so we leak a locked page and that's what the folio_wait_bit_common is stuck on. --D > > [ 6328.415475] run fstests xfs/708 at 2024-05-04 15:35:29 > > [ 6328.964720] XFS (loop16): EXPERIMENTAL online scrub feature in use. Use at your own risk! > > [ 6329.258411] XFS (loop5): Mounting V5 Filesystem e96086f0-a2f9-4424-a1d5-c75d53d823be > > [ 6329.265694] XFS (loop5): Ending clean mount > > [ 6329.267899] XFS (loop5): Quotacheck needed: Please wait. > > [ 6329.280141] XFS (loop5): Quotacheck: Done. > > [ 6329.291589] XFS (loop5): EXPERIMENTAL online scrub feature in use. Use at your own risk! > > [ 7865.474615] INFO: task xfs_io:143725 blocked for more than 122 seconds. > > [ 7865.476744] Not tainted 6.9.0-rc4+ #1 > > [ 7865.478109] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > > [ 7865.479827] task:xfs_io state:D stack:0 pid:143725 tgid:143725 ppid:117661 flags:0x00004006 > > [ 7865.481685] Call Trace: > > [ 7865.482761] <TASK> > > [ 7865.483801] __schedule+0x69c/0x17a0 > > [ 7865.485053] ? __pfx___schedule+0x10/0x10 > > [ 7865.486372] ? _raw_spin_lock_irq+0x8b/0xe0 > > [ 7865.487576] schedule+0x74/0x1b0 > > [ 7865.488749] io_schedule+0xc4/0x140 > > [ 7865.489943] folio_wait_bit_common+0x254/0x650 > > Huh. So we're evicting a shmem inode and it's stuck waiting for a > folio? > > > [ 7865.491308] ? __pfx_folio_wait_bit_common+0x10/0x10 > > [ 7865.492596] ? __pfx_find_get_entries+0x10/0x10 > > [ 7865.493875] ? __pfx_wake_page_function+0x10/0x10 > > [ 7865.495222] ? lru_add_drain_cpu+0x1dd/0x2e0 > > [ 7865.496399] shmem_undo_range+0x9d5/0xb40 > > Can you addr2line this to figure out what exactly shmem_undo_range was > trying to do? Is memory tight here? > > > [ 7865.497558] ? __pfx_shmem_undo_range+0x10/0x10 > > [ 7865.498757] ? poison_slab_object+0x106/0x190 > > [ 7865.500003] ? kfree+0xfc/0x300 > > [ 7865.501107] ? xfs_scrub_metadata+0x84e/0xdf0 [xfs] > > [ 7865.502466] ? xfs_ioc_scrub_metadata+0x9e/0x120 [xfs] > > [ 7865.503900] ? wakeup_preempt+0x161/0x260 > > [ 7865.505105] ? _raw_spin_lock+0x85/0xe0 > > [ 7865.506214] ? __pfx__raw_spin_lock+0x10/0x10 > > [ 7865.507334] ? _raw_spin_lock+0x85/0xe0 > > [ 7865.508410] ? __pfx__raw_spin_lock+0x10/0x10 > > [ 7865.509524] ? __pfx__raw_spin_lock+0x10/0x10 > > [ 7865.510638] ? _raw_spin_lock+0x85/0xe0 > > [ 7865.511677] ? kasan_save_track+0x14/0x30 > > [ 7865.512754] ? kasan_save_free_info+0x3b/0x60 > > [ 7865.513872] ? poison_slab_object+0x106/0x190 > > [ 7865.515084] ? xfs_scrub_metadata+0x84e/0xdf0 [xfs] > > [ 7865.516326] ? kfree+0xfc/0x300 > > [ 7865.517302] ? xfs_scrub_metadata+0x84e/0xdf0 [xfs] > > [ 7865.518578] shmem_evict_inode+0x322/0x8f0 > > [ 7865.519626] ? __inode_wait_for_writeback+0xcf/0x1a0 > > [ 7865.520801] ? __pfx_shmem_evict_inode+0x10/0x10 > > [ 7865.521951] ? __pfx___inode_wait_for_writeback+0x10/0x10 > > [ 7865.523136] ? __pfx_wake_bit_function+0x10/0x10 > > [ 7865.524207] ? __pfx__raw_spin_lock+0x10/0x10 > > [ 7865.525243] ? __pfx__raw_spin_lock+0x10/0x10 > > [ 7865.526236] evict+0x24e/0x560 > > [ 7865.527091] __dentry_kill+0x17d/0x4d0 > > [ 7865.528107] dput+0x263/0x430 > > [ 7865.529006] __fput+0x2fc/0xaa0 > > [ 7865.529927] task_work_run+0x132/0x210 > > [ 7865.530891] ? __pfx_task_work_run+0x10/0x10 > > [ 7865.531910] get_signal+0x1a8/0x1910 > > [ 7865.532917] ? kasan_save_track+0x14/0x30 > > [ 7865.533885] ? kasan_save_free_info+0x3b/0x60 > > [ 7865.534880] ? __pfx_get_signal+0x10/0x10 > > [ 7865.535793] ? poison_slab_object+0xbe/0x190 > > [ 7865.536784] ? __pfx_ioctl_has_perm.constprop.0.isra.0+0x10/0x10 > > [ 7865.537952] arch_do_signal_or_restart+0x7b/0x2f0 > > [ 7865.539014] ? __pfx_arch_do_signal_or_restart+0x10/0x10 > > [ 7865.540091] ? restore_fpregs_from_fpstate+0x96/0x150 > > [ 7865.541123] ? __pfx_restore_fpregs_from_fpstate+0x10/0x10 > > [ 7865.542209] ? security_file_ioctl+0x51/0x90 > > [ 7865.543153] syscall_exit_to_user_mode+0x1c2/0x200 > > [ 7865.544165] do_syscall_64+0x72/0x170 > > [ 7865.545033] entry_SYSCALL_64_after_hwframe+0x76/0x7e > > [ 7865.546095] RIP: 0033:0x7f4d18c3ec6b > > [ 7865.547033] RSP: 002b:00007ffe2056f878 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 > > [ 7865.548407] RAX: fffffffffffffffc RBX: 0000000000000001 RCX: 00007f4d18c3ec6b > > [ 7865.549757] RDX: 00007ffe2056f880 RSI: 00000000c040583c RDI: 0000000000000003 > > [ 7865.551047] RBP: 000000001bd46c40 R08: 0000000000000002 R09: 0000000000000000 > > [ 7865.552317] R10: 00007f4d18d9eac0 R11: 0000000000000246 R12: 0000000000000000 > > [ 7865.553619] R13: 000000001bd46bc0 R14: 000000001bd46520 R15: 0000000000000004 > > [ 7865.555005] </TASK> > > > > The following is the contents from fstests config file, > > > > FSTYP=xfs > > TEST_DIR=/media/test > > SCRATCH_MNT=/media/scratch > > DUMP_CORRUPT_FS=1 > > SOAK_DURATION=1320 > > > > TEST_DEV=/dev/loop16 > > SCRATCH_DEV_POOL="/dev/loop5 /dev/loop6 /dev/loop7 /dev/loop8 /dev/loop9 /dev/loop10 /dev/loop11 /dev/loop12" > > Huh. Does the problem go away if the loop devices are directio=1 ? > > --D > > > MKFS_OPTIONS='-f -m reflink=1,rmapbt=1, -i sparse=1,' > > MOUNT_OPTIONS='-o usrquota,grpquota,prjquota' > > TEST_FS_MOUNT_OPTS="$TEST_FS_MOUNT_OPTS -o usrquota,grpquota,prjquota" > > USE_EXTERNAL=no > > LOGWRITES_DEV=/dev/loop15 > > > > -- > > Chandan >
