XFS mount timeout in linux-6.9.11

XFS mount timeout in linux-6.9.11

[Anders Blomdell]

With a filesystem that contains a very large amount of hardlinks
the time to mount the filesystem skyrockets to around 15 minutes
on 6.9.11-200.fc40.x86_64 as compared to around 1 second on
6.8.10-300.fc40.x86_64, this of course makes booting drop
into emergency mode if the filesystem is in /etc/fstab. A git bisect
nails the offending commit as 14dd46cf31f4aaffcf26b00de9af39d01ec8d547.

The filesystem is a collection of daily snapshots of a live filesystem
collected over a number of years, organized as a storage of unique files,
that are reflinked to inodes that contain the actual {owner,group,permission,
mtime}, and these inodes are hardlinked into the daily snapshot trees.

The numbers for the filesystem are:

   Total file size:           3.6e+12 bytes
   Unique files:             12.4e+06
   Reflink inodes:           18.6e+06
   Hardlinks:                15.7e+09
   
Timing between the systems are:

   6.8.10-300.fc40.x86_64:

     # time mount /dev/vg1/test /test
     real	0m0.835s
     user	0m0.002s
     sys	        0m0.014s

   6.9.11-200.fc40.x86_64:

     # time mount /dev/vg1/test /test
     real	15m36.508s
     user	0m0.000s
     sys	        0m27.628s

     (iotop reports 1-4 MB/s)

Re: XFS mount timeout in linux-6.9.11

[Dave Chinner]

On Fri, Aug 09, 2024 at 07:08:41PM +0200, Anders Blomdell wrote:
> With a filesystem that contains a very large amount of hardlinks
> the time to mount the filesystem skyrockets to around 15 minutes
> on 6.9.11-200.fc40.x86_64 as compared to around 1 second on
> 6.8.10-300.fc40.x86_64,

That sounds like the filesystem is not being cleanly unmounted on
6.9.11-200.fc40.x86_64 and so is having to run log recovery on the
next mount and so is recovering lots of hardlink operations that
weren't written back at unmount.

Hence this smells like an unmount or OS shutdown process issue, not
a mount issue. e.g. if something in the shutdown scripts hangs,
systemd may time out the shutdown and power off/reboot the machine
wihtout completing the full shutdown process. The result of this is
the filesystem has to perform recovery on the next mount and so you
see a long mount time because of some other unrelated issue.

What is the dmesg output for the mount operations? That will tell us
if journal recovery is the difference for certain.  Have you also
checked to see what is happening in the shutdown/unmount process
before the long mount times occur?

> this of course makes booting drop
> into emergency mode if the filesystem is in /etc/fstab. A git bisect
> nails the offending commit as 14dd46cf31f4aaffcf26b00de9af39d01ec8d547.

Commit 14dd46cf31f4 ("xfs: split xfs_inobt_init_cursor") doesn't
seem like a candidate for any sort of change of behaviour. It's just
a refactoring patch that doesn't change any behaviour at all. Are
you sure the reproducer you used for the bisect is reliable?

> The filesystem is a collection of daily snapshots of a live filesystem
> collected over a number of years, organized as a storage of unique files,
> that are reflinked to inodes that contain the actual {owner,group,permission,
> mtime}, and these inodes are hardlinked into the daily snapshot trees.

So it's reflinks and hardlinks. Recovering a reflink takes a lot
more CPU time and journal traffic than recovering a hardlink, so
that will also be a contributing factor.

> The numbers for the filesystem are:
> 
>   Total file size:           3.6e+12 bytes

3.6TB, not a large data set by any measurement.

>   Unique files:             12.4e+06

12M files, not a lot.

>   Reflink inodes:           18.6e+06

18M inodes with shared extents, not a huge number, either.

>   Hardlinks:                15.7e+09

Ok, 15.7 billion hardlinks is a *lot*.

And by a lot, I mean that's the largest number of hardlinks in an
XFS filesystem I've personally ever heard about in 20 years.

As a warning: hope like hell you never have a disaster with that
storage and need to run xfs_repair on that filesystem. It you don't
have many, many TBs of RAM, just checking the hardlinks resolve
correctly could take billions of IOs...

-Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: XFS mount timeout in linux-6.9.11

[Anders Blomdell]

On 2024-08-10 00:55, Dave Chinner wrote:
> On Fri, Aug 09, 2024 at 07:08:41PM +0200, Anders Blomdell wrote:
>> With a filesystem that contains a very large amount of hardlinks
>> the time to mount the filesystem skyrockets to around 15 minutes
>> on 6.9.11-200.fc40.x86_64 as compared to around 1 second on
>> 6.8.10-300.fc40.x86_64,
> 
> That sounds like the filesystem is not being cleanly unmounted on
> 6.9.11-200.fc40.x86_64 and so is having to run log recovery on the
> next mount and so is recovering lots of hardlink operations that
> weren't written back at unmount.
> 
> Hence this smells like an unmount or OS shutdown process issue, not
> a mount issue. e.g. if something in the shutdown scripts hangs,
> systemd may time out the shutdown and power off/reboot the machine
> wihtout completing the full shutdown process. The result of this is
> the filesystem has to perform recovery on the next mount and so you
> see a long mount time because of some other unrelated issue.
> 
> What is the dmesg output for the mount operations? That will tell us
> if journal recovery is the difference for certain.  Have you also
> checked to see what is happening in the shutdown/unmount process
> before the long mount times occur?
echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
mount /dev/vg1/test /test
echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
umount /test
echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
mount /dev/vg1/test /test
echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg

