Message ID | 20230929113233.863824-1-john.ogness@linutronix.de |
---|---|
State | New |
Headers |
Return-Path: <linux-kernel-owner@vger.kernel.org> Delivered-To: ouuuleilei@gmail.com Received: by 2002:a05:612c:2a8e:b0:403:3b70:6f57 with SMTP id in14csp136366vqb; Fri, 29 Sep 2023 18:14:04 -0700 (PDT) X-Google-Smtp-Source: AGHT+IEM1TRn2amHicfE2GXDc2+204YWsFvPcHQL7/StrIMgCu1qnk5mAXfplvT5PPm49vPYO05Z X-Received: by 2002:a17:90b:3882:b0:274:7db1:f50f with SMTP id mu2-20020a17090b388200b002747db1f50fmr9535093pjb.15.1696036444119; Fri, 29 Sep 2023 18:14:04 -0700 (PDT) ARC-Seal: i=1; a=rsa-sha256; t=1696036444; cv=none; d=google.com; s=arc-20160816; b=zWPU4XKU73ZIUgdoRjkgfcC+tVOpeKI/QyS0RPPXGDY/gjkiCc5ZzU7vTuxNnPS5zK 9c0SkW66SRLan5T2A3X/vYkkApk8bzb8P9Yxv9+aGjsws7a++JBbulIwqNWmdOdA7hm+ JdyHcnAILhX1b4IHbKadTPCI2rkKpaY0OQKgTUiSr8fE/aRPmJvXqANWOvtVMDpOptAj GHFXpgSFzobGwWAuHbObaS7BfI5zi4pNxo9j7fW2AvTUUvouoOfJUmhHqDqsBHABNmni /+bKMYER8My16vnm+lrh+ZVcgK/wHF5NOV6/ZGwu8ZkxHtLSCFtknUMSKFtJEs2tSjBj glXA== ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=google.com; s=arc-20160816; h=list-id:precedence:content-transfer-encoding:mime-version :message-id:date:subject:cc:to:dkim-signature:dkim-signature:from; bh=UIipO+SgaQkwOUgqbE7dftCadTipucHktt7Dz7VlEvw=; fh=+WiQ2jjWv7hkX4n01jo89PecmvbVaG49N7UAN6x9A/o=; b=ZpShUBsovEzcKa3h5PBYziUY6uwJcWXbL/szFDlgFfVirbqy5tWEPgwg43Yu2JRoSf c7eW3UzojT4cwrnRFjPYXoLyE8dAVQehXntm+heLvWQcCpzgO2DLWOEFyYnXZVf3W3lX hjhoNEtOdwaLYXbIC8v1H7dScay2xeNp8OkBoEj25sU+xAf152+aCVOT+SdoVJfC+Q8r K5ySFVRO+KHDheAAM0yNgv4KrNJP5YfNFLJkZfqNs9iVjtQlVKq5jg/dflZzUIdCwNpw mLnCa3XAvpEHfJIIA/QtXTQSta5jvsPi/4LuAhgg5NuCzWwuVvath9ogASi0lcWi5M6U 2eTQ== ARC-Authentication-Results: i=1; mx.google.com; dkim=pass header.i=@linutronix.de header.s=2020 header.b="r0S/zBzC"; dkim=neutral (no key) header.i=@linutronix.de header.s=2020e header.b=0X1loJtv; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.34 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=QUARANTINE dis=NONE) header.from=linutronix.de Received: from howler.vger.email (howler.vger.email. [23.128.96.34]) by mx.google.com with ESMTPS id t8-20020a17090ae50800b002745c4e215fsi2522548pjy.175.2023.09.29.18.14.03 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Fri, 29 Sep 2023 18:14:04 -0700 (PDT) Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.34 as permitted sender) client-ip=23.128.96.34; Authentication-Results: mx.google.com; dkim=pass header.i=@linutronix.de header.s=2020 header.b="r0S/zBzC"; dkim=neutral (no key) header.i=@linutronix.de header.s=2020e header.b=0X1loJtv; spf=pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 23.128.96.34 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE sp=QUARANTINE dis=NONE) header.from=linutronix.de Received: from out1.vger.email (depot.vger.email [IPv6:2620:137:e000::3:0]) by howler.vger.email (Postfix) with ESMTP id 4A00080D1DFB; Fri, 29 Sep 2023 04:32:46 -0700 (PDT) X-Virus-Status: Clean X-Virus-Scanned: clamav-milter 0.103.10 at howler.vger.email Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S232630AbjI2Lck (ORCPT <rfc822;pwkd43@gmail.com> + 20 others); Fri, 29 Sep 2023 07:32:40 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:51218 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229687AbjI2Lcj (ORCPT <rfc822;linux-kernel@vger.kernel.org>); Fri, 29 Sep 2023 07:32:39 -0400 Received: from galois.linutronix.de (Galois.linutronix.de [193.142.43.55]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id DB2C294 for <linux-kernel@vger.kernel.org>; Fri, 29 Sep 2023 04:32:35 -0700 (PDT) From: John Ogness <john.ogness@linutronix.de> DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linutronix.de; s=2020; t=1695987154; 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; bh=UIipO+SgaQkwOUgqbE7dftCadTipucHktt7Dz7VlEvw=; b=r0S/zBzCESwXq+yQNhp+72oEodba2w5Q87jwg/Wb+Q4mFjid2uFBD9anORdTgth7gKGg9W Qdx0rxID6I+zsRwm/HyNJ6TDE8qLPJRO4vmh9LVj0rRbCEYyCVBgMUz87TOF8wOtTS2m7Q m6lJNfzGYwtC2QkZSo6dZRPRKeCCnE4ML8O18KP8PDjPahYbwjTY/3TwC8aV0LCjjVaYer koMPc1AdEccb0OXgUywdw54RoxnDOOlr6zszE2ISn2H9ZAwpCP3i3gvBaD+bJrWZp9pWvE yzYhvB+3CbKyfxZ/Ih7o3S2JXKPzFFvuVXv//EsqwyQv/FrNuDjJgjJY8VK2HQ== DKIM-Signature: v=1; a=ed25519-sha256; c=relaxed/relaxed; d=linutronix.de; s=2020e; t=1695987154; 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; bh=UIipO+SgaQkwOUgqbE7dftCadTipucHktt7Dz7VlEvw=; b=0X1loJtvalKL2keyu/6BHQPhV1aCbcE1sPE4dCfaNYEdpEVVkvBTU92IeatfUoTi4gpI9t wMjJXO1s65fLNQBA== To: Petr Mladek <pmladek@suse.com> Cc: Sergey Senozhatsky <senozhatsky@chromium.org>, Steven Rostedt <rostedt@goodmis.org>, Thomas Gleixner <tglx@linutronix.de>, linux-kernel@vger.kernel.org, Todd Brandt <todd.e.brandt@intel.com> Subject: [PATCH printk] printk: flush consoles before checking progress Date: Fri, 29 Sep 2023 13:38:33 +0206 Message-Id: <20230929113233.863824-1-john.ogness@linutronix.de> MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Spam-Status: No, score=-3.9 required=5.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,DKIM_VALID_EF,INVALID_DATE_TZ_ABSURD, RCVD_IN_DNSWL_MED,SPF_HELO_NONE,SPF_PASS autolearn=ham autolearn_force=no version=3.4.6 X-Spam-Checker-Version: SpamAssassin 3.4.6 (2021-04-09) on lindbergh.monkeyblade.net Precedence: bulk List-ID: <linux-kernel.vger.kernel.org> X-Mailing-List: linux-kernel@vger.kernel.org X-Greylist: Sender passed SPF test, not delayed by milter-greylist-4.6.4 (howler.vger.email [0.0.0.0]); Fri, 29 Sep 2023 04:32:46 -0700 (PDT) X-getmail-retrieved-from-mailbox: INBOX X-GMAIL-THRID: 1778380213637573530 X-GMAIL-MSGID: 1778423110040036068 |
Series |
[printk] printk: flush consoles before checking progress
|
|
Commit Message
John Ogness
Sept. 29, 2023, 11:32 a.m. UTC
Commit 9e70a5e109a4 ("printk: Add per-console suspended state")
removed console lock usage during resume and replaced it with
the clearly defined console_list_lock and srcu mechanisms.
However, the console lock usage had an important side-effect
of flushing the consoles. After its removal, consoles were no
longer flushed before checking their progress.
Add the console_lock/console_unlock dance to the beginning
of __pr_flush() to actually flush the consoles before checking
their progress. Also add comments to clarify this additional
usage of the console lock.
Finally, in case pr_flush() needs to poll-wait (for example,
because there has been a handover to another CPU), reduce the
polling interval from 100ms to 1ms. In the bug report it was
mentioned that 100ms is unnecessarily long.
Reported-by: Todd Brandt <todd.e.brandt@intel.com>
Closes: https://bugzilla.kernel.org/show_bug.cgi?id=217955
Fixes: 9e70a5e109a4 ("printk: Add per-console suspended state")
Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
kernel/printk/printk.c | 23 ++++++++++++-----------
1 file changed, 12 insertions(+), 11 deletions(-)
base-commit: 4952801fc6adb5b50b8ec2bcc5aeef92fcce8730
Comments
On Fri 2023-09-29 13:38:33, John Ogness wrote: > Finally, in case pr_flush() needs to poll-wait (for example, > because there has been a handover to another CPU), reduce the > polling interval from 100ms to 1ms. In the bug report it was > mentioned that 100ms is unnecessarily long. > > Reported-by: Todd Brandt <todd.e.brandt@intel.com> > Closes: https://bugzilla.kernel.org/show_bug.cgi?id=217955 > Fixes: 9e70a5e109a4 ("printk: Add per-console suspended state") > Signed-off-by: John Ogness <john.ogness@linutronix.de> > --- > kernel/printk/printk.c | 23 ++++++++++++----------- > 1 file changed, 12 insertions(+), 11 deletions(-) > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 7e0b4dd02398..cf7841fc6eef 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -3775,16 +3781,11 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre > if (diff == 0 || remaining == 0) > break; > > - if (remaining < 0) { > - /* no timeout limit */ > - msleep(100); > - } else if (remaining < 100) { > - msleep(remaining); > - remaining = 0; > - } else { > - msleep(100); > - remaining -= 100; > - } > + msleep(1); I was about to push this patch and ran checkpatch.pl. It warned about WARNING: msleep < 20ms can sleep for up to 20ms; see Documentation/timers/timers-howto.rst #73: FILE: kernel/printk/printk.c:3782: + msleep(1); And indeed, Documentation/timers/timers-howto.rst says that msleep() might sleep longer that expected for <20ms delays. I guess that it is somehow related to jiffies, HZ, and load on the system. I think that we need to count jiffies here. Something like: diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index db81b68d7f14..6ea500d95fd9 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -3723,7 +3723,8 @@ late_initcall(printk_late_init); /* If @con is specified, only wait for that console. Otherwise wait for all. */ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress) { - int remaining = timeout_ms; + unsigned long timeout_jiffies = msecs_to_jiffies(timeout_ms); + unsigned_long timeout_end = jiffies + timeout_jiffies; struct console *c; u64 last_diff = 0; u64 printk_seq; @@ -3772,24 +3773,19 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre console_srcu_read_unlock(cookie); if (diff != last_diff && reset_on_progress) - remaining = timeout_ms; + timeout_end = jiffies + timeout_jiffies; console_unlock(); /* Note: @diff is 0 if there are no usable consoles. */ - if (diff == 0 || remaining == 0) + if (diff == 0) break; - if (remaining < 0) { - /* no timeout limit */ - msleep(100); - } else if (remaining < 100) { - msleep(remaining); - remaining = 0; - } else { - msleep(100); - remaining -= 100; - } + /* Negative timeout means an infinite wait. */ + if (timeout_ms >= 0 && time_after_eq(jiffies, timeout_end)) + break; + + msleep(2000 / HZ); last_diff = diff; } Note that I used 2000 / HZ to make sure that it will be >= 1. And we should do this in a separate patch. It seems that sleeping is a bigger magic than I expected. Best Regards, Petr
On 2023-10-02, Petr Mladek <pmladek@suse.com> wrote: > I was about to push this patch and ran checkpatch.pl. It warned about > > WARNING: msleep < 20ms can sleep for up to 20ms; see Documentation/timers/timers-howto.rst > #73: FILE: kernel/printk/printk.c:3782: > + msleep(1); > > And indeed, Documentation/timers/timers-howto.rst says that msleep() > might sleep longer that expected for <20ms delays. I guess that > it is somehow related to jiffies, HZ, and load on the system. > > I think that we need to count jiffies here. Agreed. The @timeout_ms parameter should be respected. > Something like: > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index db81b68d7f14..6ea500d95fd9 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -3723,7 +3723,8 @@ late_initcall(printk_late_init); > /* If @con is specified, only wait for that console. Otherwise wait for all. */ > static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progress) > { > - int remaining = timeout_ms; > + unsigned long timeout_jiffies = msecs_to_jiffies(timeout_ms); > + unsigned_long timeout_end = jiffies + timeout_jiffies; > struct console *c; > u64 last_diff = 0; > u64 printk_seq; > @@ -3772,24 +3773,19 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre > console_srcu_read_unlock(cookie); > > if (diff != last_diff && reset_on_progress) > - remaining = timeout_ms; > + timeout_end = jiffies + timeout_jiffies; > > console_unlock(); > > /* Note: @diff is 0 if there are no usable consoles. */ > - if (diff == 0 || remaining == 0) > + if (diff == 0) > break; > > - if (remaining < 0) { > - /* no timeout limit */ > - msleep(100); > - } else if (remaining < 100) { > - msleep(remaining); > - remaining = 0; > - } else { > - msleep(100); > - remaining -= 100; > - } > + /* Negative timeout means an infinite wait. */ > + if (timeout_ms >= 0 && time_after_eq(jiffies, timeout_end)) > + break; > + > + msleep(2000 / HZ); Is there really any advantage to this? I would just do msleep(1) and let msleep round up. Everything else (tracking via jiffies) looks fine to me. > last_diff = diff; > } > > And we should do this in a separate patch. It seems that sleeping > is a bigger magic than I expected. Agreed. John
On Wed 2023-10-04 12:31:07, John Ogness wrote: > On 2023-10-02, Petr Mladek <pmladek@suse.com> wrote: > > I was about to push this patch and ran checkpatch.pl. It warned about > > > > WARNING: msleep < 20ms can sleep for up to 20ms; see Documentation/timers/timers-howto.rst > > #73: FILE: kernel/printk/printk.c:3782: > > + msleep(1); > > > > And indeed, Documentation/timers/timers-howto.rst says that msleep() > > might sleep longer that expected for <20ms delays. I guess that > > it is somehow related to jiffies, HZ, and load on the system. > > > > I think that we need to count jiffies here. > > Agreed. The @timeout_ms parameter should be respected. > > > Something like: > > > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > > index db81b68d7f14..6ea500d95fd9 100644 > > --- a/kernel/printk/printk.c > > +++ b/kernel/printk/printk.c > > @@ -3772,24 +3773,19 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre > > console_srcu_read_unlock(cookie); > > > > if (diff != last_diff && reset_on_progress) > > - remaining = timeout_ms; > > + timeout_end = jiffies + timeout_jiffies; > > > > console_unlock(); > > > > /* Note: @diff is 0 if there are no usable consoles. */ > > - if (diff == 0 || remaining == 0) > > + if (diff == 0) > > break; > > > > - if (remaining < 0) { > > - /* no timeout limit */ > > - msleep(100); > > - } else if (remaining < 100) { > > - msleep(remaining); > > - remaining = 0; > > - } else { > > - msleep(100); > > - remaining -= 100; > > - } > > + /* Negative timeout means an infinite wait. */ > > + if (timeout_ms >= 0 && time_after_eq(jiffies, timeout_end)) > > + break; > > + > > + msleep(2000 / HZ); > > Is there really any advantage to this? I would just do msleep(1) and let > msleep round up. Everything else (tracking via jiffies) looks fine to me. It was attempt to synchronize it with a scheduler tick. I saw it somewhere ;-) But you are right. Let's keep it simple and use msleep(1). > > last_diff = diff; > > } > > > > And we should do this in a separate patch. It seems that sleeping > > is a bigger magic than I expected. > > Agreed. Are you going to prepare them or should I? Best Regards, Petr
On 2023-10-04, Petr Mladek <pmladek@suse.com> wrote:
> Are you going to prepare them or should I?
Really it was your version that we are taking. I suppose you should post
them and I can review them.
Also, the Closes tag probably should just be on the lock/unlock patch.
John
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 7e0b4dd02398..cf7841fc6eef 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -3740,12 +3740,18 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre seq = prb_next_seq(prb); + /* Flush the consoles so that records up to @seq are printed. */ + console_lock(); + console_unlock(); + for (;;) { diff = 0; /* * Hold the console_lock to guarantee safe access to - * console->seq. + * console->seq. Releasing console_lock flushes more + * records in case @seq is still not printed on all + * usable consoles. */ console_lock(); @@ -3775,16 +3781,11 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre if (diff == 0 || remaining == 0) break; - if (remaining < 0) { - /* no timeout limit */ - msleep(100); - } else if (remaining < 100) { - msleep(remaining); - remaining = 0; - } else { - msleep(100); - remaining -= 100; - } + msleep(1); + + /* If @remaining < 0, there is no timeout limit. */ + if (remaining > 0) + remaining--; last_diff = diff; }