From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from stravinsky.debian.org (stravinsky.debian.org [82.195.75.108]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 2188D3C197E for ; Mon, 10 Aug 2026 11:31:23 +0000 (UTC) Authentication-Results: smtp.subspace.kernel.org; arc=none smtp.client-ip=82.195.75.108 ARC-Seal:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1786361485; cv=none; b=s+gI2FMYMAM1PrC9pkTMrkB7M7/v0H+wb4WLjg5SO+AUKcdBrG5jq0wW5ntYhK+Uosqfk9TyEIeoOApgpQEG8ZQqX3Sw67DCXsCN4WcMUxcscMzlhBd6KDBIHmmatfGM1/JKtBXwPSOcjPdv5ID4jB2X/KCjynn5Yz8ouJv1rGU= ARC-Message-Signature:i=1; a=rsa-sha256; d=subspace.kernel.org; s=arc-20240116; t=1786361485; c=relaxed/simple; bh=UBzg63/2N1mzgAab5bdr1tIaH6KgwUvGi23oBtwkdm0=; h=From:Date:Subject:MIME-Version:Content-Type:Message-Id:References: In-Reply-To:To:Cc; b=tk6XUB9gcJhFSe0OpidV2fnRRZuWiqtj3/iikeiZkC5/5kj7fnd5e9DJ7j7FNmW8hQTResyKWcJ39fi1U/RsTfvF0ANq/N56+8+cfJ83RPjMMTdp8jzIMBIWdCTSmcVpl2Rdjqi5HyWTuH53RsewJugv4LthWySu7NarltO5vps= ARC-Authentication-Results:i=1; smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=debian.org; spf=pass smtp.mailfrom=debian.org; dkim=pass (2048-bit key) header.d=debian.org header.i=@debian.org header.b=I6pPP8b+; arc=none smtp.client-ip=82.195.75.108 Authentication-Results: smtp.subspace.kernel.org; dmarc=pass (p=none dis=none) header.from=debian.org Authentication-Results: smtp.subspace.kernel.org; spf=pass smtp.mailfrom=debian.org Authentication-Results: smtp.subspace.kernel.org; dkim=pass (2048-bit key) header.d=debian.org header.i=@debian.org header.b="I6pPP8b+" DKIM-Signature: v=1; a=rsa-sha256; q=dns/txt; c=relaxed/relaxed; d=debian.org; s=smtpauto.stravinsky; h=X-Debian-User:Cc:To:In-Reply-To:References: Message-Id:Content-Transfer-Encoding:Content-Type:MIME-Version:Subject:Date: From:Reply-To:Content-ID:Content-Description; bh=MN0xfPztgxg2Gg0bh5XmoEswYR1K6oRv9+HujuAICEQ=; b=I6pPP8b+6Ttki9WFSxb5ruvGui GoSlv/EzIkKWhF6ZkLaw16UwtaMG2yf6TfKrBjJoHobKZNoNx3MtNmYbFoM4Jmurid6kXY4QI+qba 0MI2YexxP6Eo1PTPXlKPYDSUqUBgsZtwmceQ/HhocTzaqJHx6mNqlBg43VCy3Vg4pc9Q1JaMa3McR r4HCLHmcntJxQmLVwfy0qq+YQGcgMn3C9jYzaLKdPlRfG4ZlttC7qofoMNg24+syP7DO4pxZXfvdo v93ljyg8msVPnxzeCouRNtVwMT8/tOsOTqNNwcb2StqdzvegWoQtE7AFa2/zVvB3VXDqLeEqEJRDE rJwE2zxg==; Received: from authenticated-user by stravinsky.debian.org with esmtpsa (TLS1.3:ECDHE_X25519__RSA_PSS_RSAE_SHA256__AES_256_GCM:256) (Exim 4.96) (envelope-from ) id 1wtODu-002if7-2Q; Mon, 10 Aug 2026 11:31:19 +0000 From: Breno Leitao Date: Mon, 10 Aug 2026 04:29:25 -0700 Subject: [PATCH v2 2/3] locking/csd-lock: Report how long a stuck CSD lock took to recover Precedence: bulk X-Mailing-List: linux-kernel@vger.kernel.org List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 Content-Type: text/plain; charset="utf-8" Content-Transfer-Encoding: 7bit Message-Id: <20260810-csd-stall-duration-v2-2-795083bf04a4@debian.org> References: <20260810-csd-stall-duration-v2-0-795083bf04a4@debian.org> In-Reply-To: <20260810-csd-stall-duration-v2-0-795083bf04a4@debian.org> To: paulmck@kernel.org, Andrew Morton , d@ilvokhin.com Cc: linux-kernel@vger.kernel.org, Peter Zijlstra , Ingo Molnar , Sebastian Andrzej Siewior , linux-kernel@vger.kernel.org, kernel-team@meta.com, Thomas Gleixner , Breno Leitao X-Mailer: b4 0.16-dev-f8e9d X-Developer-Signature: v=1; a=openpgp-sha256; l=3201; i=leitao@debian.org; h=from:subject:message-id; bh=UBzg63/2N1mzgAab5bdr1tIaH6KgwUvGi23oBtwkdm0=; b=owEBbQKS/ZANAwAIATWjk5/8eHdtAcsmYgBqebZxd57YC56uaNF9o1WtmoW433JIa6e3w0Avx cui/UGcSReJAjMEAAEIAB0WIQSshTmm6PRnAspKQ5s1o5Of/Hh3bQUCanm2cQAKCRA1o5Of/Hh3 bUybD/0a02ZFS/PrXL5vGteXO+ZYt0pJer7dpgF1A8Arid4iXUopKZdQENG2FTnlPOiDCbQqM90 Q5WQWHcRymGwyDwp9oVVj0Bu/1osGfmRE0ejMLN8BBd5Pd66bfTyC5WYlupd0iT+Pty1WJwvmNq hPWyVEis+mLVSOm82gIrII22jDA+15JofYF+vkiSy7hZyul8emM1ktlhmmVeDewozHLBSfvYsI4 mJDrHYdSg7fGyIUhVSaCAwcdxXhrHSfZRI+OHR7ZvyTmTv4ZJh9KQgoYXAlG8mj+wo0vVXZY/jl H4cyUiW+eep0ijlwRfpRi6WKL5JCoh/0QwaJd2wT3+puwyaQUoPPcgZLR2UoJBwB7OKI1Q87xIa qtCWhdYLM7xakX+R69DrulcozuKhDhkpVkmWA0geIe4QL+uP6D3LoSber8mJbrCnaOKH3rSjuGh dYEloj34byOilDRj8W5BtLIW1ByKLduKSWCB3d3fQyYCWuEOdvzQyk61GHpZnlEkPCw3QE74gua AF75HMBpAHD4K6GA7bQN5aUnvVJlQVagRu2VIG4+1ylPU80afihZOEMBbIrkhRJgBnjm2lgxgVa VUvB0s2OcqkyCndAPV408O/ofiWx8Z483Lae6hdCf85rkViB9RK1fZCvspua2W7z0qxughDCLDA wEtjaasYyAv7BTA== X-Developer-Key: i=leitao@debian.org; a=openpgp; fpr=AC8539A6E8F46702CA4A439B35A3939FFC78776D X-Debian-User: leitao The CSD lock debug output is a useful way to catch IPI stalls, but when the lock finally recovers it only says that it did: smp: csd: CSD lock (#1) got unstuck on CPU#32, CPU#123 released the lock. How long the target took to answer is left out, even though csd_lock_wait_toolong() already has the timestamp the wait started from. At Meta's fleet, that line fired 211K times in the last 24 hours, so plenty of stalls get reported with no indication of how long they lasted. Print how long the lock was stuck, and, when an IPI was re-sent, how long after that re-send the target released, as: smp: csd: CSD lock (#1) got unstuck on CPU#00, CPU#01 released the lock after 8000854660 ns, 3000825778 ns after the last IPI re-send. Signed-off-by: Breno Leitao Reviewed-by: Dmitry Ilvokhin --- kernel/smp.c | 23 +++++++++++++++++++++-- 1 file changed, 21 insertions(+), 2 deletions(-) diff --git a/kernel/smp.c b/kernel/smp.c index e00b8f620c5d9..c7475b3deb574 100644 --- a/kernel/smp.c +++ b/kernel/smp.c @@ -227,10 +227,28 @@ bool csd_lock_is_stuck(void) struct csd_wait_state { u64 ts_start; /* When the wait began. */ u64 ts_report; /* When the last complaint was printed. */ + u64 ts_resend; /* When the last IPI was re-sent, 0 if never. */ int bug_id; unsigned long nmessages; }; +/* + * Report a CSD lock that came back, @ts_unstuck being when the release was + * noticed. Only mention the re-send delta if an IPI was actually re-sent. + */ +static void csd_lock_print_unstuck(struct csd_wait_state *state, int cpu, u64 ts_unstuck) +{ + if (state->ts_resend) + pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock after %lld ns, %lld ns after the last IPI re-send.\n", + state->bug_id, raw_smp_processor_id(), cpu, + (s64)(ts_unstuck - state->ts_start), + (s64)(ts_unstuck - state->ts_resend)); + else + pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock after %lld ns.\n", + state->bug_id, raw_smp_processor_id(), cpu, + (s64)(ts_unstuck - state->ts_start)); +} + /* * Complain if too much time spent waiting. Note that only * the CSD_TYPE_SYNC/ASYNC types provide the destination CPU, @@ -249,9 +267,9 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, struct csd_wait_state if (!(flags & CSD_FLAG_LOCK)) { if (!unlikely(state->bug_id)) return true; + ts_now = ktime_get_mono_fast_ns(); cpu = csd_lock_wait_getcpu(csd); - pr_alert("csd: CSD lock (#%d) got unstuck on CPU#%02d, CPU#%02d released the lock.\n", - state->bug_id, raw_smp_processor_id(), cpu); + csd_lock_print_unstuck(state, cpu, ts_now); atomic_dec(&n_csd_lock_stuck); return true; } @@ -309,6 +327,7 @@ static bool csd_lock_wait_toolong(call_single_data_t *csd, struct csd_wait_state if (!cpu_cur_csd) { pr_alert("csd: Re-sending CSD lock (#%d) IPI from CPU#%02d to CPU#%02d\n", state->bug_id, raw_smp_processor_id(), cpu); arch_send_call_function_single_ipi(cpu); + state->ts_resend = ktime_get_mono_fast_ns(); } } if (firsttime) -- 2.53.0-Meta