[55581.470484] 6.8.0-rc4-00129-g14dd46cf31f4 09:17:20
[55581.492733] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
[56048.292804] XFS (dm-7): Ending clean mount
[56516.433008] 6.8.0-rc4-00129-g14dd46cf31f4 09:32:55
[56516.434695] XFS (dm-7): Unmounting Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
[56516.925145] 6.8.0-rc4-00129-g14dd46cf31f4 09:32:56
[56517.039873] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
[56986.017144] XFS (dm-7): Ending clean mount
[57454.876371] 6.8.0-rc4-00129-g14dd46cf31f4 09:48:34

And rebooting to the kernel before the offending commit:

[   60.177951] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:00
[   61.009283] SGI XFS with ACLs, security attributes, realtime, scrub, quota, no debug enabled
[   61.017422] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
[   61.351100] XFS (dm-7): Ending clean mount
[   61.366359] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
[   61.367673] XFS (dm-7): Unmounting Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
[   61.444552] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
[   61.459358] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
[   61.513938] XFS (dm-7): Ending clean mount
[   61.524056] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01


> 
>> this of course makes booting drop
>> into emergency mode if the filesystem is in /etc/fstab. A git bisect
>> nails the offending commit as 14dd46cf31f4aaffcf26b00de9af39d01ec8d547.
> 
> Commit 14dd46cf31f4 ("xfs: split xfs_inobt_init_cursor") doesn't
> seem like a candidate for any sort of change of behaviour. It's just
> a refactoring patch that doesn't change any behaviour at all. 
> Are you sure the reproducer you used for the bisect is reliable?
Yes.

>> The filesystem is a collection of daily snapshots of a live filesystem
>> collected over a number of years, organized as a storage of unique files,
>> that are reflinked to inodes that contain the actual {owner,group,permission,
>> mtime}, and these inodes are hardlinked into the daily snapshot trees.
> 
> So it's reflinks and hardlinks. Recovering a reflink takes a lot
> more CPU time and journal traffic than recovering a hardlink, so
> that will also be a contributing factor.
> 
>> The numbers for the filesystem are:
>>
>>    Total file size:           3.6e+12 bytes
> 
> 3.6TB, not a large data set by any measurement.
> 
>>    Unique files:             12.4e+06
> 
> 12M files, not a lot.
> 
>>    Reflink inodes:           18.6e+06
> 
> 18M inodes with shared extents, not a huge number, either.
> 
>>    Hardlinks:                15.7e+09
> 
> Ok, 15.7 billion hardlinks is a *lot*.
:-)
> 
> And by a lot, I mean that's the largest number of hardlinks in an
> XFS filesystem I've personally ever heard about in 20 years.
Glad to be of service.

> 
> As a warning: hope like hell you never have a disaster with that
> storage and need to run xfs_repair on that filesystem. It you don't
> have many, many TBs of RAM, just checking the hardlinks resolve
> correctly could take billions of IOs...
I hope so as well :-), but it is not a critical system (used for testing
and statistics, will take about a month to rebuild though :-/).

> 
> -Dave.

Re: XFS mount timeout in linux-6.9.11

[Dave Chinner]

On Sat, Aug 10, 2024 at 10:29:38AM +0200, Anders Blomdell wrote:
> 
> 
> On 2024-08-10 00:55, Dave Chinner wrote:
> > On Fri, Aug 09, 2024 at 07:08:41PM +0200, Anders Blomdell wrote:
> > > With a filesystem that contains a very large amount of hardlinks
> > > the time to mount the filesystem skyrockets to around 15 minutes
> > > on 6.9.11-200.fc40.x86_64 as compared to around 1 second on
> > > 6.8.10-300.fc40.x86_64,
> > 
> > That sounds like the filesystem is not being cleanly unmounted on
> > 6.9.11-200.fc40.x86_64 and so is having to run log recovery on the
> > next mount and so is recovering lots of hardlink operations that
> > weren't written back at unmount.
> > 
> > Hence this smells like an unmount or OS shutdown process issue, not
> > a mount issue. e.g. if something in the shutdown scripts hangs,
> > systemd may time out the shutdown and power off/reboot the machine
> > wihtout completing the full shutdown process. The result of this is
> > the filesystem has to perform recovery on the next mount and so you
> > see a long mount time because of some other unrelated issue.
> > 
> > What is the dmesg output for the mount operations? That will tell us
> > if journal recovery is the difference for certain.  Have you also
> > checked to see what is happening in the shutdown/unmount process
> > before the long mount times occur?
> echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
> mount /dev/vg1/test /test
> echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
> umount /test
> echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
> mount /dev/vg1/test /test
> echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
> 
> [55581.470484] 6.8.0-rc4-00129-g14dd46cf31f4 09:17:20
> [55581.492733] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> [56048.292804] XFS (dm-7): Ending clean mount
> [56516.433008] 6.8.0-rc4-00129-g14dd46cf31f4 09:32:55

