RCU stall in xfs_reclaim_inodes_ag

RCU stall in xfs_reclaim_inodes_ag

[Alex Lyakas]

Greetings XFS community,

We had an RCU stall [1]. According to the code, it happened in 
radix_tree_gang_lookup_tag():

rcu_read_lock();
nr_found = radix_tree_gang_lookup_tag(
        &pag->pag_ici_root,
        (void **)batch, first_index,
        XFS_LOOKUP_BATCH,
        XFS_ICI_RECLAIM_TAG);


This XFS system has over 100M files. So perhaps looping inside the radix 
tree took too long, and it was happening in RCU read-side critical seciton. 
This is one of the possible causes for RCU stall.

This happened in kernel 4.14.99, but looking at latest mainline code, code 
is still the same.

Can anyone please advise how to address that? It is not possible to put 
cond_resched() inside the radix tree code, because it can be used with 
spinlocks, and perhaps other contexts where sleeping is not allowed.

Thanks,
Alex.


[1]
Nov 16 12:33:15.314001 vsa-0000002a-vc-1 kernel: [78961.809221] INFO: 
rcu_preempt detected stalls on CPUs/tasks:
Nov 16 12:33:15.314031 vsa-0000002a-vc-1 kernel: [78961.810785]     Tasks 
blocked on level-0 rcu_node (CPUs 0-4): P8854
Nov 16 12:33:15.314033 vsa-0000002a-vc-1 kernel: [78961.812141] 
(detected by 3, t=60004 jiffies, g=18947673, c=18947672, q=110854)
Nov 16 12:33:15.314036 vsa-0000002a-vc-1 kernel: [78961.814050] python 
R  running task        0  8854   8792 0x00000000
Nov 16 12:33:15.314038 vsa-0000002a-vc-1 kernel: [78961.814054] Call Trace:
Nov 16 12:33:15.314040 vsa-0000002a-vc-1 kernel: [78961.814067]  ? 
__schedule+0x290/0x8a0
Nov 16 12:33:15.314041 vsa-0000002a-vc-1 kernel: [78961.814070] 
preempt_schedule_irq+0x37/0x60
Nov 16 12:33:15.314043 vsa-0000002a-vc-1 kernel: [78961.814074] 
retint_kernel+0x1b/0x1d
Nov 16 12:33:15.314044 vsa-0000002a-vc-1 kernel: [78961.814079] RIP: 
0010:radix_tree_next_chunk+0x111/0x320
Nov 16 12:33:15.314045 vsa-0000002a-vc-1 kernel: [78961.814080] RSP: 
0018:ffffb31f5fbab7d0 EFLAGS: 00000287 ORIG_RAX: ffffffffffffff10
Nov 16 12:33:15.314047 vsa-0000002a-vc-1 kernel: [78961.814082] RAX: 
0000000000000033 RBX: 0000000000000010 RCX: 000000000000000c
Nov 16 12:33:15.314049 vsa-0000002a-vc-1 kernel: [78961.814083] RDX: 
0000000000000000 RSI: ffffb31f5fbab818 RDI: 00000000000b3000
Nov 16 12:33:15.314051 vsa-0000002a-vc-1 kernel: [78961.814084] RBP: 
ffffa07dd6d80b48 R08: ffffa08079fe56d0 R09: ffffa08079fe6481
Nov 16 12:33:15.314052 vsa-0000002a-vc-1 kernel: [78961.814085] R10: 
000000000000000c R11: ffffa08079fe5890 R12: 000000000000000c
Nov 16 12:33:15.314054 vsa-0000002a-vc-1 kernel: [78961.814086] R13: 
0000000000000040 R14: 0000000000000228 R15: 0000000000033000
Nov 16 12:33:15.314055 vsa-0000002a-vc-1 kernel: [78961.814090] 
radix_tree_gang_lookup_tag+0xd6/0x160
Nov 16 12:33:15.314056 vsa-0000002a-vc-1 kernel: [78961.814152] 
xfs_reclaim_inodes_ag+0xd5/0x310 [xfs]
Nov 16 12:33:15.314058 vsa-0000002a-vc-1 kernel: [78961.814199] 
xfs_reclaim_inodes_nr+0x3c/0x50 [xfs]
Nov 16 12:33:15.314059 vsa-0000002a-vc-1 kernel: [78961.814204] 
super_cache_scan+0x156/0x1a0
Nov 16 12:33:15.314061 vsa-0000002a-vc-1 kernel: [78961.814210] 
shrink_slab.part.51+0x1e8/0x400
Nov 16 12:33:15.314062 vsa-0000002a-vc-1 kernel: [78961.814213] 
shrink_node+0x123/0x310
Nov 16 12:33:15.314063 vsa-0000002a-vc-1 kernel: [78961.814216] 
do_try_to_free_pages+0xc3/0x330
Nov 16 12:33:15.314064 vsa-0000002a-vc-1 kernel: [78961.814218] 
try_to_free_pages+0xf4/0x1f0
Nov 16 12:33:15.314065 vsa-0000002a-vc-1 kernel: [78961.814224] 
__alloc_pages_slowpath+0x3a5/0xd50
Nov 16 12:33:15.314067 vsa-0000002a-vc-1 kernel: [78961.814228] 
__alloc_pages_nodemask+0x2a7/0x2d0
Nov 16 12:33:15.314068 vsa-0000002a-vc-1 kernel: [78961.814232] 
alloc_pages_vma+0x7c/0x1e0
Nov 16 12:33:15.314070 vsa-0000002a-vc-1 kernel: [78961.814236] 
__handle_mm_fault+0x90c/0x12f0
Nov 16 12:33:15.314071 vsa-0000002a-vc-1 kernel: [78961.814239] 
handle_mm_fault+0xb1/0x1e0
Nov 16 12:33:15.314072 vsa-0000002a-vc-1 kernel: [78961.814244] 
__do_page_fault+0x278/0x530
Nov 16 12:33:15.314073 vsa-0000002a-vc-1 kernel: [78961.814247]  ? 
async_page_fault+0x2f/0x50
Nov 16 12:33:15.314074 vsa-0000002a-vc-1 kernel: [78961.814248] 
async_page_fault+0x45/0x50

