On Fri, Sep 29, 2023 at 5:39 AM Joel Fernandes <joel@xxxxxxxxxxxxxxxxx> wrote:
>
> Hello,
> Firstly, kudos to the detailed report and analysis. Rare failures are
> hard and your usage crash/kdump is awesome to dig deeper into the
> issue..
>
> On Thu, Sep 28, 2023 at 3:59 AM zhuangel570 <zhuangel570@xxxxxxxxx> wrote:
> >
> > Hi,
> >
> > We encounter SRCU hung issue in stable tree 5.4.203, we are running VM create
> > and destroy concurrent test, the issue happens after several weeks. Now we
> > didn't have a way to reproduce this issue, the issue happens randomly, this
> > is the second time we found it in this year.
> >
> > We did some investigation with crash tools, hope to get some useful clues
> > about the issue, try to find root cause of the issue (further find a way to
> > fix or workaround it), here is some of our investigation, hope to get
> > feedback from SRCU experts.
> >
> > [3144162.608392] INFO: task kworker/136:12:252684 blocked for more
> > than 122 seconds.
> > [3144162.615986] Tainted: G O K 5.4.203-1-tlinux4-0011.1 #1
> > [3144162.623053] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> > disables this message.
> > [3144162.631162] kworker/136:12 D 0 252684 2 0x90004000
> > [3144162.631189] Workqueue: kvm-irqfd-cleanup irqfd_shutdown [kvm]
> > [3144162.631192] Call Trace:
> > [3144162.631202] __schedule+0x2ee/0x660
> > [3144162.631206] schedule+0x33/0xa0
> > [3144162.631209] schedule_timeout+0x1c4/0x340
> > [3144162.631214] ? update_load_avg+0x82/0x660
> > [3144162.631217] ? raw_spin_rq_lock_nested+0x1f/0x30
> > [3144162.631218] wait_for_completion+0x119/0x180
> > [3144162.631220] ? wake_up_q+0x80/0x80
> > [3144162.631224] __synchronize_srcu.part.19+0x81/0xb0
> > [3144162.631226] ? __bpf_trace_rcu_utilization+0x10/0x10
> > [3144162.631227] synchronize_srcu+0x5f/0xc0
> > [3144162.631236] irqfd_shutdown+0x3c/0xb0 [kvm]
> > [3144162.631239] ? __schedule+0x2f6/0x660
> > [3144162.631243] process_one_work+0x19a/0x3a0
> > [3144162.631244] worker_thread+0x37/0x3a0
> > [3144162.631247] kthread+0x117/0x140
> > [3144162.631247] ? process_one_work+0x3a0/0x3a0
> > [3144162.631248] ? __kthread_cancel_work+0x40/0x40
> > [3144162.631250] ret_from_fork+0x1f/0x30
> >
> > Test workload:
> > - Repeated concurrency testing, include Create VM, service probe, destroy VM.
> > - VM using virito device, so kvm->irq_srcu is using frequently.
> > - x86_64 Machine with 191 core.
> >
> > Crash analysis clues:
> > - The hung task is run on CPU 136, waiting synchronize_srcu to be completed.
> > - The current GP of SRCU struct is 304 (srcu_gp_seq and srcu_gp_seq_needed).
> > - The SNP (node) of SRCU struct has 2 levels.
> > - The SNP (node) of SRCU struct show all SNP now in GP 304 (srcu_have_cbs).
> > - The SNP (node) of SRCU struct show CPU 136 belongs to group [128,143].
> > - The SDP (per-cpu) of SRCU struct show lock and unlock matches.
> > - The SDP (per-cpu) of CPU 136 segcblist has one entry in pending list.
> > - The pending entry is just the calling entry of hung kwoker task.
> > - The SDP (per-cpu) of CPU 136 is waiting GP 288, gp_seq of segcblist is 296.
> > - The SDP (per-cpu) of CPU 136 segcblist has no entry in DONE list.
> > - The work-queue of SRCU and SDP of CPU 136 is idle.
> > - More details could be found via reference at the end of this mail.
> >
> > crash> struct srcu_struct.srcu_idx,srcu_gp_seq,srcu_gp_seq_needed,srcu_gp_seq_needed_exp,sda
> > 0xffffc900f100e878
> > srcu_idx = 76
> > srcu_gp_seq = 304
> > srcu_gp_seq_needed = 304
> > srcu_gp_seq_needed_exp = 304
> > sda = 0x5fff9ac17800
> >
> > crash> struct srcu_data 0x5fff9ac17800:136
> > [136]: ffffe8bee9817800
> > ...
> > srcu_cblist = {
> > head = 0xffffc900e8413dd0,
> > tails = {0xffffe8bee9817848, 0xffffc900e8413dd0,
> > 0xffffc900e8413dd0, 0xffffc900e8413dd0},
> > gp_seq = {0, 296, 296, 0},
>
> I am actually a bit puzzled why the DONE segment count is 0. I would
> have expected it to be >= 296 in this situation.
The gp_seq of segcblist will only be updated in rcu_segcblist_accelerate
and rcu_segcblist_advance, and the update logic does not include DONE and
NEXT tail, so I think the seq of DONE and NEXT should always be zero.
>
> > len = 1,
> > len_lazy = 0,
> > enabled = 1 '\001',
> > offloaded = 0 '\000'
> > },
> > srcu_gp_seq_needed = 288,
> > srcu_gp_seq_needed_exp = 0,
> > srcu_cblist_invoking = false,
> > ...
> >
> > Root cause (we can't reproduce the issue, so the result is base on crash
> > analysis and code analysis):
> > - The leaked entry on segcblist has incorrect gp_seq (SDP is waiting 288).
> > - The leaked entry on segcblist seems has been "accelerated".
> > - The incorrect accelerate maybe caused by srcu_invoke_callbacks, because
> > srcu_invoke_callbacks may be using incorrect GP seq doing accelerate.
> > - Here are two emulated case may cause the "accelerate issue":
> >
> >
> > CASE1: entry of CPU 136 belongs to GP 288 was accelerated to GP 292
> > - [CPU 136] [GP 280-284] finished, yet not enter srcu_invoke_callbacks.
> > - [CPU 136] [GP 284-288] starting, new synchronize_srcu request, queue entry
> > to SDP.
> > - [CPU 041] [GP 284-288] starting, new synchronize_srcu request, workload run
> > faster than CPU 136, start GP, set rcu_seq_start.
> > - [CPU 136] [GP 284-288] starting, call srcu_funnel_gp_start, found no need
> > to start GP.
> > - [CPU 136] [GP 280-284] finished, start to run srcu_invoke_callbacks,
> > "accelerate" the seq of new added entry to 292 (it should be 288).
>
> But srcu_gp_seq is at 304 right now. How does it matter that the CB is
> marked for 292? It should be ready to execute anyway even at 292. Note
> the meaning of "acceleration", the idea is to start conservatively and
> move the callbacks forward as more accurate information is available.
> Considering this, 292 initially should be OK IMHO (that's just more
> conservative than 288)..
As Neeraj explained, the callback is manged under SDP (per-CPU), but CBs are
managed under SNP (group of CPU).
>
> > CASE2: entry of CPU 136 belongs to GP 288 was accelerated to GP 296
> > - [CPU 136] [GP 280-284] finished, yet not enter srcu_invoke_callbacks.
> > - [CPU 136] [GP 284-288] starting, new synchronize_srcu request, queue entry
> > to SDP.
> > - [CPU 041] [GP 284-288] starting, new synchronize_srcu request, workload run
> > faster than CPU 136, start GP.
> > - [CPU 041] [GP 284-288] finished, workload run faster, finish GP.
> > - [CPU 136] [GP 284-288] starting, call srcu_funnel_gp_start, found no need
> > to start GP.
> > - [CPU 017] [GP 288-292] starting, new synchronize_srcu request, start GP,
> > set rcu_seq_start.
> > - [CPU 136] [GP 280-284] finished, start to run srcu_invoke_callbacks,
> > "accelerate" new added entry to 296 (it should be 288).
>
> I had the same analysis here.
>
> > /*
> > * CASE1
> > * - entry of CPU 136 expecting GP 288 was accelerated to GP 292
> > * - GP0: 280-284, GP1: 284-288.
> > */
> >
> > /* [GP0][CPU-136] */
> > process_srcu {
> > srcu_gp_end
> > }
> > /* [GP1][CPU-136] */
> > synchronize_srcu {
> > __call_srcu {
> > rcu_segcblist_enqueue
> > /* [GP1][CPU-041] */
> > synchronize_srcu {
> > __call_srcu {
> > srcu_funnel_gp_start
> > srcu_gp_start
> > rcu_seq_start
> > }
> > }
> > /* [GP1][CPU-136] */
> > srcu_funnel_gp_start
> > }
> > }
> > /* [GP0][CPU-136] */
> > srcu_invoke_callbacks {
> > rcu_segcblist_accelerate
> > }
> >
> >
> > /*
> > * CASE2
> > * - entry of CPU 136 belongs to GP 288 was accelerated to GP 296.
> > * - GP0: 280-284, GP1: 284-288, GP2: 288-292.
> > */
> >
> > /* [GP0][CPU-136] */
> > process_srcu {
> > srcu_gp_end
> > }
> >
> > /* [GP1][CPU-136] */
> > synchronize_srcu {
> > __call_srcu {
> > rcu_segcblist_enqueue
> > /* [GP1][CPU-041] */
> > synchronize_srcu {
> > __call_srcu {
> > srcu_funnel_gp_start
> > srcu_gp_start
> > }
> > }
> > process_srcu {
> > srcu_gp_end
> > rcu_seq_end
> > }
> > /* [GP1][CPU-136] */
> > srcu_funnel_gp_start
> > }
> > }
> > /* [GP0][CPU-136] */
> > srcu_invoke_callbacks {
>
> If srcu_invoke_callbacks() was really called for the rdp, I would have
> expected rcu_segcblist_advance() to advance all those pending
> callbacks to 304.
>
> I posit that probably srcu_invoke_callbacks() is not even being called
> in the first place, otherwise why is the DONE segment count still 0?
> DONE should not be 0, otherwise callbacks will not run. The segcblist
> of the rdp seems out of date perhaps due to rcu_invoke_callbacks() not
> being called due to some other bug (or a workqueue/timer issue causing
> the srcu_invoke_callbacks() to not run?).
There are no other system error messages and the system is running fine
except for KVM related operations such as destroying the VM (this is
because the SRCU hang is blocking the KVM global work queue). So I'd
rather think there's a bug in SRCU and the analysis shows there may be
a race issue.
>
> I wonder if you would consider trying to reproduce it with the
> rcutorture module's SRCU testing in the chance that it occurs with it
> on your setup.
>
> thanks,
>
> - Joel
>
>
> > /* [GP2][CPU-017] */
> > synchronize_srcu {
> > __call_srcu {
> > srcu_funnel_gp_start
> > srcu_gp_start
> > rcu_seq_start
> > }
> > }
> > /* [GP0][CPU-136] */
> > rcu_segcblist_accelerate
> > }
> >
> >
> > Potential fix:
> > We shouldn't accelerate the segcblist in srcu_invoke_callbacks base snapshot
> > of current gp seq of SRCU struct, how about accelerate the sda base
> > sdp->srcu_gp_seq_needed, maybe like this:
> >
> >
> > diff --git a/kernel/rcu/srcutree.c b/kernel/rcu/srcutree.c
> > index 21115ffb6c44..ff8579abc924 100644
> > --- a/kernel/rcu/srcutree.c
> > +++ b/kernel/rcu/srcutree.c
> > @@ -1197,7 +1197,7 @@ static void srcu_invoke_callbacks(struct
> > work_struct *work)
> > spin_lock_irq_rcu_node(sdp);
> > rcu_segcblist_insert_count(&sdp->srcu_cblist, &ready_cbs);
> > (void)rcu_segcblist_accelerate(&sdp->srcu_cblist,
> > - rcu_seq_snap(&ssp->srcu_gp_seq));
> > + rcu_seq_snap(&sdp->srcu_gp_seq_needed));
> > sdp->srcu_cblist_invoking = false;
> > more = rcu_segcblist_ready_cbs(&sdp->srcu_cblist);
> > spin_unlock_irq_rcu_node(sdp);
>
> I think "rcu_seq_snap(&ssp->srcu_gp_seq))" is correct IMHO,
> rcu_seq_snap() says which what's the gp_seq at which a full GP has
> passed from the moment rcu_seq_snap() is called. That's precisely when
> it is safe to call all those non-accelerated callbacks.
>
> Basically, if any of the bits are set in the state portion of the
> sequence of the gp_seq number, then it returns (COUNTER_PORTION + 2)
> << RCU_SEQ_CTR_SHIFT.
> Otherwise, it returns (COUNTER_PORTION + 1) << RCU_SEQ_CTR_SHIFT.
>
>
>
>
>
> >
> >
> > Thanks for reading!
> >
> >
> > Reference detail log of crash dump information:
> > https://raw.githubusercontent.com/zhuangel/misc/main/debug/srcu_hung/bt.f.252684.log
> > https://raw.githubusercontent.com/zhuangel/misc/main/debug/srcu_hung/irq_srcu.partial.log
> > https://raw.githubusercontent.com/zhuangel/misc/main/debug/srcu_hung/irq_srcu.raw.log
> > https://raw.githubusercontent.com/zhuangel/misc/main/debug/srcu_hung/irq_srcu.sda.lock.log
> > https://raw.githubusercontent.com/zhuangel/misc/main/debug/srcu_hung/irq_srcu.sda.raw.log
--
——————————
zhuangel570
——————————
