Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::3:4 as permitted sender) client-ip=2620:137:e000::3:4;
From:   John Ogness <john.ogness@linutronix.de>
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: Re: [PATCH printk] printk: flush consoles before checking progress
In-Reply-To: <ZRrAFS3cELj1DDN2@alley>
References: <20230929113233.863824-1-john.ogness@linutronix.de>
 <ZRrAFS3cELj1DDN2@alley>
Date:   Wed, 04 Oct 2023 12:31:07 +0206
Message-ID: <87h6n64rcs.fsf@jogness.linutronix.de>
MIME-Version: 1.0
Content-Type: text/plain
Precedence: bulk

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