Re: RCU stall in xfs_reclaim_inodes_ag

[Dave Chinner]

On Mon, Nov 16, 2020 at 07:45:46PM +0200, Alex Lyakas wrote:
> Greetings XFS community,
> 
> We had an RCU stall [1]. According to the code, it happened in
> radix_tree_gang_lookup_tag():
> 
> rcu_read_lock();
> nr_found = radix_tree_gang_lookup_tag(
>        &pag->pag_ici_root,
>        (void **)batch, first_index,
>        XFS_LOOKUP_BATCH,
>        XFS_ICI_RECLAIM_TAG);
> 
> 
> This XFS system has over 100M files. So perhaps looping inside the radix
> tree took too long, and it was happening in RCU read-side critical seciton.
> This is one of the possible causes for RCU stall.

Doubt it. According to the trace it was stalled for 60s, and a
radix tree walk of 100M entries only takes a second or two.

Further, unless you are using inode32, the inodes will be spread
across multiple radix trees and that makes the radix trees much
smaller and even less likely to take this long to run a traversal.

This could be made a little more efficient by adding a "last index"
parameter to tell the search where to stop (i.e. if the batch count
has not yet been reached), but in general that makes little
difference to the search because the radix tree walk finds the next
inodes in a few pointer chases...

> This happened in kernel 4.14.99, but looking at latest mainline code, code
> is still the same.

These inode radix trees have been used in XFS since 2008, and this
is the first time anyone has reported a stall like this, so I'm
doubtful that there is actually a general bug. My suspicion for such
a rare occurrence would be memory corruption of some kind or a
leaked atomic/rcu state in some other code on that CPU....

> Can anyone please advise how to address that? It is not possible to put
> cond_resched() inside the radix tree code, because it can be used with
> spinlocks, and perhaps other contexts where sleeping is not allowed.

I don't think there is a solution to this problem - it just
shouldn't happen in when everything is operating normally as it's
just a tag search on an indexed tree.