So it took ~450s to determine that the mount was clean, then another
450s to return to userspace?

> [56516.434695] XFS (dm-7): Unmounting Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> [56516.925145] 6.8.0-rc4-00129-g14dd46cf31f4 09:32:56
> [56517.039873] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> [56986.017144] XFS (dm-7): Ending clean mount
> [57454.876371] 6.8.0-rc4-00129-g14dd46cf31f4 09:48:34

Same again.

Can you post the 'xfs_info /mnt/pt' for that filesystem?

> And rebooting to the kernel before the offending commit:
> 
> [   60.177951] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:00
> [   61.009283] SGI XFS with ACLs, security attributes, realtime, scrub, quota, no debug enabled
> [   61.017422] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> [   61.351100] XFS (dm-7): Ending clean mount
> [   61.366359] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
> [   61.367673] XFS (dm-7): Unmounting Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> [   61.444552] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
> [   61.459358] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> [   61.513938] XFS (dm-7): Ending clean mount
> [   61.524056] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01

Yeah, that's what I'd expect to see.

But, hold on, the kernel version you are testing is apparently is in
the middle of 6.8-rc4. This commit wasn't merged until 6.9-rc1 and
there were no XFS changes merged in the between 6.8-rc3 and 6.8-rc6.
So as the bisect is walking back in time through the XFS commits,
the base kernel is also changing. Hence there's a lot more change
in the kernel being tested by each bisect step than just the XFS
commits, right?

This smells like a bisect jumping randomly backwards in time as it
lands inside merges rather than bisecting the order in which commits
were merged into the main tree. Can you post the full bisect log?

-Dave.

-- 
Dave Chinner
david@fromorbit.com

Re: XFS mount timeout in linux-6.9.11

[Anders Blomdell]

On 2024-08-11 01:11, Dave Chinner wrote:
> On Sat, Aug 10, 2024 at 10:29:38AM +0200, Anders Blomdell wrote:
>>
>>
>> On 2024-08-10 00:55, Dave Chinner wrote:
>>> On Fri, Aug 09, 2024 at 07:08:41PM +0200, Anders Blomdell wrote:
>>>> With a filesystem that contains a very large amount of hardlinks
>>>> the time to mount the filesystem skyrockets to around 15 minutes
>>>> on 6.9.11-200.fc40.x86_64 as compared to around 1 second on
>>>> 6.8.10-300.fc40.x86_64,
>>>
>>> That sounds like the filesystem is not being cleanly unmounted on
>>> 6.9.11-200.fc40.x86_64 and so is having to run log recovery on the
>>> next mount and so is recovering lots of hardlink operations that
>>> weren't written back at unmount.
>>>
>>> Hence this smells like an unmount or OS shutdown process issue, not
>>> a mount issue. e.g. if something in the shutdown scripts hangs,
>>> systemd may time out the shutdown and power off/reboot the machine
>>> wihtout completing the full shutdown process. The result of this is
>>> the filesystem has to perform recovery on the next mount and so you
>>> see a long mount time because of some other unrelated issue.
>>>
>>> What is the dmesg output for the mount operations? That will tell us
>>> if journal recovery is the difference for certain.  Have you also
>>> checked to see what is happening in the shutdown/unmount process
>>> before the long mount times occur?
>> echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
>> mount /dev/vg1/test /test
>> echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
>> umount /test
>> echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
>> mount /dev/vg1/test /test
>> echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
>>
>> [55581.470484] 6.8.0-rc4-00129-g14dd46cf31f4 09:17:20
>> [55581.492733] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
>> [56048.292804] XFS (dm-7): Ending clean mount
>> [56516.433008] 6.8.0-rc4-00129-g14dd46cf31f4 09:32:55
> 
> So it took ~450s to determine that the mount was clean, then another
> 450s to return to userspace?
Yeah, that aligns with my userspace view that the mount takes 15 minutes.
> 
>> [56516.434695] XFS (dm-7): Unmounting Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
>> [56516.925145] 6.8.0-rc4-00129-g14dd46cf31f4 09:32:56
>> [56517.039873] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
>> [56986.017144] XFS (dm-7): Ending clean mount
>> [57454.876371] 6.8.0-rc4-00129-g14dd46cf31f4 09:48:34
> 
> Same again.
> 
> Can you post the 'xfs_info /mnt/pt' for that filesystem?
# uname -r ; xfs_info /test
6.8.0-rc4-00128-g8541a7d9da2d
meta-data=/dev/mapper/vg1-test isize=512    agcount=8, agsize=268435455 blks
          =                       sectsz=4096  attr=2, projid32bit=1
          =                       crc=1        finobt=1, sparse=0, rmapbt=0
          =                       reflink=1    bigtime=0 inobtcount=0 nrext64=0
