Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
From:   Stephen Brennan <stephen.s.brennan@oracle.com>
To:     Petr Mladek <pmladek@suse.com>,
        Sergey Senozhatsky <senozhatsky@chromium.org>,
        Steven Rostedt <rostedt@goodmis.org>,
        John Ogness <john.ogness@linutronix.de>
Cc:     Stephen Brennan <stephen.s.brennan@oracle.com>,
        Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
        linux-kernel@vger.kernel.org
Subject: [PATCH v2] printk: disable optimistic spin during panic
Date:   Tue, 18 Jan 2022 17:31:40 -0800
Message-Id: <20220119013140.383261-1-stephen.s.brennan@oracle.com>
Content-Transfer-Encoding: 8bit
Content-Type: text/plain
MIME-Version: 1.0
X-MS-Exchange-AntiSpam-MessageData-ChunkCount: 1
X-MS-Exchange-AntiSpam-MessageData-0: =?us-ascii?Q?flO8wCwGHdXaabGPiibNS27EnC6vm0N56sgy8yJeNTSpG+c4heAXS8pxmCVB?=
 =?us-ascii?Q?yYDHjwhmx9lSgb/BMRCaGev2jo8CzuSWIYjdTj48iFoCd2+wWHokWNlJN1j3?=
 =?us-ascii?Q?1p7VC7+YIaklhUcoltmZBcLsgEaliy423kyuDM20fjUHbaPXNgnL3FyMXL6A?=
 =?us-ascii?Q?V0lOhMh0mOTz4/XZwzimYeLu4odE9DyMoHUmfsKr/7fsj3CyuZktxQYSZmwj?=
 =?us-ascii?Q?0e20zNEfy6hBhkWWcw3Rlt0tdIfuZSOEtPe6wJLoLKv23Ct4SCzv2gmjcVRH?=
 =?us-ascii?Q?I+IwE3RD7u9LpUHd4sWywjCEiGCrRRoJMrtdZb/TDQkwY2gmTTyX1y4gKlfb?=
 =?us-ascii?Q?xXRiFBzatWbsLxPyFXx19Z3/4YKe7Qnijv00u/dVBNMTupYkvPAbELVwc6ur?=
 =?us-ascii?Q?gJpEfL4mh55OoF+dhf4l6o5tccNmWnRipHi3bvk3JUp+WR72N3N9evlbPV2g?=
 =?us-ascii?Q?tMOzz/Y2bGdEwH/Kj3Cmz6c0o716VsOPjjVEATJ258dbYUcpc9dJKEWyfW9r?=
 =?us-ascii?Q?Gnma0mYgOhAdhCP79ne08woG0t3FhEUzfrGgoIQ603fMuNU/dAGL1KibIFZx?=
 =?us-ascii?Q?YdgrBkDzWvn39SkRcVi4Ml6MJBPz+nehBn+FqJtJWAO2DFg1PFDhdgoQcY3b?=
 =?us-ascii?Q?VxaB7ctSAuHxGvU21J8SmLodt5+Dabt31WuHYIQ4Ke/6Hxcyfi+a4DC30ZPl?=
 =?us-ascii?Q?eNtfQK1kgjOG6XS+tuCk+OLMV5PRl8L08MQoMgVaIMErepJCG5BCC30AWbLJ?=
 =?us-ascii?Q?1oKhCEJvZdLxlRDff1k0OaZGEYu1Gqi5qz/2hQ9G5nrx9N7fXEeTzQwIIug3?=
 =?us-ascii?Q?mPGvxoAfFk8YTzj895fOVla949G1dcfsMC1H4TKmtTg2p44ZoP+omcYkgm5t?=
 =?us-ascii?Q?6KgD+jqUoybumirgLcjjhvYHe1h7Ysb6BmZUdeYNpI08p1QyLBq+UTVcMTuC?=
 =?us-ascii?Q?VpdveBOQkCWzC8DZSSmKwwnSTvh3Jo+0QLxpEBICpwnrDaSe4YE1Awh7WztQ?=
 =?us-ascii?Q?VduLvvgzZjoxarbpHSDEwwzGi0aS80dm520UALlAsOPF8uoCiOv/+2ESrqII?=
 =?us-ascii?Q?L65tWFqbJV/PopixoP5E1BUfLrvIPX9AxQDxl5QSTyKQtF7zYpEE+O7U1NUJ?=
 =?us-ascii?Q?424UyQT7wGfesP0Wvq2IQ9VbG9fgtHqoDJOe2htZecPKomEoHQr4eaPeiAoE?=
 =?us-ascii?Q?NpPwmpD5KecJBYU7SHyiGZgeEQSombHi2szTbgtIR6aRBgw0NDSwXgP0993k?=
 =?us-ascii?Q?fqgXcQ+CWguv/OIYvSvinK6wV7G8v1R/XU/ihgkwPq956Z7684Cyp8zpJNDE?=
 =?us-ascii?Q?CUtETUOe5p42zq3YJdNaIwK8C8uF4r9TrGBR6TVLrL27L5RBa4HxtARAreaH?=
 =?us-ascii?Q?7ssPM61UvQDCa2sppvBLB1+rblL4nTUWovEnH++MDeQ4EWACoeZyxDv3LYh0?=
 =?us-ascii?Q?AVSbQJ/DvCExlrYoMKPX8gr+3FixizSWJWOoheTd4MfmVEZ8W/VAhzy2Oq8I?=
 =?us-ascii?Q?tPRmxM2ChFlR6w1cBfrtjVZwzHC0lvkNXVgSsUP+x1Hv0k0DCZkCfXhV2VfA?=
 =?us-ascii?Q?c+4PUfIpfxOGFa9SJcrl8KqArbUHdbeRB/xSYS/mG2+6/rbDun4zJ+0e9dB5?=
 =?us-ascii?Q?8eXfHH9TLYqSQhulhD5OmcN+SP0iXbgBwWiscd4sDieMkV3HwABtJCWKgca7?=
 =?us-ascii?Q?TWTxzQ=3D=3D?=