Hence even if there was a hack to stop stall warnings, it won't fix
whatever problem is leading to the rcu stall. The system will then
just spin burning CPU, and eventually something else will fail.

IOWs, unless you can reproduce this stall and find out what is wrong
in the radix tree that is leading to it looping forever, there's
likely nothing we can do to avoid this.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com

Re: RCU stall in xfs_reclaim_inodes_ag

[Alex Lyakas]

Hi Dave,

Thank you for your response.

We did some more investigations on the issue, and we have the following 
findings:

1) We tracked the max amount of inodes per AG radix tree. We found in our 
tests, that the max amount of inodes per AG radix tree was about 1.5M:
[xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384662 
reclaimable=58
[xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384630 
reclaimable=46
[xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384600 
reclaimable=16
[xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594500 
reclaimable=75
[xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594468 
reclaimable=55
[xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594436 
reclaimable=46
[xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594421 
reclaimable=42
(but the amount of reclaimable inodes is very small, as you can see).

Do you think this number is reasonable per radix tree?

2) This particular XFS instance is total of 500TB. However, the AG size in 
this case is 100GB. This is the AG size that we use, due to issues that we 
reported in https://www.spinics.net/lists/linux-xfs/msg06501.html,
where the "near" allocation algorithm was stuck for a long time scanning the 
free-space btrees. With smaller AG size, we don't see such issues.
But with 500TB filesystem, we now have 5000 AGs. As a result, we suspect 
(due to some instrumentation), that the looping over 5000 AGs in 
xfs_reclaim_inodes_ag() is what is causing the RCU stall for us. Although 
the code has cond_resched() call, but somehow the RCU stall still happens, 
and it always happens in this function, while searching the radix tree.

Thanks,
Alex.



-----Original Message----- 
From: Dave Chinner
Sent: Monday, November 16, 2020 11:30 PM
To: Alex Lyakas
Cc: linux-xfs@vger.kernel.org
Subject: Re: RCU stall in xfs_reclaim_inodes_ag

On Mon, Nov 16, 2020 at 07:45:46PM +0200, Alex Lyakas wrote:
> Greetings XFS community,
>
> We had an RCU stall [1]. According to the code, it happened in
> radix_tree_gang_lookup_tag():
>
> rcu_read_lock();
> nr_found = radix_tree_gang_lookup_tag(
>        &pag->pag_ici_root,
>        (void **)batch, first_index,
>        XFS_LOOKUP_BATCH,
>        XFS_ICI_RECLAIM_TAG);
>
>
> This XFS system has over 100M files. So perhaps looping inside the radix
> tree took too long, and it was happening in RCU read-side critical 
> seciton.
> This is one of the possible causes for RCU stall.

Doubt it. According to the trace it was stalled for 60s, and a
radix tree walk of 100M entries only takes a second or two.

Further, unless you are using inode32, the inodes will be spread
across multiple radix trees and that makes the radix trees much
smaller and even less likely to take this long to run a traversal.

This could be made a little more efficient by adding a "last index"
parameter to tell the search where to stop (i.e. if the batch count
has not yet been reached), but in general that makes little
difference to the search because the radix tree walk finds the next
inodes in a few pointer chases...

> This happened in kernel 4.14.99, but looking at latest mainline code, code
> is still the same.

These inode radix trees have been used in XFS since 2008, and this
is the first time anyone has reported a stall like this, so I'm
doubtful that there is actually a general bug. My suspicion for such
a rare occurrence would be memory corruption of some kind or a
leaked atomic/rcu state in some other code on that CPU....

> Can anyone please advise how to address that? It is not possible to put
> cond_resched() inside the radix tree code, because it can be used with
> spinlocks, and perhaps other contexts where sleeping is not allowed.

I don't think there is a solution to this problem - it just
shouldn't happen in when everything is operating normally as it's
just a tag search on an indexed tree.

Hence even if there was a hack to stop stall warnings, it won't fix
whatever problem is leading to the rcu stall. The system will then
just spin burning CPU, and eventually something else will fail.

IOWs, unless you can reproduce this stall and find out what is wrong
in the radix tree that is leading to it looping forever, there's
likely nothing we can do to avoid this.

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com 

Re: RCU stall in xfs_reclaim_inodes_ag

[Brian Foster]

On Mon, Dec 07, 2020 at 12:18:13PM +0200, Alex Lyakas wrote:
> Hi Dave,
> 
> Thank you for your response.
> 
> We did some more investigations on the issue, and we have the following
> findings:
> 
> 1) We tracked the max amount of inodes per AG radix tree. We found in our
> tests, that the max amount of inodes per AG radix tree was about 1.5M:
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384662
> reclaimable=58
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384630
> reclaimable=46
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384600
> reclaimable=16
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594500
> reclaimable=75
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594468
> reclaimable=55
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594436
> reclaimable=46
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594421
> reclaimable=42
> (but the amount of reclaimable inodes is very small, as you can see).
> 
> Do you think this number is reasonable per radix tree?
> 
> 2) This particular XFS instance is total of 500TB. However, the AG size in
> this case is 100GB. This is the AG size that we use, due to issues that we
> reported in https://www.spinics.net/lists/linux-xfs/msg06501.html,
> where the "near" allocation algorithm was stuck for a long time scanning the
> free-space btrees. With smaller AG size, we don't see such issues.
> But with 500TB filesystem, we now have 5000 AGs. As a result, we suspect
> (due to some instrumentation), that the looping over 5000 AGs in
> xfs_reclaim_inodes_ag() is what is causing the RCU stall for us. Although
> the code has cond_resched() call, but somehow the RCU stall still happens,
> and it always happens in this function, while searching the radix tree.
> 

Just a quick bit on the near more allocation algorithm.. the report at
the provided link refers to a v3.18 kernel, which apparently was old
even at the time of the report. Regardless, the allocation algorithm was
reworked in commit dc8e69bd7218 ("xfs: optimize near mode bnobt scans
with concurrent cntbt lookups") to address this kind of problem. That
patch landed in v5.5. It might be worth trying that to see if it allows
you to unroll the AG size mitigation (which seems to have just
transferred the original inefficiency from the allocation code to
management of excessive AG counts)...

Brian

> Thanks,
> Alex.
> 
> 
> 
> -----Original Message----- From: Dave Chinner
> Sent: Monday, November 16, 2020 11:30 PM
> To: Alex Lyakas
> Cc: linux-xfs@vger.kernel.org
> Subject: Re: RCU stall in xfs_reclaim_inodes_ag
> 
> On Mon, Nov 16, 2020 at 07:45:46PM +0200, Alex Lyakas wrote:
> > Greetings XFS community,
> > 
> > We had an RCU stall [1]. According to the code, it happened in
> > radix_tree_gang_lookup_tag():
> > 
> > rcu_read_lock();
> > nr_found = radix_tree_gang_lookup_tag(
> >        &pag->pag_ici_root,
> >        (void **)batch, first_index,
> >        XFS_LOOKUP_BATCH,
> >        XFS_ICI_RECLAIM_TAG);
> > 
> > 
> > This XFS system has over 100M files. So perhaps looping inside the radix
> > tree took too long, and it was happening in RCU read-side critical
> > seciton.
> > This is one of the possible causes for RCU stall.
> 
> Doubt it. According to the trace it was stalled for 60s, and a
> radix tree walk of 100M entries only takes a second or two.
> 
> Further, unless you are using inode32, the inodes will be spread
> across multiple radix trees and that makes the radix trees much
> smaller and even less likely to take this long to run a traversal.
> 
> This could be made a little more efficient by adding a "last index"
> parameter to tell the search where to stop (i.e. if the batch count
> has not yet been reached), but in general that makes little
> difference to the search because the radix tree walk finds the next
> inodes in a few pointer chases...
> 
> > This happened in kernel 4.14.99, but looking at latest mainline code, code
> > is still the same.
> 
> These inode radix trees have been used in XFS since 2008, and this
> is the first time anyone has reported a stall like this, so I'm
> doubtful that there is actually a general bug. My suspicion for such
> a rare occurrence would be memory corruption of some kind or a
> leaked atomic/rcu state in some other code on that CPU....
> 
> > Can anyone please advise how to address that? It is not possible to put
> > cond_resched() inside the radix tree code, because it can be used with
> > spinlocks, and perhaps other contexts where sleeping is not allowed.
> 
> I don't think there is a solution to this problem - it just
> shouldn't happen in when everything is operating normally as it's
> just a tag search on an indexed tree.
> 
> Hence even if there was a hack to stop stall warnings, it won't fix
> whatever problem is leading to the rcu stall. The system will then
> just spin burning CPU, and eventually something else will fail.
> 
> IOWs, unless you can reproduce this stall and find out what is wrong
> in the radix tree that is leading to it looping forever, there's
> likely nothing we can do to avoid this.
> 
> Cheers,
> 
> Dave.
> -- 
> Dave Chinner
> david@fromorbit.com
> 

Re: RCU stall in xfs_reclaim_inodes_ag

[Dave Chinner]

On Mon, Dec 07, 2020 at 12:18:13PM +0200, Alex Lyakas wrote:
> Hi Dave,
> 
> Thank you for your response.
> 
> We did some more investigations on the issue, and we have the following
> findings:
> 
> 1) We tracked the max amount of inodes per AG radix tree. We found in our
> tests, that the max amount of inodes per AG radix tree was about 1.5M:
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384662
> reclaimable=58
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384630
> reclaimable=46
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1368]: count=1384600
> reclaimable=16
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594500
> reclaimable=75
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594468
> reclaimable=55
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594436
> reclaimable=46
> [xfs_reclaim_inodes_ag:1285] XFS(dm-79): AG[1370]: count=1594421
> reclaimable=42
> (but the amount of reclaimable inodes is very small, as you can see).
> 
> Do you think this number is reasonable per radix tree?

That's fine. I regularly run tests that push 10M+ inodes into a
single radix tree, and that generally doesn't even show up on the
profiles....

> 2) This particular XFS instance is total of 500TB. However, the AG size in
> this case is 100GB.

Ok. I run scalability tests on 500TB filesystems with 500AGs that
hammer inode reclaim, but it should be trivial to run them with
5000AGs. Hell, let's just run 50,000AGs to see if there's actually
an iteration problem in the shrinker...

(we really need async IO in mkfs for doing things like this!)

Yup, that hurts a bit on 5.10-rc7, but not significantly. Profile
with 16 CPUs turning over 250,000 inodes/s through the cache:

       - 3.17% xfs_fs_free_cached_objects                                                                                                         ▒
	  - xfs_reclaim_inodes_nr                                                                                                                 ▒
	     - 3.09% xfs_reclaim_inodes_ag                                                                                                        ▒
		- 0.91% _raw_spin_lock                                                                                                            ▒
		     0.87% do_raw_spin_lock                                                                                                       ▒
		- 0.71% _raw_spin_unlock                                                                                                          ▒
		   - 0.67% do_raw_spin_unlock                                                                                                     ▒
			__raw_callee_save___pv_queued_spin_unlock

Which indicate spinlocks are the largest CPU user in that path.
That's likley the radix tree spin locks when removing inodes from
the AG because the upstream code now allows multiple reclaimers to
operate on the same AG.

But even with that, there isn't any sign of holdoff latencies,
scanning delays, etc occurring inside the RCU critical section.
IOWs, bumping up the number of AGs massively shouldn't impact the
RCU code here as the RCU crictical region is inside the loop over
the AGs, not spanning the loop.

I don't know how old your kernel is, but maybe something is getting
stuck on a spinlock (per-inode or per-ag) inside the RCU section?
i.e. maybe you see a RCU stall because the code has livelocked or
has severe contention on a per-ag or inode spinlock inside the RCU
section?

I suspect you are going to need to profile the code when it is
running to some idea of what it is actually doing when the stalls
occur...

Cheers,

Dave.
-- 
Dave Chinner
david@fromorbit.com