data     =                       bsize=4096   blocks=2147483640, imaxpct=20
          =                       sunit=0      swidth=0 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
> 
>> And rebooting to the kernel before the offending commit:
>>
>> [   60.177951] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:00
>> [   61.009283] SGI XFS with ACLs, security attributes, realtime, scrub, quota, no debug enabled
>> [   61.017422] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
>> [   61.351100] XFS (dm-7): Ending clean mount
>> [   61.366359] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
>> [   61.367673] XFS (dm-7): Unmounting Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
>> [   61.444552] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
>> [   61.459358] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
>> [   61.513938] XFS (dm-7): Ending clean mount
>> [   61.524056] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
> 
> Yeah, that's what I'd expect to see.
> 
> But, hold on, the kernel version you are testing is apparently is in
> the middle of 6.8-rc4. This commit wasn't merged until 6.9-rc1 and
> there were no XFS changes merged in the between 6.8-rc3 and 6.8-rc6.
If I read the logs correctly, these commited xfs changes were based on the
6.8-rc4, and not rebased to 6.8.0 (which is totally OK, but confusing at
times, after doing some kernel bisects I have stopped thinking about it).

> So as the bisect is walking back in time through the XFS commits,
> the base kernel is also changing. Hence there's a lot more change
> in the kernel being tested by each bisect step than just the XFS
> commits, right?
Yes, it's a binary search through the highly convoluted graph of commits.
It always suprises me how few of these "random" points fails miserably
during a bisect (in this particular case none), so kudos to all linux
maintainers to keep things so sane!

> 
> This smells like a bisect jumping randomly backwards in time as it
> lands inside merges rather than bisecting the order in which commits
> were merged into the main tree. Can you post the full bisect log?
git bisect start
# status: waiting for both good and bad commits
# bad: [73f3c33036904bada1b9b6476a883b1a966440cc] Linux 6.9.11
git bisect bad 73f3c33036904bada1b9b6476a883b1a966440cc
# status: waiting for good commit(s), bad commit known
# good: [a0c69a570e420e86c7569b8c052913213eef2b45] Linux 6.8.10
git bisect good a0c69a570e420e86c7569b8c052913213eef2b45
# good: [e8f897f4afef0031fe618a8e94127a0934896aba] Linux 6.8
git bisect good e8f897f4afef0031fe618a8e94127a0934896aba
# bad: [fe46a7dd189e25604716c03576d05ac8a5209743] Merge tag 'sound-6.9-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/tiwai/sound
git bisect bad fe46a7dd189e25604716c03576d05ac8a5209743
# good: [9187210eee7d87eea37b45ea93454a88681894a4] Merge tag 'net-next-6.9' of git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net-next
git bisect good 9187210eee7d87eea37b45ea93454a88681894a4
# good: [119b225f01e4d3ce974cd3b4d982c76a380c796d] Merge tag 'amd-drm-next-6.9-2024-03-08-1' of https://gitlab.freedesktop.org/agd5f/linux into drm-next
git bisect good 119b225f01e4d3ce974cd3b4d982c76a380c796d
# good: [70ef654469b371d0a71bcf967fa3dcbca05d4b25] Merge tag 'efi-next-for-v6.9' of git://git.kernel.org/pub/scm/linux/kernel/git/efi/efi
git bisect good 70ef654469b371d0a71bcf967fa3dcbca05d4b25
# bad: [8403ce70be339d462892a2b935ae30ee52416f92] Merge tag 'mfd-next-6.9' of git://git.kernel.org/pub/scm/linux/kernel/git/lee/mfd
git bisect bad 8403ce70be339d462892a2b935ae30ee52416f92
# bad: [480e035fc4c714fb5536e64ab9db04fedc89e910] Merge tag 'drm-next-2024-03-13' of https://gitlab.freedesktop.org/drm/kernel
git bisect bad 480e035fc4c714fb5536e64ab9db04fedc89e910
# bad: [57982d6c835a71da5c66e6090680de1adf6e736a] xfs: consolidate btree ptr checking
git bisect bad 57982d6c835a71da5c66e6090680de1adf6e736a
# good: [0b8686f19879d896bbe2d3e893f433a08160452d] xfs: separate the marking of sick and checked metadata
git bisect good 0b8686f19879d896bbe2d3e893f433a08160452d
# good: [1a9d26291c68fbb8f8d24f9f694b32223a072745] xfs: store the btree pointer length in struct xfs_btree_ops
git bisect good 1a9d26291c68fbb8f8d24f9f694b32223a072745
# good: [802f91f7b1d535ac975e2d696bf5b5dea82816e7] xfs: fold xfs_bmbt_init_common into xfs_bmbt_init_cursor
git bisect good 802f91f7b1d535ac975e2d696bf5b5dea82816e7
# good: [4bfb028a4c00d0a079a625d7867325efb3c37de2] xfs: remove the btnum argument to xfs_inobt_count_blocks
git bisect good 4bfb028a4c00d0a079a625d7867325efb3c37de2
# bad: [fbeef4e061ab28bf556af4ee2a5a9848dc4616c5] xfs: pass a 'bool is_finobt' to xfs_inobt_insert
git bisect bad fbeef4e061ab28bf556af4ee2a5a9848dc4616c5
# good: [8541a7d9da2dd6e44f401f2363b21749b7413fc9] xfs: split xfs_inobt_insert_sprec
git bisect good 8541a7d9da2dd6e44f401f2363b21749b7413fc9
# bad: [14dd46cf31f4aaffcf26b00de9af39d01ec8d547] xfs: split xfs_inobt_init_cursor
git bisect bad 14dd46cf31f4aaffcf26b00de9af39d01ec8d547
# first bad commit: [14dd46cf31f4aaffcf26b00de9af39d01ec8d547] xfs: split xfs_inobt_init_cursor

