[BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Chandan Babu R]

Hi,

Executing fstests' recoveryloop test group on XFS on a next-20240102 kernel
sometimes causes the following hung task report to be printed on the console,

[  190.284008] XFS (loop5): Mounting V5 Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f
[  190.291326] XFS (loop5): Ending clean mount
[  190.301165] XFS (loop5): User initiated shutdown received.
[  190.302808] XFS (loop5): Log I/O Error (0x6) detected at xfs_fs_goingdown+0x93/0xd0 [xfs] (fs/xfs/xfs_fsops.c:458).  Shutting down filesystem.
[  190.308555] XFS (loop5): Please unmount the filesystem and rectify the problem(s)
[  190.369214] XFS (loop5): Unmounting Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f
[  190.404932] XFS (loop5): Mounting V5 Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f
[  190.419673] XFS (loop5): Ending clean mount
[  190.429301] XFS (loop5): User initiated shutdown received.
[  190.431178] XFS (loop5): Log I/O Error (0x6) detected at xfs_fs_goingdown+0x93/0xd0 [xfs] (fs/xfs/xfs_fsops.c:458).  Shutting down filesystem.
[  190.437622] XFS (loop5): Please unmount the filesystem and rectify the problem(s)
[  369.717531] INFO: task fsstress:18269 blocked for more than 122 seconds.
[  369.724323]       Not tainted 6.7.0-rc8-next-20240102+ #1
[  369.727077] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  369.730717] task:fsstress        state:D stack:0     pid:18269 tgid:18269 ppid:1      flags:0x00004006
[  369.734945] Call Trace:
[  369.736468]  <TASK>
[  369.737768]  __schedule+0x237/0x720
[  369.739593]  schedule+0x30/0xd0
[  369.741310]  schedule_preempt_disabled+0x15/0x30
[  369.743555]  rwsem_down_read_slowpath+0x240/0x4d0
[  369.745634]  ? xlog_cil_force_seq+0x200/0x270 [xfs]
[  369.747859]  down_read+0x49/0xa0
[  369.749436]  super_lock+0xf1/0x120
[  369.751008]  ? srso_alias_return_thunk+0x5/0xfbef5
[  369.753530]  ? srso_alias_return_thunk+0x5/0xfbef5
[  369.755865]  ? xfs_log_force+0x20c/0x230 [xfs]
[  369.758147]  ? srso_alias_return_thunk+0x5/0xfbef5
[  369.760391]  ? __pfx_sync_fs_one_sb+0x10/0x10
[  369.762516]  iterate_supers+0x5a/0xe0
[  369.764403]  ksys_sync+0x64/0xb0
[  369.766104]  __do_sys_sync+0xe/0x20
[  369.767856]  do_syscall_64+0x6c/0x170
[  369.769684]  entry_SYSCALL_64_after_hwframe+0x6c/0x74
[  369.771975] RIP: 0033:0x7f2b24e3ed5b
[  369.773732] RSP: 002b:00007fff7183b058 EFLAGS: 00000202 ORIG_RAX: 00000000000000a2
[  369.777022] RAX: ffffffffffffffda RBX: 000000000007a120 RCX: 00007f2b24e3ed5b
[  369.780177] RDX: 0000000000000000 RSI: 00000000796b9c69 RDI: 0000000000000000
[  369.783356] RBP: 028f5c28f5c28f5c R08: 0000000000000008 R09: 0000000000001010
[  369.787096] R10: 00007f2b24e15228 R11: 0000000000000202 R12: 0000000000000000
[  369.790256] R13: 8f5c28f5c28f5c29 R14: 00000000004034c0 R15: 00007f2b250156c0
[  369.793499]  </TASK>

The sb->s_umount semaphore was owned by a task executing systemd-coredump. The
systemd-coredump task was busy executing shrink_dcache_parent() as shown below,

systemd-coredum   18274 [001] 85214.162988:                probe:d_walk: (ffffffff88218580) parent_path="/" fs_type="tmpfs"
        ffffffff88218581 d_walk+0x1 ([kernel.kallsyms])
        ffffffff8821a8e2 shrink_dcache_parent+0x52 ([kernel.kallsyms])
        ffffffff8821ac9b shrink_dcache_for_umount+0x3b ([kernel.kallsyms])
        ffffffff881f9c10 generic_shutdown_super+0x20 ([kernel.kallsyms])
        ffffffff881fa667 kill_litter_super+0x27 ([kernel.kallsyms])
        ffffffff881fb3b5 deactivate_locked_super+0x35 ([kernel.kallsyms])
        ffffffff88226d30 cleanup_mnt+0x100 ([kernel.kallsyms])
        ffffffff87eef72c task_work_run+0x5c ([kernel.kallsyms])
        ffffffff87ec9763 do_exit+0x2b3 ([kernel.kallsyms])
        ffffffff87ec9b90 do_group_exit+0x30 ([kernel.kallsyms])
        ffffffff87ec9c38 [unknown] ([kernel.kallsyms])
        ffffffff88b9930c do_syscall_64+0x6c ([kernel.kallsyms])
        ffffffff88c000e5 entry_SYSCALL_64+0xa5 ([kernel.kallsyms])

