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 EC484C433EF for ; Fri, 17 Jun 2022 13:39:04 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1382184AbiFQNjD (ORCPT ); Fri, 17 Jun 2022 09:39:03 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:49370 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1381935AbiFQNjB (ORCPT ); Fri, 17 Jun 2022 09:39:01 -0400 Received: from ams.source.kernel.org (ams.source.kernel.org [IPv6:2604:1380:4601:e00::1]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id B3740B480 for ; Fri, 17 Jun 2022 06:39:00 -0700 (PDT) Received: from smtp.kernel.org (relay.kernel.org [52.25.139.140]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by ams.source.kernel.org (Postfix) with ESMTPS id 6546FB829AC for ; Fri, 17 Jun 2022 13:38:59 +0000 (UTC) Received: by smtp.kernel.org (Postfix) with ESMTPSA id 86858C3411B; Fri, 17 Jun 2022 13:38:57 +0000 (UTC) Authentication-Results: smtp.kernel.org; dkim=pass (1024-bit key) header.d=zx2c4.com header.i=@zx2c4.com header.b="mJCSzTS8" DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=zx2c4.com; s=20210105; t=1655473135; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=the0bHwmSoyiH9hzlVaC5HDxQSTmKiYgUbnNqfXQJ74=; b=mJCSzTS8VnEhrIOGqy50ZTbQKlkAVYjcKIagLTlBxn8X5c/0rz24UufNxFEBDpI3QfEJoq cFD2gHZEN3DY1Kk4A+NLsDjM3QuD4WdS3ChU0bMqcz5T+OsDf9XVysCq6TieptNnlZYkQH wVYNFsBiCzJFwQ60YEuWeQJGCnDDm0k= Received: by mail.zx2c4.com (ZX2C4 Mail Server) with ESMTPSA id 0fc50dcf (TLSv1.3:AEAD-AES256-GCM-SHA384:256:NO); Fri, 17 Jun 2022 13:38:54 +0000 (UTC) From: "Jason A. Donenfeld" To: John Ogness , Petr Mladek , Marco Elver , linux-kernel@vger.kernel.org Cc: "Jason A. Donenfeld" Subject: [PATCH] printk: allow direct console printing to be enabled always Date: Fri, 17 Jun 2022 15:38:47 +0200 Message-Id: <20220617133847.27517-1-Jason@zx2c4.com> In-Reply-To: References: MIME-Version: 1.0 Content-Transfer-Encoding: 8bit Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org In 5.19, there are some changes in printk message ordering / interleaving which leads to confusion. The most obvious (and benign) example appears on system boot, in which the "Run /init as init process" message gets intermixed with the messages that init actually writes() to stdout. For example, here's a snippet from build.wireguard.com: [ 0.469732] Freeing unused kernel image (initmem) memory: 4576K [ 0.469738] Write protecting the kernel read-only data: 10240k [ 0.473823] Freeing unused kernel image (text/rodata gap) memory: 2044K [ 0.475228] Freeing unused kernel image (rodata/data gap) memory: 1136K [ 0.475236] Run /init as init process WireGuard Test Suite on Linux 5.19.0-rc2+ x86_64 [+] Mounting filesystems... [+] Module self-tests: * allowedips self-tests: pass * nonce counter self-tests: pass * ratelimiter self-tests: pass [+] Enabling logging... [+] Launching tests... [ 0.475237] with arguments: [ 0.475238] /init [ 0.475238] with environment: [ 0.475239] HOME=/ [ 0.475240] TERM=linux [+] ip netns add wg-test-46-0 [+] ip netns add wg-test-46-1 Before the "with arguments:" and such would print prior to the "wireguard test suite on linux 5.19" banner. Now it shows after. I see the same thing with "Freeing unused kernel image (text/rodata gap) memory" printing interwoven into the console of my initramfs on my laptop. And so forth. But the bigger issue for me is that it makes it very confusing to interpret CI results later on. Prior, I would nice a nice correlation of: [+] some userspace command [ 1.2345 ] some kernel log output [+] some userspace command [ 1.2346 ] some kernel log output [+] some userspace command [ 1.2347 ] some kernel log output Now, the kernel log outputs are all over the place and out of order with the sequence of commands. This makes debugging issues somewhat tricky, because post hoc ergo propter hoc winds up being a good intuition to follow when tracking down bugs, and now the post hoc part is muddled. This is caused by threaded printk. In order to restore this in debugging sessions and in CI, this commit adds the ability to always use direct printk, either set by default at compile time, or overridden with a runtime command line switch. Cc: John Ogness Cc: Petr Mladek Cc: Marco Elver Fixes: 09c5ba0aa2fc ("printk: add kthread console printers") Signed-off-by: Jason A. Donenfeld --- Documentation/admin-guide/kernel-parameters.txt | 8 ++++++++ init/Kconfig | 12 ++++++++++++ kernel/printk/printk.c | 12 ++++++++++++ 3 files changed, 32 insertions(+) diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt index 8090130b544b..a960c47a2002 100644 --- a/Documentation/admin-guide/kernel-parameters.txt +++ b/Documentation/admin-guide/kernel-parameters.txt @@ -4389,6 +4389,14 @@ printk.time= Show timing data prefixed to each printk message line Format: (1/Y/y=enable, 0/N/n=disable) + printk.always_direct= + Rather than using kthreads for printk output, always + write to the console immediately. This has performance + implications, but will result in a more faithful + ordering and interleaving with other processes writing + to the console. + Format: (1/Y/y=enable, 0/N/n=disable) + processor.max_cstate= [HW,ACPI] Limit processor to maximum C-state max_cstate=9 overrides any DMI blacklist limit. diff --git a/init/Kconfig b/init/Kconfig index c7900e8975f1..7676897f2321 100644 --- a/init/Kconfig +++ b/init/Kconfig @@ -798,6 +798,18 @@ config PRINTK_INDEX There is no additional runtime cost to printk with this enabled. +config PRINTK_ALWAYS_DIRECT + bool "Flush printk output immediately" + depends on PRINTK + help + Rather than using kthreads for printk output, always write to the + console immediately. This has performance implications, but will + result in a more faithful ordering and interleaving with other + processes writing to the console. + + Say N here unless you really need this. This may also be controlled + at boot time with printk.always_direct=0/1. + # # Architectures with an unreliable sched_clock() should select this: # diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index ea3dd55709e7..d9f419a88429 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -178,6 +178,14 @@ static int __init control_devkmsg(char *str) } __setup("printk.devkmsg=", control_devkmsg); +static bool always_direct_printk = IS_ENABLED(CONFIG_PRINTK_ALWAYS_DIRECT); + +static int __init control_always_direct_printk(char *str) +{ + return kstrtobool(str, &always_direct_printk); +} +__setup("printk.always_direct=", control_always_direct_printk); + char devkmsg_log_str[DEVKMSG_STR_MAX_SIZE] = "ratelimit"; #if defined(CONFIG_PRINTK) && defined(CONFIG_SYSCTL) int devkmsg_sysctl_set_loglvl(struct ctl_table *table, int write, @@ -471,6 +479,10 @@ void printk_prefer_direct_exit(void) */ static inline bool allow_direct_printing(void) { + /* If the user has explicitly enabled this to be on always. */ + if (always_direct_printk) + return true; + /* * Checking kthread availability is a possible race because the * kthread printers can become permanently disabled during runtime. -- 2.35.1