/Anders

Re: XFS mount timeout in linux-6.9.11

[Dave Chinner]

On Sun, Aug 11, 2024 at 10:17:50AM +0200, Anders Blomdell wrote:
> On 2024-08-11 01:11, Dave Chinner wrote:
> > On Sat, Aug 10, 2024 at 10:29:38AM +0200, Anders Blomdell wrote:
> > > On 2024-08-10 00:55, Dave Chinner wrote:
> > > > On Fri, Aug 09, 2024 at 07:08:41PM +0200, Anders Blomdell wrote:
> > > echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
> > > mount /dev/vg1/test /test
> > > echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
> > > umount /test
> > > echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
> > > mount /dev/vg1/test /test
> > > echo $(uname -r) $(date +%H:%M:%S) > /dev/kmsg
> > > 
> > > [55581.470484] 6.8.0-rc4-00129-g14dd46cf31f4 09:17:20
> > > [55581.492733] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> > > [56048.292804] XFS (dm-7): Ending clean mount
> > > [56516.433008] 6.8.0-rc4-00129-g14dd46cf31f4 09:32:55
> > 
> > So it took ~450s to determine that the mount was clean, then another
> > 450s to return to userspace?
> Yeah, that aligns with my userspace view that the mount takes 15 minutes.
> > 
> > > [56516.434695] XFS (dm-7): Unmounting Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> > > [56516.925145] 6.8.0-rc4-00129-g14dd46cf31f4 09:32:56
> > > [56517.039873] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> > > [56986.017144] XFS (dm-7): Ending clean mount
> > > [57454.876371] 6.8.0-rc4-00129-g14dd46cf31f4 09:48:34
> > 
> > Same again.
> > 
> > Can you post the 'xfs_info /mnt/pt' for that filesystem?
> # uname -r ; xfs_info /test
> 6.8.0-rc4-00128-g8541a7d9da2d
> meta-data=/dev/mapper/vg1-test isize=512    agcount=8, agsize=268435455 blks
>          =                       sectsz=4096  attr=2, projid32bit=1
>          =                       crc=1        finobt=1, sparse=0, rmapbt=0
>          =                       reflink=1    bigtime=0 inobtcount=0 nrext64=0
> data     =                       bsize=4096   blocks=2147483640, imaxpct=20
>          =                       sunit=0      swidth=0 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

Ok, nothing I'd consider strange there.

> > > And rebooting to the kernel before the offending commit:
> > > 
> > > [   60.177951] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:00
> > > [   61.009283] SGI XFS with ACLs, security attributes, realtime, scrub, quota, no debug enabled
> > > [   61.017422] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> > > [   61.351100] XFS (dm-7): Ending clean mount
> > > [   61.366359] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
> > > [   61.367673] XFS (dm-7): Unmounting Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> > > [   61.444552] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
> > > [   61.459358] XFS (dm-7): Mounting V5 Filesystem e2159bbc-18fb-4d4b-a6c5-14c97b8e5380
> > > [   61.513938] XFS (dm-7): Ending clean mount
> > > [   61.524056] 6.8.0-rc4-00128-g8541a7d9da2d 10:23:01
> > 
> > Yeah, that's what I'd expect to see.

Ok, can you run the same series of commands but this time in another
shell run this command and leave it running for the entire
mount/unmount/mount/unmount sequence:

# trace-cmd record -e xfs\* -e printk

Then ctrl-c out of it, and run:

# trace-cmd report > xfs-mount-report.<kernel>.txt

on both kernels and send me the output (or a link that I can
download because it will probably be quite large even when
compressed) that is generated?

That will tell me what XFS is doing different at mount time on the
different kernels.

[snip stuff about git bisect]

