From: zhuangel570 <zhuangel570@gmail.com>
To: paulmck@kernel.org, rcu@vger.kernel.org, josh@joshtriplett.org,
rostedt@goodmis.org, mathieu.desnoyers@efficios.com,
jiangshanlai@gmail.com
Cc: like.xu.linux@gmail.com, linussli@tencent.com, foxywang@tencent.com
Subject: SRCU: kworker hung in synchronize_srcu
Date: Thu, 28 Sep 2023 15:59:37 +0800 [thread overview]
Message-ID: <CANZk6aR+CqZaqmMWrC2eRRPY12qAZnDZLwLnHZbNi=xXMB401g@mail.gmail.com> (raw)
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
next reply other threads:[~2023-09-28 7:59 UTC|newest]
Thread overview: 28+ messages / expand[flat|nested] mbox.gz Atom feed top
2023-09-28 7:59 zhuangel570 [this message]
2023-09-28 21:39 ` SRCU: kworker hung in synchronize_srcu Joel Fernandes
2023-09-28 21:40 ` Joel Fernandes
2023-09-29 1:50 ` Zhouyi Zhou
2023-09-29 22:44 ` Frederic Weisbecker
2023-09-30 2:45 ` Neeraj upadhyay
2023-09-30 7:30 ` Frederic Weisbecker
2023-09-30 9:10 ` Frederic Weisbecker
2023-09-30 9:48 ` Neeraj upadhyay
2023-09-30 10:01 ` Neeraj upadhyay
2023-10-01 0:19 ` Joel Fernandes
2023-10-01 2:27 ` Neeraj upadhyay
2023-10-01 22:32 ` Frederic Weisbecker
2023-10-01 22:39 ` Frederic Weisbecker
2023-10-02 2:21 ` Neeraj upadhyay
2023-10-02 11:05 ` Frederic Weisbecker
2023-10-02 22:46 ` Frederic Weisbecker
2023-10-03 12:06 ` Neeraj upadhyay
2023-10-02 2:17 ` Neeraj upadhyay
2023-10-02 10:41 ` Frederic Weisbecker
2023-10-02 13:22 ` Neeraj upadhyay
2023-10-02 21:09 ` Frederic Weisbecker
2023-10-03 12:00 ` Neeraj upadhyay
2023-10-03 12:22 ` Frederic Weisbecker
2023-10-03 18:46 ` Neeraj upadhyay
2023-10-07 9:13 ` zhuangel570
2023-10-07 8:53 ` zhuangel570
2023-09-30 10:11 ` Neeraj upadhyay
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to='CANZk6aR+CqZaqmMWrC2eRRPY12qAZnDZLwLnHZbNi=xXMB401g@mail.gmail.com' \
--to=zhuangel570@gmail.com \
--cc=foxywang@tencent.com \
--cc=jiangshanlai@gmail.com \
--cc=josh@joshtriplett.org \
--cc=like.xu.linux@gmail.com \
--cc=linussli@tencent.com \
--cc=mathieu.desnoyers@efficios.com \
--cc=paulmck@kernel.org \
--cc=rcu@vger.kernel.org \
--cc=rostedt@goodmis.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).