Trying to obtain more debug data via perf caused the 'perf record' task to
indefinitely enter into the TASK_UNINTERRUPTIBLE state. I will try to recreate
the bug and debug it further.

The following is the fstests configuration that was used.
  FSTYP=xfs
  TEST_DEV=/dev/loop7
  TEST_DIR=/media/test
  SCRATCH_DEV=/dev/loop5
  SCRATCH_MNT=/media/scratch
  MKFS_OPTIONS='-f -m reflink=1,rmapbt=1, -i sparse=1,'
  MOUNT_OPTIONS='-o usrquota,grpquota,prjquota'
  LOGWRITES_DEV=/dev/loop6
  SOAK_DURATION=9900

The recoveryloop group of tests can then be executed by,
$ ./check -g recoveryloop

-- 
Chandan

Re: [BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Darrick J. Wong]

On Wed, Jan 03, 2024 at 12:12:12PM +0530, Chandan Babu R wrote:
> Hi,
> 
> Executing fstests' recoveryloop test group on XFS on a next-20240102 kernel
> sometimes causes the following hung task report to be printed on the console,
> 
> [  190.284008] XFS (loop5): Mounting V5 Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f

Huh.  Which test is this, specifically?  And is this easily
reproduceable and new?  Or hard to re-trigger and who knows how long
it's been this way?

> [  190.291326] XFS (loop5): Ending clean mount
> [  190.301165] XFS (loop5): User initiated shutdown received.
> [  190.302808] XFS (loop5): Log I/O Error (0x6) detected at xfs_fs_goingdown+0x93/0xd0 [xfs] (fs/xfs/xfs_fsops.c:458).  Shutting down filesystem.
> [  190.308555] XFS (loop5): Please unmount the filesystem and rectify the problem(s)
> [  190.369214] XFS (loop5): Unmounting Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f
> [  190.404932] XFS (loop5): Mounting V5 Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f
> [  190.419673] XFS (loop5): Ending clean mount
> [  190.429301] XFS (loop5): User initiated shutdown received.
> [  190.431178] XFS (loop5): Log I/O Error (0x6) detected at xfs_fs_goingdown+0x93/0xd0 [xfs] (fs/xfs/xfs_fsops.c:458).  Shutting down filesystem.
> [  190.437622] XFS (loop5): Please unmount the filesystem and rectify the problem(s)
> [  369.717531] INFO: task fsstress:18269 blocked for more than 122 seconds.
> [  369.724323]       Not tainted 6.7.0-rc8-next-20240102+ #1
> [  369.727077] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [  369.730717] task:fsstress        state:D stack:0     pid:18269 tgid:18269 ppid:1      flags:0x00004006
> [  369.734945] Call Trace:
> [  369.736468]  <TASK>
> [  369.737768]  __schedule+0x237/0x720
> [  369.739593]  schedule+0x30/0xd0
> [  369.741310]  schedule_preempt_disabled+0x15/0x30
> [  369.743555]  rwsem_down_read_slowpath+0x240/0x4d0
> [  369.745634]  ? xlog_cil_force_seq+0x200/0x270 [xfs]
> [  369.747859]  down_read+0x49/0xa0
> [  369.749436]  super_lock+0xf1/0x120
> [  369.751008]  ? srso_alias_return_thunk+0x5/0xfbef5
> [  369.753530]  ? srso_alias_return_thunk+0x5/0xfbef5
> [  369.755865]  ? xfs_log_force+0x20c/0x230 [xfs]
> [  369.758147]  ? srso_alias_return_thunk+0x5/0xfbef5
> [  369.760391]  ? __pfx_sync_fs_one_sb+0x10/0x10
> [  369.762516]  iterate_supers+0x5a/0xe0
> [  369.764403]  ksys_sync+0x64/0xb0
> [  369.766104]  __do_sys_sync+0xe/0x20
> [  369.767856]  do_syscall_64+0x6c/0x170
> [  369.769684]  entry_SYSCALL_64_after_hwframe+0x6c/0x74
> [  369.771975] RIP: 0033:0x7f2b24e3ed5b
> [  369.773732] RSP: 002b:00007fff7183b058 EFLAGS: 00000202 ORIG_RAX: 00000000000000a2
> [  369.777022] RAX: ffffffffffffffda RBX: 000000000007a120 RCX: 00007f2b24e3ed5b
> [  369.780177] RDX: 0000000000000000 RSI: 00000000796b9c69 RDI: 0000000000000000
> [  369.783356] RBP: 028f5c28f5c28f5c R08: 0000000000000008 R09: 0000000000001010
> [  369.787096] R10: 00007f2b24e15228 R11: 0000000000000202 R12: 0000000000000000
> [  369.790256] R13: 8f5c28f5c28f5c29 R14: 00000000004034c0 R15: 00007f2b250156c0
> [  369.793499]  </TASK>
> 
> The sb->s_umount semaphore was owned by a task executing systemd-coredump. The
> systemd-coredump task was busy executing shrink_dcache_parent() as shown below,
> 
> systemd-coredum   18274 [001] 85214.162988:                probe:d_walk: (ffffffff88218580) parent_path="/" fs_type="tmpfs"
>         ffffffff88218581 d_walk+0x1 ([kernel.kallsyms])
>         ffffffff8821a8e2 shrink_dcache_parent+0x52 ([kernel.kallsyms])
>         ffffffff8821ac9b shrink_dcache_for_umount+0x3b ([kernel.kallsyms])
>         ffffffff881f9c10 generic_shutdown_super+0x20 ([kernel.kallsyms])
>         ffffffff881fa667 kill_litter_super+0x27 ([kernel.kallsyms])
>         ffffffff881fb3b5 deactivate_locked_super+0x35 ([kernel.kallsyms])
>         ffffffff88226d30 cleanup_mnt+0x100 ([kernel.kallsyms])
>         ffffffff87eef72c task_work_run+0x5c ([kernel.kallsyms])
>         ffffffff87ec9763 do_exit+0x2b3 ([kernel.kallsyms])
>         ffffffff87ec9b90 do_group_exit+0x30 ([kernel.kallsyms])
>         ffffffff87ec9c38 [unknown] ([kernel.kallsyms])
>         ffffffff88b9930c do_syscall_64+0x6c ([kernel.kallsyms])
>         ffffffff88c000e5 entry_SYSCALL_64+0xa5 ([kernel.kallsyms])