I'll come back to the bisect if it's relevant once I know what XFS
is doing differently across the unmount/mount cycles on the two
different kernels.

-Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: XFS mount timeout in linux-6.9.11

[Dave Chinner]

On Mon, Aug 12, 2024 at 03:03:49PM +0200, Anders Blomdell wrote:
> On 2024-08-12 02:04, Dave Chinner wrote:
> > 
> > Ok, can you run the same series of commands but this time in another
> > shell run this command and leave it running for the entire
> > mount/unmount/mount/unmount sequence:
> > 
> > # trace-cmd record -e xfs\* -e printk

[snip location of trace]

> > That will tell me what XFS is doing different at mount time on the
> > different kernels.
> Looks like a timing issue, a trylock fails and brings about a READ_AHEAD burst.

Not timing - it is definitely a bug in the commit the bisect pointed
at.

However, it's almost impossible to actually see until someone or
something (the trace) points it out directly.

The trace confirmed what I suspected - the READ_AHEAD stuff you see
is an inode btree being walked. I knew that we walk the free inode
btrees during mount unless you have a specific feature bit set, but
I didn't think your filesystem is new enough to have that feature
set according to the xfs_info output.

However, I couldn't work out why the free inode btrees would take
that long to walk as the finobt generally tends towards empty on any
filesystem that is frequently allocating inodes. The mount time on
the old kernel indicates they are pretty much empty, because the
mount time is under a second and it's walked all 8 finobts *twice*
during mount.

What the trace pointed out was that the finobt walk to calculate
AG reserve space wasn't actually walking the finobt - it was walking
the inobt. That indexes all allocated inodes, so mount was walking
the btrees that index the ~30 million allocated inodes in the
filesystem. That takes a lot of IO, and that's the 450s pause 
to calculate reserves before we run log recovery, and then the
second 450s pause occurs after log recovery because we have to
recalculate the reserves once all the intents and unlinked inodes
have been replayed.

From that observation, it was just a matter of tracking down the
code that is triggering the walk and working out why it was running
down the wrong inobt....

In hindsight, this was a wholly avoidable bug - a single patch made
two different API modifications that only differed by a single
letter, and one of the 23 conversions missed a single letter. If
that was two patches - one for the finobt conversion, the second for
the inobt conversion, the bug would have been plainly obvious during
review....

Anders, can you try the patch below? It should fix your issue.

-Dave.
-- 
Dave Chinner
david@fromorbit.com

xfs: xfs_finobt_count_blocks() walks the wrong btree

From: Dave Chinner <dchinner@redhat.com>

