[PATCH v2 0/2] printk: Reduce unnecessary wait times by pr_flush()

[PATCH v2 0/2] printk: Reduce unnecessary wait times by pr_flush()

[Petr Mladek]

This is an updated version of the patch
https://lore.kernel.org/r/20230929113233.863824-1-john.ogness@linutronix.de

Changes since v1:

  + Split reduction of the pooling time into separate patch.
  + Use jiffies to count the real sleeping time.

Note that my original POC counted jiffies spent in the entire cycle.
It would count also the time spent by console_lock() and by flushing
the legacy consoles in console_unlock().

The current version counts only the time spent by msleep(1) aka
the pooling interval.


John Ogness (1):
  printk: flush consoles before checking progress

Petr Mladek (1):
  printk: Reduce pr_flush() pooling time

 kernel/printk/printk.c | 34 ++++++++++++++++++++--------------
 1 file changed, 20 insertions(+), 14 deletions(-)

-- 
2.35.3

[PATCH v2 1/2] printk: flush consoles before checking progress

[Petr Mladek]

From: John Ogness <john.ogness@linutronix.de>

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.

Note that console_unlock() does not guarantee flushing all messages
since the commit dbdda842fe96f89 ("printk: Add console owner and waiter
logic to load balance console writes").

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")
Co-developed-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: Petr Mladek <pmladek@suse.com>
Signed-off-by: John Ogness <john.ogness@linutronix.de>
---
 kernel/printk/printk.c | 8 +++++++-
 1 file changed, 7 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 7e0b4dd02398..0b3af1529778 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();
 
-- 
2.35.3

[PATCH v2 2/2] printk: Reduce pr_flush() pooling time

[Petr Mladek]

pr_flush() does not guarantee that all messages would really get flushed
to the console. The best it could do is to wait with a given timeout.[*]

The current interval 100ms for checking the progress might seem too
long in some situations. For example, such delays are not appreciated
during suspend and resume especially when the consoles have been flushed
"long" time before the check.

One the other hand, the sleeping wait might be useful in other situations.
Especially, it would allow flushing the messages using printk kthreads
on the same CPU[*].

Use msleep(1) as a compromise.

Also measure the time using jiffies. msleep() does not guarantee
precise wakeup after the given delay. It might be much longer,
especially for times < 20s. See Documentation/timers/timers-howto.rst
for more details.

Note that msecs_to_jiffies() already translates a negative value into
an infinite timeout.

[*] console_unlock() does not guarantee flushing the consoles since
    the commit dbdda842fe96f893 ("printk: Add console owner and waiter
    logic to load balance console writes").

    It would be possible to guarantee it another way. For example,
    the spinning might be enabled only when the console_lock has been
    taken via console_trylock().

    But the load balancing is helpful. And more importantly, the flush
    with a timeout has been added as a preparation step for introducing
    printk kthreads.

Signed-off-by: Petr Mladek <pmladek@suse.com>
---
 kernel/printk/printk.c | 26 +++++++++++++-------------
 1 file changed, 13 insertions(+), 13 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 0b3af1529778..c0e13c0e68b2 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -3728,7 +3728,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 remaining_jiffies = timeout_jiffies;
 	struct console *c;
 	u64 last_diff = 0;
 	u64 printk_seq;
@@ -3745,6 +3746,9 @@ static bool __pr_flush(struct console *con, int timeout_ms, bool reset_on_progre
 	console_unlock();
 
 	for (;;) {
+		unsigned long begin_jiffies;
+		unsigned long slept_jiffies;
+
 		diff = 0;
 
 		/*
@@ -3773,24 +3777,20 @@ 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;
+			remaining_jiffies = timeout_jiffies;
 
 		console_unlock();
 
 		/* Note: @diff is 0 if there are no usable consoles. */
-		if (diff == 0 || remaining == 0)
+		if (diff == 0 || remaining_jiffies == 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) might sleep much longer. Check time by jiffies. */
+		begin_jiffies = jiffies;
+		msleep(1);
+		slept_jiffies = jiffies - begin_jiffies;
+
+		remaining_jiffies -= min(slept_jiffies, remaining_jiffies);
 
 		last_diff = diff;
 	}
-- 
2.35.3

Re: [PATCH v2 2/2] printk: Reduce pr_flush() pooling time

[John Ogness]

On 2023-10-06, Petr Mladek <pmladek@suse.com> wrote:
> pr_flush() does not guarantee that all messages would really get flushed
> to the console. The best it could do is to wait with a given timeout.[*]
>
> The current interval 100ms for checking the progress might seem too
> long in some situations. For example, such delays are not appreciated
> during suspend and resume especially when the consoles have been flushed
> "long" time before the check.
>
> One the other hand, the sleeping wait might be useful in other situations.

  "One" should be "On"

Otherwise the patch looks OK to me. Thanks!

Reviewed-by: John Ogness <john.ogness@linutronix.de>

Re: [PATCH v2 0/2] printk: Reduce unnecessary wait times by pr_flush()

[Petr Mladek]

On Fri 2023-10-06 10:21:49, Petr Mladek wrote:
> This is an updated version of the patch
> https://lore.kernel.org/r/20230929113233.863824-1-john.ogness@linutronix.de
> 
> Changes since v1:
> 
>   + Split reduction of the pooling time into separate patch.
>   + Use jiffies to count the real sleeping time.
> 
> Note that my original POC counted jiffies spent in the entire cycle.
> It would count also the time spent by console_lock() and by flushing
> the legacy consoles in console_unlock().
> 
> The current version counts only the time spent by msleep(1) aka
> the pooling interval.
> 
> 
> John Ogness (1):
>   printk: flush consoles before checking progress
> 
> Petr Mladek (1):
>   printk: Reduce pr_flush() pooling time

JFYI, the patchset has been committed into printk/linux.git,
branch rework/misc-cleanups.

I am going to push it in the next merge window for 6.7.
IMHO, the issue is not critical and we are already at 6.6-rc5.

Best Regards,
Petr

Re: [PATCH v2 0/2] printk: Reduce unnecessary wait times by pr_flush()

[John Ogness]

On 2023-10-10, Petr Mladek <pmladek@suse.com> wrote:
>> This is an updated version of the patch
>> https://lore.kernel.org/r/20230929113233.863824-1-john.ogness@linutronix.de
>> 
>> Changes since v1:
>> 
>>   + Split reduction of the pooling time into separate patch.
>>   + Use jiffies to count the real sleeping time.
>> 
>> Note that my original POC counted jiffies spent in the entire cycle.
>> It would count also the time spent by console_lock() and by flushing
>> the legacy consoles in console_unlock().
>> 
>> The current version counts only the time spent by msleep(1) aka
>> the pooling interval.
>> 
>> 
>> John Ogness (1):
>>   printk: flush consoles before checking progress
>> 
>> Petr Mladek (1):
>>   printk: Reduce pr_flush() pooling time
>
> JFYI, the patchset has been committed into printk/linux.git,
> branch rework/misc-cleanups.
>
> I am going to push it in the next merge window for 6.7.
> IMHO, the issue is not critical and we are already at 6.6-rc5.

It is a real regression. I think it is important that it goes into
6.6. At least the first patch is simple enough and fixes the regression.

John

Re: [PATCH v2 0/2] printk: Reduce unnecessary wait times by pr_flush()

[Petr Mladek]

On Tue 2023-10-10 13:44:38, John Ogness wrote:
> On 2023-10-10, Petr Mladek <pmladek@suse.com> wrote:
> >> This is an updated version of the patch
> >> https://lore.kernel.org/r/20230929113233.863824-1-john.ogness@linutronix.de
> >> 
> >> Changes since v1:
> >> 
> >>   + Split reduction of the pooling time into separate patch.
> >>   + Use jiffies to count the real sleeping time.
> >> 
> >> Note that my original POC counted jiffies spent in the entire cycle.
> >> It would count also the time spent by console_lock() and by flushing
> >> the legacy consoles in console_unlock().
> >> 
> >> The current version counts only the time spent by msleep(1) aka
> >> the pooling interval.
> >> 
> >> 
> >> John Ogness (1):
> >>   printk: flush consoles before checking progress
> >> 
> >> Petr Mladek (1):
> >>   printk: Reduce pr_flush() pooling time
> >
> > JFYI, the patchset has been committed into printk/linux.git,
> > branch rework/misc-cleanups.
> >
> > I am going to push it in the next merge window for 6.7.
> > IMHO, the issue is not critical and we are already at 6.6-rc5.
> 
> It is a real regression. I think it is important that it goes into
> 6.6. At least the first patch is simple enough and fixes the regression.

Fair enough. I have crated pull request with the 1st patch for
6.6-rc6, see ZSaPGo13Fz9TLUc6@alley.

Note that I rebased the branch rework/misc-cleanups in
printk/linux.git to be able to crate a merge with the 1st patch only.
I am not sure if it could have been done without the rebase.

Best Regards,
Petr