From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by smtp.lore.kernel.org (Postfix) with ESMTP id 12636C43334 for ; Mon, 13 Jun 2022 02:13:05 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S236718AbiFMCND (ORCPT ); Sun, 12 Jun 2022 22:13:03 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:58584 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S235855AbiFMCNB (ORCPT ); Sun, 12 Jun 2022 22:13:01 -0400 Received: from galois.linutronix.de (Galois.linutronix.de [IPv6:2a0a:51c0:0:12e:550::1]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 7A9A912AD1 for ; Sun, 12 Jun 2022 19:12:59 -0700 (PDT) From: John Ogness DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linutronix.de; s=2020; t=1655086377; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: in-reply-to:in-reply-to:references:references; bh=9Or2rbY8MjbpIj8wbtfD9FjomH8TXd2sOJsV3nzxdHE=; b=EBvH6LzinBUvol2iP9BgQPuybJCqyYmeGqcIVfjEGC9DrfWosOQWwaiTkeGGUhlDmRLzG4 3ItJ7jSbWTyPzqlceGy+Vx+9kPrykEsMDoJkTQD3ZVxDDi6dyyegkJzLjRvSVfXzTYUhPo 4pGHTmD4a+X/beB5H75zhMe0fEzZYMll71sJvAsnk1zE1syfc1lc84edGRUXdhoXCYYK7D m17nF2fADJq6sZtiSep69M7b59t0ovhXvCOVJEf/eGor/Izb3Tn6E3Kx7n1tAzV3jF8Kj1 PUZF8OE54FKqmR6mPXcwtmfRQ8aWYBPiqmNy43CljDcAiIhIbccf2xi32w636Q== DKIM-Signature: v=1; a=ed25519-sha256; c=relaxed/relaxed; d=linutronix.de; s=2020e; t=1655086377; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: in-reply-to:in-reply-to:references:references; bh=9Or2rbY8MjbpIj8wbtfD9FjomH8TXd2sOJsV3nzxdHE=; b=WaG2qSsKx0Tslybo4icUP2xx8YIHPGtfXmoEfKqf6ki0G1uT+Uu7XJV/XzIl1fEWmzJ1oj lCRScQwaJXnLkQCA== To: paulmck@kernel.org Cc: linux-kernel@vger.kernel.org, frederic@kernel.org, pmladek@suse.com, Sergey Senozhatsky , Steven Rostedt Subject: Re: [BUG] 8e274732115f ("printk: extend console_lock for per-console locking") In-Reply-To: <20220610205038.GA3050413@paulmck-ThinkPad-P17-Gen-1> References: <20220610205038.GA3050413@paulmck-ThinkPad-P17-Gen-1> Date: Mon, 13 Jun 2022 04:18:56 +0206 Message-ID: <87v8t5l39z.fsf@jogness.linutronix.de> MIME-Version: 1.0 Content-Type: text/plain Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 2022-06-10, "Paul E. McKenney" wrote: > I have started getting rcutorture shutdown-time hangs when running > against recent mainline, and bisected back to the 8e274732115f ("printk: > extend console_lock for per-console locking") commit. These hangs go > away (or at least their probability drops dramatically) if I build with > CONFIG_PREEMPTION=n -and- CONFIG_NO_HZ=y (not n!), at least assuming > that I also boot with "nohz_full=0-N". > > Attempts to debug using rcutorture's "--gdb" argument result in > "[Inferior 1 (process 1) exited normally]", but with the same truncated > console-log output as when running without "--gdb". This suggests > that the kernel really did run to completion and halt as expected, > but that the shutdown-time printk() output was lost. Furthermore, if I > use the gdb "hbreak" command to set a breakpoint at kernel_power_off(), > it really does hit that breakpoint. This would not happen in the case > of a kernel hang. > > So, given that I can hit that breakpoint, what should I ask gdb to > show me? If you also compile with CONFIG_GDB_SCRIPTS=y then you can use the defined "lx-dmesg" gdb command to see if the messages are in the ringbuffer. (You may need to add: add-auto-load-safe-path /path/to/linux/scripts/gdb/vmlinux-gdb.py to your $HOME/.gdbinit) But since you are hitting the breakpoint, the messages will be there. > Alternatively, this reproduces on a variety of x86 platforms, so you > should be able reproduce it as follows [1]: > > git checkout v5.19-rc1 > tools/testing/selftests/rcutorture/bin/kvm.sh --allcpus --duration 2 --configs "TREE01" --gdb --kconfig "CONFIG_DEBUG_INFO_NONE=n CONFIG_DEBUG_INFO_DWARF_TOOLCHAIN_DEFAULT=y" --trust-make > > This builds a kernel, boots it, and then tells you how to launch gdb > (presumably in some other window). Once you give launch gdb and give > it the suggested commands, the kernel runs for two minutes under qemu, > then shuts down. I used the following gdb commands to set the breakpoint > and run the kernel: > > target remote :1234 # suggested by the rcutorture script > hbreak kernel_power_off # added by me > continue # suggested by the rcutorture script Thanks. Nice helper scripts. With this I could easily reproduce the issue. As I suspected, the final printk's cannot direct print because the kthread was printing. Using the below patch did seem to address your problem. But this is probably not the way forward. What I have not figured out is why this problem does not exist when only the kthread patch (but not the "extend console_lock" patch) is applied. Somehow the console_lock is magically providing some sort of synchronization in the end. Or maybe it is just the increased lock contention that helps out. It seems we need some sort of console_flush_on_panic() for non-panic situations that is not as violent as console_flush_on_panic(). @Petr, does it make sense to add the below patch to mainline? It is only marginally helpful because it performs the direct printing in the wrong context. Really we need that final pr_emerg("Power down\n") to be a successful direct print so that the buffer is fully flushed before hitting machine_power_off(). In fact, the below patch could make things worse because the printing kthread could take over printing from that final pr_emerg(). John Ogness diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index ea3dd55709e7..5950586008fa 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -3841,6 +3841,18 @@ static int printk_kthread_func(void *data) console_kthread_printing_exit(); mutex_unlock(&con->lock); + + /* + * The kernel may have transitioned to a direct printing + * state, but any printk calls may not have direct printed + * because this thread was printing its message. Grab and + * release the console lock to flush out any pending + * messages on all consoles. + */ + if (allow_direct_printing()) { + console_lock(); + console_unlock(); + } } con_printk(KERN_INFO, con, "printing thread stopped\n");