As a result of the factoring in commit 14dd46cf31f4 ("xfs: split
xfs_inobt_init_cursor"), mount started taking a long time on a
user's filesystem.  For Anders, this made mount times regress from
under a second to over 15 minutes for a filesystem with only 30
million inodes in it.

Anders bisected it down to the above commit, but even then the bug
was not obvious. In this commit, over 20 calls to
xfs_inobt_init_cursor() were modified, and some we modified to call
a new function named xfs_finobt_init_cursor().

If that takes you a moment to reread those function names to see
what the rename was, then you have realised why this bug wasn't
spotted during review. And it wasn't spotted on inspection even
after the bisect pointed at this commit - a single missing "f" isn't
the easiest thing for a human eye to notice....

The result is that xfs_finobt_count_blocks() now incorrectly calls
xfs_inobt_init_cursor() so it is now walking the inobt instead of
the finobt. Hence when there are lots of allocated inodes in a
filesystem, mount takes a -long- time run because it now walks a
massive allocated inode btrees instead of the small, nearly empty
free inode btrees. It also means all the finobt space reservations
are wrong, so mount could potentially given ENOSPC on kernel
upgrade.

In hindsight, commit 14dd46cf31f4 should have been two commits - the
first to convert the finobt callers to the new API, the second to
modify the xfs_inobt_init_cursor() API for the inobt callers. That
would have made the bug very obvious during review.

Fixes: 14dd46cf31f4 ("xfs: split xfs_inobt_init_cursor")
Reported-by: Anders Blomdell <anders.blomdell@gmail.com>
Signed-off-by: Dave Chinner <dchinner@redhat.com>
---
 fs/xfs/libxfs/xfs_ialloc_btree.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/fs/xfs/libxfs/xfs_ialloc_btree.c b/fs/xfs/libxfs/xfs_ialloc_btree.c
index 496e2f72a85b..797d5b5f7b72 100644
--- a/fs/xfs/libxfs/xfs_ialloc_btree.c
+++ b/fs/xfs/libxfs/xfs_ialloc_btree.c
@@ -749,7 +749,7 @@ xfs_finobt_count_blocks(
 	if (error)
 		return error;
 
-	cur = xfs_inobt_init_cursor(pag, tp, agbp);
+	cur = xfs_finobt_init_cursor(pag, tp, agbp);
 	error = xfs_btree_count_blocks(cur, tree_blocks);
 	xfs_btree_del_cursor(cur, error);
 	xfs_trans_brelse(tp, agbp);

Re: XFS mount timeout in linux-6.9.11

[Anders Blomdell]

On 2024-08-13 11:19, Dave Chinner wrote:
> On Mon, Aug 12, 2024 at 03:03:49PM +0200, Anders Blomdell wrote:
>> On 2024-08-12 02:04, Dave Chinner wrote:
>>>
>>> Ok, can you run the same series of commands but this time in another
>>> shell run this command and leave it running for the entire
>>> mount/unmount/mount/unmount sequence:
>>>
>>> # trace-cmd record -e xfs\* -e printk
> 
> [snip location of trace]
> 
>>> That will tell me what XFS is doing different at mount time on the
>>> different kernels.
>> Looks like a timing issue, a trylock fails and brings about a READ_AHEAD burst.
> 
> Not timing - it is definitely a bug in the commit the bisect pointed
> at.
> 
> However, it's almost impossible to actually see until someone or
> something (the trace) points it out directly.
> 
> The trace confirmed what I suspected - the READ_AHEAD stuff you see
> is an inode btree being walked. I knew that we walk the free inode
> btrees during mount unless you have a specific feature bit set, but
> I didn't think your filesystem is new enough to have that feature
> set according to the xfs_info output.
> 
> However, I couldn't work out why the free inode btrees would take
> that long to walk as the finobt generally tends towards empty on any
> filesystem that is frequently allocating inodes. The mount time on
> the old kernel indicates they are pretty much empty, because the
> mount time is under a second and it's walked all 8 finobts *twice*
> during mount.
> 
> What the trace pointed out was that the finobt walk to calculate
> AG reserve space wasn't actually walking the finobt - it was walking
> the inobt. That indexes all allocated inodes, so mount was walking
> the btrees that index the ~30 million allocated inodes in the
> filesystem. That takes a lot of IO, and that's the 450s pause
> to calculate reserves before we run log recovery, and then the
> second 450s pause occurs after log recovery because we have to
> recalculate the reserves once all the intents and unlinked inodes
> have been replayed.
> 
>  From that observation, it was just a matter of tracking down the
> code that is triggering the walk and working out why it was running
> down the wrong inobt....
> 
> In hindsight, this was a wholly avoidable bug - a single patch made
> two different API modifications that only differed by a single
> letter, and one of the 23 conversions missed a single letter. If
> that was two patches - one for the finobt conversion, the second for
> the inobt conversion, the bug would have been plainly obvious during
> review....
> 
> Anders, can you try the patch below? It should fix your issue.
Works like a charm! Thanks for the help!

I take it that this patch goes into linux-stable (and linux-next) quite soon!

/Anders

Re: XFS mount timeout in linux-6.9.11

[Christoph Hellwig]

On Tue, Aug 13, 2024 at 07:19:28PM +1000, Dave Chinner wrote:
> In hindsight, this was a wholly avoidable bug - a single patch made
> two different API modifications that only differed by a single
> letter, and one of the 23 conversions missed a single letter. If
> that was two patches - one for the finobt conversion, the second for
> the inobt conversion, the bug would have been plainly obvious during
> review....

Maybe we should avoid identifiers that close anyway :)

The change looks good:

Reviewed-by: Christoph Hellwig <hch@lst.de>

Re: XFS mount timeout in linux-6.9.11

[Darrick J. Wong]

On Tue, Aug 13, 2024 at 04:59:25PM +0200, Christoph Hellwig wrote:
> On Tue, Aug 13, 2024 at 07:19:28PM +1000, Dave Chinner wrote:
> > In hindsight, this was a wholly avoidable bug - a single patch made
> > two different API modifications that only differed by a single
> > letter, and one of the 23 conversions missed a single letter. If
> > that was two patches - one for the finobt conversion, the second for
> > the inobt conversion, the bug would have been plainly obvious during
> > review....
> 
> Maybe we should avoid identifiers that close anyway :)
> 
> The change looks good:
> 
> Reviewed-by: Christoph Hellwig <hch@lst.de>

Looks good to me too
Reviewed-by: Darrick J. Wong <djwong@kernel.org>

--D

Re: XFS mount timeout in linux-6.9.11

[Anders Blomdell]

Anything I need to do to get this patch into the affected kernel versions?

/Anders

On 2024-08-13 17:25, Darrick J. Wong wrote:
> On Tue, Aug 13, 2024 at 04:59:25PM +0200, Christoph Hellwig wrote:
>> On Tue, Aug 13, 2024 at 07:19:28PM +1000, Dave Chinner wrote:
>>> In hindsight, this was a wholly avoidable bug - a single patch made
>>> two different API modifications that only differed by a single
>>> letter, and one of the 23 conversions missed a single letter. If
>>> that was two patches - one for the finobt conversion, the second for
>>> the inobt conversion, the bug would have been plainly obvious during
>>> review....
>>
>> Maybe we should avoid identifiers that close anyway :)
>>
>> The change looks good:
>>
>> Reviewed-by: Christoph Hellwig <hch@lst.de>
> 
> Looks good to me too
> Reviewed-by: Darrick J. Wong <djwong@kernel.org>
> 
> --D
> 

