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},
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).
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).
/*
* 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 {
/* [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);
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
