This is an updated version of the patch
https://lore.kernel.org/r/[email protected]
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
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 <[email protected]>
---
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
On 2023-10-06, Petr Mladek <[email protected]> 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 <[email protected]>
On Fri 2023-10-06 10:21:49, Petr Mladek wrote:
> This is an updated version of the patch
> https://lore.kernel.org/r/[email protected]
>
> 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
On 2023-10-10, Petr Mladek <[email protected]> wrote:
>> This is an updated version of the patch
>> https://lore.kernel.org/r/[email protected]
>>
>> 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
On Tue 2023-10-10 13:44:38, John Ogness wrote:
> On 2023-10-10, Petr Mladek <[email protected]> wrote:
> >> This is an updated version of the patch
> >> https://lore.kernel.org/r/[email protected]
> >>
> >> 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