Curious.  I wonder if systemd-coredump@ is tearing down its private
/tmp or something?  I've never had systemd coredump installed on a test
vm.

> Trying to obtain more debug data via perf caused the 'perf record' task to
> indefinitely enter into the TASK_UNINTERRUPTIBLE state. I will try to recreate
> the bug and debug it further.

Doh. :(

--D
> 
> The following is the fstests configuration that was used.
>   FSTYP=xfs
>   TEST_DEV=/dev/loop7
>   TEST_DIR=/media/test
>   SCRATCH_DEV=/dev/loop5
>   SCRATCH_MNT=/media/scratch
>   MKFS_OPTIONS='-f -m reflink=1,rmapbt=1, -i sparse=1,'
>   MOUNT_OPTIONS='-o usrquota,grpquota,prjquota'
>   LOGWRITES_DEV=/dev/loop6
>   SOAK_DURATION=9900
> 
> The recoveryloop group of tests can then be executed by,
> $ ./check -g recoveryloop
> 
> -- 
> Chandan
> 

Re: [BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Chandan Babu R]

On Wed, Jan 03, 2024 at 08:34:20 PM -0800, Darrick J. Wong wrote:
> On Wed, Jan 03, 2024 at 12:12:12PM +0530, Chandan Babu R wrote:
>> Hi,
>> 
>> Executing fstests' recoveryloop test group on XFS on a next-20240102 kernel
>> sometimes causes the following hung task report to be printed on the console,
>> 
>> [  190.284008] XFS (loop5): Mounting V5 Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f
>
> Huh.  Which test is this, specifically?  And is this easily
> reproduceable and new?  Or hard to re-trigger and who knows how long
> it's been this way?
>

The bug was recreated for the first time when using the next-20231222
kernel. IIRC, it was generic/475 which caused the bug at that time. The kernel
was accidently built without debug info and hence I couldn't do much to find
the root cause.

However, with the next-20240102 kernel, it was generic/388 test which
recreated the bug.

With both kernels, one iteration across the recoveryloop group of tests was
sufficient to recreate the bug. I am hoping that this stays true for my future
attempts.

>> [  190.291326] XFS (loop5): Ending clean mount
>> [  190.301165] XFS (loop5): User initiated shutdown received.
>> [ 190.302808] XFS (loop5): Log I/O Error (0x6) detected at
>> xfs_fs_goingdown+0x93/0xd0 [xfs] (fs/xfs/xfs_fsops.c:458).  Shutting
>> down filesystem.
>> [  190.308555] XFS (loop5): Please unmount the filesystem and rectify the problem(s)
>> [  190.369214] XFS (loop5): Unmounting Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f
>> [  190.404932] XFS (loop5): Mounting V5 Filesystem 43ed2bb9-5b51-4bdc-af8d-af2ca7001f3f
>> [  190.419673] XFS (loop5): Ending clean mount
>> [  190.429301] XFS (loop5): User initiated shutdown received.
>> [ 190.431178] XFS (loop5): Log I/O Error (0x6) detected at
>> xfs_fs_goingdown+0x93/0xd0 [xfs] (fs/xfs/xfs_fsops.c:458).  Shutting
>> down filesystem.
>> [  190.437622] XFS (loop5): Please unmount the filesystem and rectify the problem(s)
>> [  369.717531] INFO: task fsstress:18269 blocked for more than 122 seconds.
>> [  369.724323]       Not tainted 6.7.0-rc8-next-20240102+ #1
>> [  369.727077] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> [  369.730717] task:fsstress        state:D stack:0     pid:18269 tgid:18269 ppid:1      flags:0x00004006
>> [  369.734945] Call Trace:
>> [  369.736468]  <TASK>
>> [  369.737768]  __schedule+0x237/0x720
>> [  369.739593]  schedule+0x30/0xd0
>> [  369.741310]  schedule_preempt_disabled+0x15/0x30
>> [  369.743555]  rwsem_down_read_slowpath+0x240/0x4d0
>> [  369.745634]  ? xlog_cil_force_seq+0x200/0x270 [xfs]
>> [  369.747859]  down_read+0x49/0xa0
>> [  369.749436]  super_lock+0xf1/0x120
>> [  369.751008]  ? srso_alias_return_thunk+0x5/0xfbef5
>> [  369.753530]  ? srso_alias_return_thunk+0x5/0xfbef5
>> [  369.755865]  ? xfs_log_force+0x20c/0x230 [xfs]
>> [  369.758147]  ? srso_alias_return_thunk+0x5/0xfbef5
>> [  369.760391]  ? __pfx_sync_fs_one_sb+0x10/0x10
>> [  369.762516]  iterate_supers+0x5a/0xe0
>> [  369.764403]  ksys_sync+0x64/0xb0
>> [  369.766104]  __do_sys_sync+0xe/0x20
>> [  369.767856]  do_syscall_64+0x6c/0x170
>> [  369.769684]  entry_SYSCALL_64_after_hwframe+0x6c/0x74
>> [  369.771975] RIP: 0033:0x7f2b24e3ed5b
>> [  369.773732] RSP: 002b:00007fff7183b058 EFLAGS: 00000202 ORIG_RAX: 00000000000000a2
>> [  369.777022] RAX: ffffffffffffffda RBX: 000000000007a120 RCX: 00007f2b24e3ed5b
>> [  369.780177] RDX: 0000000000000000 RSI: 00000000796b9c69 RDI: 0000000000000000
>> [  369.783356] RBP: 028f5c28f5c28f5c R08: 0000000000000008 R09: 0000000000001010
>> [  369.787096] R10: 00007f2b24e15228 R11: 0000000000000202 R12: 0000000000000000
>> [  369.790256] R13: 8f5c28f5c28f5c29 R14: 00000000004034c0 R15: 00007f2b250156c0
>> [  369.793499]  </TASK>
>> 
>> The sb->s_umount semaphore was owned by a task executing systemd-coredump. The
>> systemd-coredump task was busy executing shrink_dcache_parent() as shown below,
>> 
>> systemd-coredum   18274 [001] 85214.162988:                probe:d_walk: (ffffffff88218580) parent_path="/" fs_type="tmpfs"
>>         ffffffff88218581 d_walk+0x1 ([kernel.kallsyms])
>>         ffffffff8821a8e2 shrink_dcache_parent+0x52 ([kernel.kallsyms])
>>         ffffffff8821ac9b shrink_dcache_for_umount+0x3b ([kernel.kallsyms])
>>         ffffffff881f9c10 generic_shutdown_super+0x20 ([kernel.kallsyms])
>>         ffffffff881fa667 kill_litter_super+0x27 ([kernel.kallsyms])
>>         ffffffff881fb3b5 deactivate_locked_super+0x35 ([kernel.kallsyms])
>>         ffffffff88226d30 cleanup_mnt+0x100 ([kernel.kallsyms])
>>         ffffffff87eef72c task_work_run+0x5c ([kernel.kallsyms])
>>         ffffffff87ec9763 do_exit+0x2b3 ([kernel.kallsyms])
>>         ffffffff87ec9b90 do_group_exit+0x30 ([kernel.kallsyms])
>>         ffffffff87ec9c38 [unknown] ([kernel.kallsyms])
>>         ffffffff88b9930c do_syscall_64+0x6c ([kernel.kallsyms])
>>         ffffffff88c000e5 entry_SYSCALL_64+0xa5 ([kernel.kallsyms])
>
> Curious.  I wonder if systemd-coredump@ is tearing down its private
> /tmp or something?  I've never had systemd coredump installed on a test
> vm.
>

I have always used Oracle Linux 9 for my testing and hence systemd-coredump
has always been installed and enabled.

>> Trying to obtain more debug data via perf caused the 'perf record' task to
>> indefinitely enter into the TASK_UNINTERRUPTIBLE state. I will try to recreate
>> the bug and debug it further.
>
> Doh. :(
>
> --D
>> 
>> The following is the fstests configuration that was used.
>>   FSTYP=xfs
>>   TEST_DEV=/dev/loop7
>>   TEST_DIR=/media/test
>>   SCRATCH_DEV=/dev/loop5
>>   SCRATCH_MNT=/media/scratch
>>   MKFS_OPTIONS='-f -m reflink=1,rmapbt=1, -i sparse=1,'
>>   MOUNT_OPTIONS='-o usrquota,grpquota,prjquota'
>>   LOGWRITES_DEV=/dev/loop6
>>   SOAK_DURATION=9900
>> 
>> The recoveryloop group of tests can then be executed by,
>> $ ./check -g recoveryloop
>> 

-- 
Chandan

Re: [BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Chandan Babu R]

On Thu, Jan 04, 2024 at 06:40:43 PM +0530, Chandan Babu R wrote:
> On Wed, Jan 03, 2024 at 08:34:20 PM -0800, Darrick J. Wong wrote:
>> On Wed, Jan 03, 2024 at 12:12:12PM +0530, Chandan Babu R wrote:
>>> Hi,
>>> 
>>> Executing fstests' recoveryloop test group on XFS on a next-20240102 kernel
>>> sometimes causes the following hung task report to be printed on the console,
>>> 

Meanwhile, I have executed some more experiments.

The bug can be recreated on a next-20240102 kernel by executing either
generic/388 or generic/475 for a maximum of 10 iterations. I tried to do a git
bisect based on this observation i.e. I would mark a commit as 'good' if the
bug does not get recreated within 10 iterations. This led to the following git
bisect log,

# git bisect log
# bad: [ab0b3e6ef50d305278b1971891cf1d82ab050b35] Add linux-next specific files for 20240102
# good: [33cc938e65a98f1d29d0a18403dbbee050dcad9a] Linux 6.7-rc4
git bisect start 'HEAD' 'v6.7-rc4' 'fs/'
# bad: [ca20194665a58bb541cc9e4dc7abcf96a7c96bd9] Merge branch 'main' of git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net-next.git
git bisect bad ca20194665a58bb541cc9e4dc7abcf96a7c96bd9
# good: [bb986dac9a56f88552418288c87e2223f8f448e3] Merge branch 'for-next' of git://git.kernel.org/pub/scm/linux/kernel/git/riscv/linux.git
git bisect good bb986dac9a56f88552418288c87e2223f8f448e3
# bad: [964c80149d24b33bbddd222edbcc782be6eab841] Merge branch 'linux-next' of git://git.kernel.org/pub/scm/linux/kernel/git/rafael/linux-pm.git
git bisect bad 964c80149d24b33bbddd222edbcc782be6eab841
# good: [da9e5cca7e753dd96e07ae9212f4aeec1b9c68a6] Merge branch 'vfs.all' of git://git.kernel.org/pub/scm/linux/kernel/git/vfs/vfs.git
git bisect good da9e5cca7e753dd96e07ae9212f4aeec1b9c68a6
# bad: [9e02829aa9d2e5f2e080ba0191c36a50a384acf1] Merge branch 'hwmon-next' of git://git.kernel.org/pub/scm/linux/kernel/git/groeck/linux-staging.git
git bisect bad 9e02829aa9d2e5f2e080ba0191c36a50a384acf1
# bad: [3ac3331ea2c1826e3d30276e0a7e7e62fff519a8] Merge branch 'next' of git://git.kernel.org/pub/scm/linux/kernel/git/pci/pci.git
git bisect bad 3ac3331ea2c1826e3d30276e0a7e7e62fff519a8
# bad: [e01e3fb272cf7380dd5d70f52e955ac1122e2184] Merge branch 'for-next' of git://git.kernel.org/pub/scm/linux/kernel/git/printk/linux.git
git bisect bad e01e3fb272cf7380dd5d70f52e955ac1122e2184
# bad: [6d06b73bcd6eee6ca43f429a28e812ef2ad7a4ea] Merge branch 'work.simple_recursive_removal' into for-next
git bisect bad 6d06b73bcd6eee6ca43f429a28e812ef2ad7a4ea
# bad: [119dcc73a9c2df0da002054cdb2296cb32b7cb93] Merge branches 'work.dcache-misc' and 'work.dcache2' into work.dcache
git bisect bad 119dcc73a9c2df0da002054cdb2296cb32b7cb93
# good: [6367b491c17a34b28aece294bddfda1a36ec0377] retain_dentry(): introduce a trimmed-down lockless variant
git bisect good 6367b491c17a34b28aece294bddfda1a36ec0377
# good: [b33c14c8618edfc00bf8963e3b0c8a2b19c9eaa4] Merge branch 'no-rebase-overlayfs' into work.dcache-misc
git bisect good b33c14c8618edfc00bf8963e3b0c8a2b19c9eaa4
# good: [f9453a1ad1fadae29fd7db5ad8ea16f35e737276] Merge branch 'merged-selinux' into work.dcache-misc
git bisect good f9453a1ad1fadae29fd7db5ad8ea16f35e737276
# good: [57851607326a2beef21e67f83f4f53a90df8445a] get rid of DCACHE_GENOCIDE
git bisect good 57851607326a2beef21e67f83f4f53a90df8445a
# good: [ef69f0506d8f3a250ac5baa96746e17ae22c67b5] __d_unalias() doesn't use inode argument
git bisect good ef69f0506d8f3a250ac5baa96746e17ae22c67b5
# first bad commit: [119dcc73a9c2df0da002054cdb2296cb32b7cb93] Merge branches 'work.dcache-misc' and 'work.dcache2' into work.dcache

Looks like the bug is caused by changes that were made in two separate
branches.

I have also confirmed that the bug was not present in the v6.7-rc4 kernel by
executing generic/388 in a loop for 44 times.

I can also confirm that the issue can be recreated on a next-20240118 kernel.

-- 
Chandan

Re: [BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Al Viro]

On Thu, Jan 18, 2024 at 10:59:06AM +0530, Chandan Babu R wrote:
> On Thu, Jan 04, 2024 at 06:40:43 PM +0530, Chandan Babu R wrote:
> > On Wed, Jan 03, 2024 at 08:34:20 PM -0800, Darrick J. Wong wrote:
> >> On Wed, Jan 03, 2024 at 12:12:12PM +0530, Chandan Babu R wrote:
> >>> Hi,
> >>> 
> >>> Executing fstests' recoveryloop test group on XFS on a next-20240102 kernel
> >>> sometimes causes the following hung task report to be printed on the console,
> >>> 
> 
> Meanwhile, I have executed some more experiments.
> 
> The bug can be recreated on a next-20240102 kernel by executing either
> generic/388 or generic/475 for a maximum of 10 iterations. I tried to do a git
> bisect based on this observation i.e. I would mark a commit as 'good' if the
> bug does not get recreated within 10 iterations. This led to the following git
> bisect log,

> # bad: [119dcc73a9c2df0da002054cdb2296cb32b7cb93] Merge branches 'work.dcache-misc' and 'work.dcache2' into work.dcache
> git bisect bad 119dcc73a9c2df0da002054cdb2296cb32b7cb93
> # good: [6367b491c17a34b28aece294bddfda1a36ec0377] retain_dentry(): introduce a trimmed-down lockless variant
> git bisect good 57851607326a2beef21e67f83f4f53a90df8445a
> # good: [ef69f0506d8f3a250ac5baa96746e17ae22c67b5] __d_unalias() doesn't use inode argument

Lovely...  Could you try to do the following:

bisect from 6.7-rc1 to work.dcache-misc; for each of those revisions
	git worktree add ../test HEAD
	cd ../test
	git merge work.dcache2
	build
	test the result
	cd -
	git worktree remove -f ../test
	git bisect {good,bad} accordingly

Re: [BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Chandan Babu R]

On Thu, Jan 18, 2024 at 06:39:30 AM +0000, Al Viro wrote:
> On Thu, Jan 18, 2024 at 10:59:06AM +0530, Chandan Babu R wrote:
>> On Thu, Jan 04, 2024 at 06:40:43 PM +0530, Chandan Babu R wrote:
>> > On Wed, Jan 03, 2024 at 08:34:20 PM -0800, Darrick J. Wong wrote:
>> >> On Wed, Jan 03, 2024 at 12:12:12PM +0530, Chandan Babu R wrote:
>> >>> Hi,
>> >>> 
>> >>> Executing fstests' recoveryloop test group on XFS on a next-20240102 kernel
>> >>> sometimes causes the following hung task report to be printed on the console,
>> >>> 
>> 
>> Meanwhile, I have executed some more experiments.
>> 
>> The bug can be recreated on a next-20240102 kernel by executing either
>> generic/388 or generic/475 for a maximum of 10 iterations. I tried to do a git
>> bisect based on this observation i.e. I would mark a commit as 'good' if the
>> bug does not get recreated within 10 iterations. This led to the following git
>> bisect log,
>
>> # bad: [119dcc73a9c2df0da002054cdb2296cb32b7cb93] Merge branches 'work.dcache-misc' and 'work.dcache2' into work.dcache
>> git bisect bad 119dcc73a9c2df0da002054cdb2296cb32b7cb93
>> # good: [6367b491c17a34b28aece294bddfda1a36ec0377] retain_dentry(): introduce a trimmed-down lockless variant
>> git bisect good 57851607326a2beef21e67f83f4f53a90df8445a
>> # good: [ef69f0506d8f3a250ac5baa96746e17ae22c67b5] __d_unalias() doesn't use inode argument
>
> Lovely...  Could you try to do the following:
>
> bisect from 6.7-rc1 to work.dcache-misc; for each of those revisions
> 	git worktree add ../test HEAD
> 	cd ../test
> 	git merge work.dcache2
> 	build
> 	test the result
> 	cd -
> 	git worktree remove -f ../test
> 	git bisect {good,bad} accordingly

The result of the above suggested bisect operation is,

# git bisect log
# bad: [0695819b3988e7e4d8099f8388244c1549d230cc] __d_unalias() doesn't use inode argument
# good: [b85ea95d086471afb4ad062012a4d73cd328fa86] Linux 6.7-rc1
git bisect start 'HEAD' 'v6.7-rc1' 'fs/'
# good: [b33c14c8618edfc00bf8963e3b0c8a2b19c9eaa4] Merge branch 'no-rebase-overlayfs' into work.dcache-misc
git bisect good b33c14c8618edfc00bf8963e3b0c8a2b19c9eaa4
# good: [ef8a633ee84d8b57eba1f5b2908a3e0bf61837aa] Merge branch 'merged-selinux' into work.dcache-misc
git bisect good ef8a633ee84d8b57eba1f5b2908a3e0bf61837aa
# good: [53f99622a2b24704766469af23360836432eb88a] d_genocide(): move the extern into fs/internal.h
git bisect good 53f99622a2b24704766469af23360836432eb88a
# bad: [ce54c803d57ab6e872b670f0b46fc65840c8d7ca] d_alloc_parallel(): in-lookup hash insertion doesn't need an RCU variant
git bisect bad ce54c803d57ab6e872b670f0b46fc65840c8d7ca
# bad: [f7aff128d8c70493d614786ba7ec5f743feafe51] get rid of DCACHE_GENOCIDE
git bisect bad f7aff128d8c70493d614786ba7ec5f743feafe51
# first bad commit: [f7aff128d8c70493d614786ba7ec5f743feafe51] get rid of DCACHE_GENOCIDE


commit f7aff128d8c70493d614786ba7ec5f743feafe51
Author: Al Viro <viro@zeniv.linux.org.uk>
Date:   Sun Nov 12 21:38:48 2023 -0500

    get rid of DCACHE_GENOCIDE

    ... now that we never call d_genocide() other than from kill_litter_super()

    Signed-off-by: Al Viro <viro@zeniv.linux.org.uk>

 fs/dcache.c            | 5 +----
 include/linux/dcache.h | 1 -
 2 files changed, 1 insertion(+), 5 deletions(-)

-- 
Chandan

Re: [BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Al Viro]

On Tue, Jan 23, 2024 at 11:31:00AM +0530, Chandan Babu R wrote:
> 
> The result of the above suggested bisect operation is,
> 
> # git bisect log
> # bad: [0695819b3988e7e4d8099f8388244c1549d230cc] __d_unalias() doesn't use inode argument
> # good: [b85ea95d086471afb4ad062012a4d73cd328fa86] Linux 6.7-rc1
> git bisect start 'HEAD' 'v6.7-rc1' 'fs/'
> # good: [b33c14c8618edfc00bf8963e3b0c8a2b19c9eaa4] Merge branch 'no-rebase-overlayfs' into work.dcache-misc
> git bisect good b33c14c8618edfc00bf8963e3b0c8a2b19c9eaa4
> # good: [ef8a633ee84d8b57eba1f5b2908a3e0bf61837aa] Merge branch 'merged-selinux' into work.dcache-misc
> git bisect good ef8a633ee84d8b57eba1f5b2908a3e0bf61837aa
> # good: [53f99622a2b24704766469af23360836432eb88a] d_genocide(): move the extern into fs/internal.h
> git bisect good 53f99622a2b24704766469af23360836432eb88a
> # bad: [ce54c803d57ab6e872b670f0b46fc65840c8d7ca] d_alloc_parallel(): in-lookup hash insertion doesn't need an RCU variant
> git bisect bad ce54c803d57ab6e872b670f0b46fc65840c8d7ca
> # bad: [f7aff128d8c70493d614786ba7ec5f743feafe51] get rid of DCACHE_GENOCIDE
> git bisect bad f7aff128d8c70493d614786ba7ec5f743feafe51
> # first bad commit: [f7aff128d8c70493d614786ba7ec5f743feafe51] get rid of DCACHE_GENOCIDE
> 
> 
> commit f7aff128d8c70493d614786ba7ec5f743feafe51
> Author: Al Viro <viro@zeniv.linux.org.uk>
> Date:   Sun Nov 12 21:38:48 2023 -0500
> 
>     get rid of DCACHE_GENOCIDE
> 
>     ... now that we never call d_genocide() other than from kill_litter_super()

Huh?  So you are seeing that on merge of f7aff128d8c70493d614786ba7ec5f743feafe51 +
6367b491c17a34b28aece294bddfda1a36ec0377, but not on
f7aff128d8c70493d614786ba7ec5f743feafe51^ + 6367b491c17a34b28aece294bddfda1a36ec0377?

Wait a minute...  That smells like a d_walk() seeing rename_lock touched when it's
ascending from a subtree (for the reasons that have nothing to do with any changes of
the tree we are walking) and deciding to take another pass through the damn thing.
Argh...

But that should've been a problem for that commit on its own, regardless of the
merge with work.dcache2...  OTOH, it probably ended up as quiet memory leak without
that merge...

OK, could you verify that revert of that commit is enough to recover?  Short-term
that would be the obvious solution, assuming this is all that happens there.
Longer term I'd probably prefer to avoid using d_walk() there, but that's
a separate story.

Re: [BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Chandan Babu R]

On Tue, Jan 23, 2024 at 11:40:43 AM +0000, Al Viro wrote:
> On Tue, Jan 23, 2024 at 11:31:00AM +0530, Chandan Babu R wrote:
>> 
>> The result of the above suggested bisect operation is,
>> 
>> # git bisect log
>> # bad: [0695819b3988e7e4d8099f8388244c1549d230cc] __d_unalias() doesn't use inode argument
>> # good: [b85ea95d086471afb4ad062012a4d73cd328fa86] Linux 6.7-rc1
>> git bisect start 'HEAD' 'v6.7-rc1' 'fs/'
>> # good: [b33c14c8618edfc00bf8963e3b0c8a2b19c9eaa4] Merge branch 'no-rebase-overlayfs' into work.dcache-misc
>> git bisect good b33c14c8618edfc00bf8963e3b0c8a2b19c9eaa4
>> # good: [ef8a633ee84d8b57eba1f5b2908a3e0bf61837aa] Merge branch 'merged-selinux' into work.dcache-misc
>> git bisect good ef8a633ee84d8b57eba1f5b2908a3e0bf61837aa
>> # good: [53f99622a2b24704766469af23360836432eb88a] d_genocide(): move the extern into fs/internal.h
>> git bisect good 53f99622a2b24704766469af23360836432eb88a
>> # bad: [ce54c803d57ab6e872b670f0b46fc65840c8d7ca] d_alloc_parallel(): in-lookup hash insertion doesn't need an RCU variant
>> git bisect bad ce54c803d57ab6e872b670f0b46fc65840c8d7ca
>> # bad: [f7aff128d8c70493d614786ba7ec5f743feafe51] get rid of DCACHE_GENOCIDE
>> git bisect bad f7aff128d8c70493d614786ba7ec5f743feafe51
>> # first bad commit: [f7aff128d8c70493d614786ba7ec5f743feafe51] get rid of DCACHE_GENOCIDE
>> 
>> 
>> commit f7aff128d8c70493d614786ba7ec5f743feafe51
>> Author: Al Viro <viro@zeniv.linux.org.uk>
>> Date:   Sun Nov 12 21:38:48 2023 -0500
>> 
>>     get rid of DCACHE_GENOCIDE
>> 
>>     ... now that we never call d_genocide() other than from kill_litter_super()
>
> Huh?  So you are seeing that on merge of f7aff128d8c70493d614786ba7ec5f743feafe51 +
> 6367b491c17a34b28aece294bddfda1a36ec0377, but not on
> f7aff128d8c70493d614786ba7ec5f743feafe51^ + 6367b491c17a34b28aece294bddfda1a36ec0377?
>

The above bad commit was identified with
f7aff128d8c70493d614786ba7ec5f743feafe51 + 4931c524ee8bbdf890972b14d6fcd9e2c72602d9

4931c524ee8bbdf890972b14d6fcd9e2c72602d9 was obtained from work.dcache2 branch at
https://git.kernel.org/pub/scm/linux/kernel/git/viro/vfs.git.

However the diff between those commits suggest that they should not impact the
bisect results,

# git diff --stat 4931c524ee8bbdf890972b14d6fcd9e2c72602d9..6367b491c17a34b28aece294bddfda1a36ec0377
 Documentation/filesystems/porting.rst | 8 ++++----
 fs/coda/cache.c                       | 3 ---
 2 files changed, 4 insertions(+), 7 deletions(-)

> Wait a minute...  That smells like a d_walk() seeing rename_lock touched when it's
> ascending from a subtree (for the reasons that have nothing to do with any changes of
> the tree we are walking) and deciding to take another pass through the damn thing.
> Argh...
>
> But that should've been a problem for that commit on its own, regardless of the
> merge with work.dcache2...  OTOH, it probably ended up as quiet memory leak without
> that merge...
>
> OK, could you verify that revert of that commit is enough to recover?  Short-term
> that would be the obvious solution, assuming this is all that happens there.
> Longer term I'd probably prefer to avoid using d_walk() there, but that's
> a separate story.

I executed generic/388 for about 22 times without including
f7aff128d8c70493d614786ba7ec5f743feafe51 commit. The first few commits on
the git tree were,

9cae6cd3e74a (HEAD -> without-dcache-genocide) Merge remote-tracking branch 'alviro/work.dcache2' into without-dcache-genocide
53f99622a2b2 d_genocide(): move the extern into fs/internal.h
4931c524ee8b (alviro/work.dcache2) retain_dentry(): introduce a trimmed-down lockless variant
1b738f196eac __dentry_kill(): new locking scheme
e3640d37d056 d_prune_aliases(): use a shrink list

The indefinite loop bug could not be recreated with the above kernel.

-- 
Chandan

Re: [BUG REPORT] shrink_dcache_parent() loops indefinitely on a next-20240102 kernel

[Dominique Martinet]

Hello -- I've also hit this on master as of a few days ago (on
021533194476 ("Kconfig: Disable -Wstringop-overflow for GCC globally"))
just running some short lived docker container in a loop -- the last
process of the mount namespace exiting cleans up the mess docker had set
up and sometimes get caught there:

 #5 [ffff9f0fcd927c48] select_collect at ffffffffb2ffa6c2
 #6 [ffff9f0fcd927c58] d_walk at ffffffffb2ffb0a8
 #7 [ffff9f0fcd927cb0] shrink_dcache_parent at ffffffffb2ffd53e
 #8 [ffff9f0fcd927cf8] shrink_dcache_for_umount at ffffffffb2ffd8e7
 #9 [ffff9f0fcd927d20] generic_shutdown_super at ffffffffb2fdc39a
#10 [ffff9f0fcd927d38] kill_litter_super at ffffffffb2fdc673
#11 [ffff9f0fcd927d50] deactivate_locked_super at ffffffffb2fdd37f
#12 [ffff9f0fcd927d68] cleanup_mnt at ffffffffb3008d1d
#13 [ffff9f0fcd927d90] task_work_run at ffffffffb2cd97e9
#14 [ffff9f0fcd927db0] do_exit at ffffffffb2cb1c9c
#15 [ffff9f0fcd927e10] do_group_exit at ffffffffb2cb264d
#16 [ffff9f0fcd927e38] __x64_sys_exit_group at ffffffffb2cb26c4
#17 [ffff9f0fcd927e40] do_syscall_64 at ffffffffb376ea47

(I'm trying to reproduce another networking bug with that, it doesn't
happen very often but I noticed docker hangs once in a while, more often
after I reduced how much memory I gave to this VM)


Reverting just 57851607326a ("get rid of DCACHE_GENOCIDE") seems to get
rid of the issue at this point, I'm pretty confident it's no longer
happening by now but I'll reply again tomorrow if I hit the problem
again overnight.


Thanks,
-- 
Dominique Martinet | Asmadeus