-- 
Since Lund University (allegedly due to insufficient funding/manpower) prohibits
sending email from Linux clients, mail from me will come from the address
anders.blomdell.at.control.lth.se@outlook.com.

Anders Blomdell                  Email: anders.blomdell@control.lth.se
Department of Automatic Control
Lund University                  Phone:    +46 46 222 8793
P.O. Box 118
SE-221 00 Lund, Sweden

Re: XFS mount timeout in linux-6.9.11

[Darrick J. Wong]

On Thu, Aug 22, 2024 at 12:25:03PM +0200, Anders Blomdell wrote:
> Anything I need to do to get this patch into the affected kernel versions?

Dave: Can you please (re)send this as a proper patch thread and ask
Chandan to add it to his fixes branch asap?

--D

> /Anders
> 
> On 2024-08-13 17:25, Darrick J. Wong wrote:
> > On Tue, Aug 13, 2024 at 04:59:25PM +0200, Christoph Hellwig wrote:
> > > On Tue, Aug 13, 2024 at 07:19:28PM +1000, Dave Chinner wrote:
> > > > In hindsight, this was a wholly avoidable bug - a single patch made
> > > > two different API modifications that only differed by a single
> > > > letter, and one of the 23 conversions missed a single letter. If
> > > > that was two patches - one for the finobt conversion, the second for
> > > > the inobt conversion, the bug would have been plainly obvious during
> > > > review....
> > > 
> > > Maybe we should avoid identifiers that close anyway :)
> > > 
> > > The change looks good:
> > > 
> > > Reviewed-by: Christoph Hellwig <hch@lst.de>
> > 
> > Looks good to me too
> > Reviewed-by: Darrick J. Wong <djwong@kernel.org>
> > 
> > --D
> > 
> 
> -- 
> Since Lund University (allegedly due to insufficient funding/manpower) prohibits
> sending email from Linux clients, mail from me will come from the address
> anders.blomdell.at.control.lth.se@outlook.com.
> 
> Anders Blomdell                  Email: anders.blomdell@control.lth.se
> Department of Automatic Control
> Lund University                  Phone:    +46 46 222 8793
> P.O. Box 118
> SE-221 00 Lund, Sweden
> 

Re: XFS mount timeout in linux-6.9.11

[David Woodhouse]

[-- Attachment #1: Type: text/plain, Size: 878 bytes --]

On Tue, 2024-08-13 at 08:25 -0700, Darrick J. Wong wrote:
> On Tue, Aug 13, 2024 at 04:59:25PM +0200, Christoph Hellwig wrote:
> > On Tue, Aug 13, 2024 at 07:19:28PM +1000, Dave Chinner wrote:
> > > In hindsight, this was a wholly avoidable bug - a single patch made
> > > two different API modifications that only differed by a single
> > > letter, and one of the 23 conversions missed a single letter. If
> > > that was two patches - one for the finobt conversion, the second for
> > > the inobt conversion, the bug would have been plainly obvious during
> > > review....
> > 
> > Maybe we should avoid identifiers that close anyway :)
> > 
> > The change looks good:
> > 
> > Reviewed-by: Christoph Hellwig <hch@lst.de>
> 
> Looks good to me too
> Reviewed-by: Darrick J. Wong <djwong@kernel.org>

Is it (now commit 95179935bea) going to -stable too?



[-- Attachment #2: smime.p7s --]
[-- Type: application/pkcs7-signature, Size: 5965 bytes --]

Re: XFS mount timeout in linux-6.9.11

[Greg KH]

On Wed, Sep 04, 2024 at 08:45:14AM +0100, David Woodhouse wrote:
> On Tue, 2024-08-13 at 08:25 -0700, Darrick J. Wong wrote:
> > On Tue, Aug 13, 2024 at 04:59:25PM +0200, Christoph Hellwig wrote:
> > > On Tue, Aug 13, 2024 at 07:19:28PM +1000, Dave Chinner wrote:
> > > > In hindsight, this was a wholly avoidable bug - a single patch made
> > > > two different API modifications that only differed by a single
> > > > letter, and one of the 23 conversions missed a single letter. If
> > > > that was two patches - one for the finobt conversion, the second for
> > > > the inobt conversion, the bug would have been plainly obvious during
> > > > review....
> > > 
> > > Maybe we should avoid identifiers that close anyway :)
> > > 
> > > The change looks good:
> > > 
> > > Reviewed-by: Christoph Hellwig <hch@lst.de>
> > 
> > Looks good to me too
> > Reviewed-by: Darrick J. Wong <djwong@kernel.org>
> 
> Is it (now commit 95179935bea) going to -stable too?

It's in the 6.10.y queue now, thanks!

greg k-h