X-OriginatorOrg: oracle.com
X-MS-Exchange-CrossTenant-Network-Message-Id: 50fa0d5d-0617-497d-b841-08d9daeb731e
X-MS-Exchange-CrossTenant-AuthSource: CH2PR10MB4166.namprd10.prod.outlook.com
X-MS-Exchange-CrossTenant-AuthAs: Internal
X-MS-Exchange-CrossTenant-OriginalArrivalTime: 19 Jan 2022 01:31:43.5702
 (UTC)
X-MS-Exchange-CrossTenant-FromEntityHeader: Hosted
X-MS-Exchange-CrossTenant-Id: 4e2c6054-71cb-48f1-bd6c-3a9705aca71b
X-MS-Exchange-CrossTenant-MailboxType: HOSTED
X-MS-Exchange-CrossTenant-UserPrincipalName: c0HBXeeTcS5CDMAVn86mFAoL6wZpLu4rK36BFHiMiaigZ+i/2jA59Nz61TOv3CHWGtLAAsN5ssBvLnKuV85RNLT4jW+n4wE+Zw4IT2v0QYQ=
X-MS-Exchange-Transport-CrossTenantHeadersStamped: CH2PR10MB4055
X-Proofpoint-Virus-Version: vendor=nai engine=6300 definitions=10231 signatures=668683
X-Proofpoint-Spam-Details: rule=notspam policy=default score=0 phishscore=0 bulkscore=0
 mlxlogscore=999 adultscore=0 suspectscore=0 malwarescore=0 mlxscore=0
 spamscore=0 classifier=spam adjust=0 reason=mlx scancount=1
 engine=8.12.0-2110150000 definitions=main-2201190004
X-Proofpoint-GUID: DaU0y8nkpJ1u0Qd8ebZ3xVpODpbzh61b
X-Proofpoint-ORIG-GUID: DaU0y8nkpJ1u0Qd8ebZ3xVpODpbzh61b
Precedence: bulk
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

A CPU executing with console lock spinning enabled might be halted
during a panic. Before the panicking CPU calls console_flush_on_panic(),
it may call console_trylock(), which attempts to optimistically spin,
deadlocking the panic CPU:

CPU 0 (panic CPU)             CPU 1
-----------------             ------
                              printk() {
                                vprintk_func() {
                                  vprintk_default() {
                                    vprintk_emit() {
                                      console_unlock() {
                                        console_lock_spinning_enable();
                                        ... printing to console ...
panic() {
  crash_smp_send_stop() {
    NMI  -------------------> HALT
  }
  atomic_notifier_call_chain() {
    printk() {
      ...
      console_trylock_spinnning() {
        // optimistic spin infinitely

This hang during panic can be induced when a kdump kernel is loaded, and
crash_kexec_post_notifiers=1 is present on the kernel command line. The
following script which concurrently writes to /dev/kmsg, and triggers a
panic, can result in this hang:

    #!/bin/bash
    date
    # 991 chars (based on log buffer size):
    chars="$(printf 'a%.0s' {1..991})"
    while :; do
        echo $chars > /dev/kmsg
    done &
    echo c > /proc/sysrq-trigger &
    date
    exit

To avoid this deadlock, ensure that console_trylock_spinning() does not
allow spinning once a panic has begun. Below are the hang rates for the
above test case, based on v5.16-rc8 before and after this patch:

before:  776 hangs / 1484 trials - 52.3%
after :    0 hangs /  102 trials -  0.0%

Fixes: dbdda842fe96 ("printk: Add console owner and waiter logic to load balance console writes")

Signed-off-by: Stephen Brennan <stephen.s.brennan@oracle.com>
---

Note: I continue to run my tests past 100 trials, but at this point I'm
confident enough in the fix to send the patch.

As Petr suggested I will send another patch making the non-panic CPUs
bail out of console_unlock(), but I wanted to get this one first, since
it is implemented and ready now.

 kernel/printk/printk.c | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 57b132b658e1..612ed895b967 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1843,6 +1843,16 @@ static int console_trylock_spinning(void)
 	if (console_trylock())
 		return 1;
 
+	/*
+	 * It's unsafe for the panic CPU to spin, since the CPU holding the
+	 * console_sem may have already been halted. However, if a panic has
+	 * started, but we're not the panic CPU, we still spin. This protects
+	 * the panic CPU from needing to write out messages buffered by other
+	 * CPUs in console_unlock().
+	 */
+	if (atomic_read(&panic_cpu) == raw_smp_processor_id())
+		return 0;
+
 	printk_safe_enter_irqsave(flags);
 
 	raw_spin_lock(&console_owner_lock);
-- 
2.30.2