rm hanging, v6.1.35

[Chris Dunlop <chris@onthe.net.au>]

Hi,

This box is newly booted into linux v6.1.35 (2 days ago), it was 
previously running v5.15.118 without any problems (other than that fixed 
by "5e672cd69f0a xfs: non-blocking inodegc pushes", the reason for the 
upgrade).

I have rm operations on two files that have been stuck for in excess of 22 
hours and 18 hours respectively:

$ ps -opid,lstart,state,wchan=WCHAN-xxxxxxxxxxxxxxx,cmd -C rm
     PID                  STARTED S WCHAN-xxxxxxxxxxxxxxx CMD
2379355 Mon Jul 10 09:07:57 2023 D vfs_unlink            /bin/rm -rf /aaa/5539_tmp
2392421 Mon Jul 10 09:18:27 2023 D down_write_nested     /bin/rm -rf /aaa/5539_tmp
2485728 Mon Jul 10 09:28:57 2023 D down_write_nested     /bin/rm -rf /aaa/5539_tmp
2488254 Mon Jul 10 09:39:27 2023 D down_write_nested     /bin/rm -rf /aaa/5539_tmp
2491180 Mon Jul 10 09:49:58 2023 D down_write_nested     /bin/rm -rf /aaa/5539_tmp
3014914 Mon Jul 10 13:00:33 2023 D vfs_unlink            /bin/rm -rf /bbb/5541_tmp
3095893 Mon Jul 10 13:11:03 2023 D down_write_nested     /bin/rm -rf /bbb/5541_tmp
3098809 Mon Jul 10 13:21:35 2023 D down_write_nested     /bin/rm -rf /bbb/5541_tmp
3101387 Mon Jul 10 13:32:06 2023 D down_write_nested     /bin/rm -rf /bbb/5541_tmp
3195017 Mon Jul 10 13:42:37 2023 D down_write_nested     /bin/rm -rf /bbb/5541_tmp

The "rm"s are run from a process that's obviously tried a few times to get 
rid of these files.

There's nothing extraordinary about the files in terms of size:

$ ls -ltrn --full-time /aaa/5539_tmp /bbb/5541_tmp
-rw-rw-rw- 1 1482 1482 7870643 2023-07-10 06:07:58.684036505 +1000 /aaa/5539_tmp
-rw-rw-rw- 1 1482 1482  701240 2023-07-10 10:00:34.181064549 +1000 /bbb/5541_tmp

As hinted by the WCHAN in the ps output above, each "primary" rm (i.e. the 
first one run on each file) stack trace looks like:

[<0>] vfs_unlink+0x48/0x270
[<0>] do_unlinkat+0x1f5/0x290
[<0>] __x64_sys_unlinkat+0x3b/0x60
[<0>] do_syscall_64+0x34/0x80
[<0>] entry_SYSCALL_64_after_hwframe+0x46/0xb0

And each "secondary" rm (i.e. the subsequent ones on each file) stack 
trace looks like:

== blog-230710-xfs-rm-stuckd
[<0>] down_write_nested+0xdc/0x100
[<0>] do_unlinkat+0x10d/0x290
[<0>] __x64_sys_unlinkat+0x3b/0x60
[<0>] do_syscall_64+0x34/0x80
[<0>] entry_SYSCALL_64_after_hwframe+0x46/0xb0

Multiple kernel strack traces don't show vfs_unlink or anything related 
that I can see, or anything else consistent or otherwise interesting. Most 
cores are idle.

Each of /aaa and /bbb are separate XFS filesystems:

$ xfs_info /aaa
meta-data=/dev/mapper/aaa        isize=512    agcount=2, agsize=268434432 blks
          =                       sectsz=4096  attr=2, projid32bit=1
          =                       crc=1        finobt=1, sparse=1, rmapbt=1
          =                       reflink=1    bigtime=1 inobtcount=1
data     =                       bsize=4096   blocks=536868864, imaxpct=5
          =                       sunit=256    swidth=256 blks
naming   =version 2              bsize=4096   ascii-ci=0, ftype=1
log      =internal log           bsize=4096   blocks=262143, version=2
          =                       sectsz=4096  sunit=1 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

$ xfs_info /bbb
meta-data=/dev/mapper/bbb        isize=512    agcount=8, agsize=268434432 blks
          =                       sectsz=4096  attr=2, projid32bit=1
          =                       crc=1        finobt=1, sparse=1, rmapbt=1
          =                       reflink=1    bigtime=1 inobtcount=1
data     =                       bsize=4096   blocks=1879047168, imaxpct=5
          =                       sunit=256    swidth=256 blks
naming   =version 2              bsize=4096   ascii-ci=0, ftype=1
log      =internal log           bsize=4096   blocks=521728, version=2
          =                       sectsz=4096  sunit=1 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

There's plenty of free space at the fs level:

$ df -h /aaa /bbb
Filesystem          Size  Used Avail Use% Mounted on
/dev/mapper/aaa     2.0T  551G  1.5T  27% /aaa
/dev/mapper/bbb     7.0T  3.6T  3.5T  52% /bbb

The fses are on sparse ceph/rbd volumes, the underlying storage tells me 
they're 50-60% utilised:

aaa: provisioned="2048G" used="1015.9G"
bbb: provisioned="7168G" used="4925.3G"

Where to from here?

I'm guessing only a reboot is going to unstick this. Anything I should be 
looking at before reverting to v5.15.118?

...subsequent to starting writing all this down I have another two sets of 
rms stuck, again on unremarkable files, and on two more separate 
filesystems.

...oh. And an 'ls' on those files is hanging. The reboot has become more 
urgent.

Cheers,

Chris