Re: [PATCH v3] printk: Relocate wake_klogd check close to the end of console_unlock()

[Sergey Senozhatsky]

On (02/26/18 16:57), Petr Mladek wrote:
[..]
> 
> Okay, what about the following patch for 4.16-rc4?

Looks good!

[..]
> Fixes: dbdda842fe96f8932 ("printk: Add console owner and waiter logic to load 
> balance console writes")
> Suggested-by: Sergey Senozhatsky 
> Signed-off-by: Petr Mladek 

Reviewed-by: Sergey Senozhatsky 

-ss

Re: [PATCH v3] printk: Relocate wake_klogd check close to the end of console_unlock()

[Sergey Senozhatsky]

On (02/26/18 16:57), Petr Mladek wrote:
[..]
> 
> Okay, what about the following patch for 4.16-rc4?

Looks good!

[..]
> Fixes: dbdda842fe96f8932 ("printk: Add console owner and waiter logic to load 
> balance console writes")
> Suggested-by: Sergey Senozhatsky 
> Signed-off-by: Petr Mladek 

Reviewed-by: Sergey Senozhatsky 

-ss

Re: [PATCH v3] printk: Relocate wake_klogd check close to the end of console_unlock()

[Petr Mladek]

On Mon 2018-02-26 15:37:35, Sergey Senozhatsky wrote:
> On (02/19/18 17:01), Petr Mladek wrote:
> [..]
> > -   raw_spin_lock(_lock);
> > retry = console_seq != log_next_seq;
> > +   /*
> > +* Check whether userland needs notification. Do this only when really
> > +* leaving to avoid race with console_trylock_spinning().
> > +*/
> > +   if (seen_seq != log_next_seq && !retry) {
> > +   wake_klogd = true;
> > +   seen_seq = log_next_seq;
> > +   }
> 
> Let's add the "why" part. This "!retry" might be hard to understand. We
> are looking at
> 
> - CPUa is about to leave console_unlock()
> - printk on CPUb appends a new message
> - CPUa detects that `console_seq != log_next_seq', updates `seen_seq'
> - printk on CPUb is getting preempted
> - CPUa re-takes the console_sem via retry path
> - printk CPUb is becoming TASK_RUNNING again - it now spins for console_sem,
>   since we have an active console_sem owner
> - CPUa detects that there is a console_sem waiter, so it offloads the
>   printing task, without ever waking up klogd

Yes, this is the scenario. I agree that it is very tricky.

> Either we can have that complex "seen_seq != log_next_seq && !retry"
> check - or we simply can add
> 
>   if (console_lock_spinning_disable_and_check()) {
>   printk_safe_exit_irqrestore(flags);
>   if (wake_klogd)
>   wake_up_klogd();
>   }
> 
> to the offloading return path.
> 
> The later is *may be* simpler to follow. The rule is: every
> !console_suspend and !cant-use-consoles return path from console_unlock()
> must wake_up_klogd() [if needed].

Yes, this looks more straighforward. It might cause earlier and more
often wakeup but we want to go this way anyway. I do not see any
real problem with it.

Okay, what about the following patch for 4.16-rc4?

>From 7450da0e7e0d7ee5926f09c8bbbaa44c67ae0b48 Mon Sep 17 00:00:00 2001
From: Petr Mladek 
Date: Mon, 26 Feb 2018 15:44:20 +0100
Subject: [PATCH] printk: Wake klogd when passing console_lock owner

wake_klogd is a local variable in console_unlock(). The information
is lost when the console_lock owner using the busy wait added by
the commit dbdda842fe96f8932 ("printk: Add console owner and waiter
logic to load balance console writes"). The following race is
possible:

CPU0CPU1
console_unlock()

  for (;;)
 /* calling console for last message */

printk()
  log_store()
log_next_seq++;

 /* see new message */
 if (seen_seq != log_next_seq) {
wake_klogd = true;
seen_seq = log_next_seq;
 }

 console_lock_spinning_enable();

  if (console_trylock_spinning())
 /* spinning */

 if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
return;

  console_unlock()
if (seen_seq != log_next_seq) {
/* already seen */
/* nothing to do */

Result: Nobody would wakeup klogd.

One solution would be to make a global variable from wake_klogd.
But then we would need to manipulate it under a lock or so.

This patch wakes klogd also when console_lock is passed to the
spinning waiter. It looks like the right way to go. Also userspace
should have a chance to see and store any "flood" of messages.

Note that the very late klogd wake up was a historic solution.
It made sense on single CPU systems or when sys_syslog() operations
were synchronized using the big kernel lock like in v2.1.113.
But it is questionable these days.

Fixes: dbdda842fe96f8932 ("printk: Add console owner and waiter logic to load 
balance console writes")
Suggested-by: Sergey Senozhatsky 
Signed-off-by: Petr Mladek 
---
 kernel/printk/printk.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc1123583fa6..f274fbef821d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2397,7 +2397,7 @@ void console_unlock(void)
 
if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
-   return;
+   goto out;
}
 
printk_safe_exit_irqrestore(flags);
@@ -2430,6 +2430,7 @@ void console_unlock(void)
if (retry && console_trylock())
goto again;
 
+out:
if (wake_klogd)
wake_up_klogd();
 }
-- 
2.13.6

Re: [PATCH v3] printk: Relocate wake_klogd check close to the end of console_unlock()

[Petr Mladek]

On Mon 2018-02-26 15:37:35, Sergey Senozhatsky wrote:
> On (02/19/18 17:01), Petr Mladek wrote:
> [..]
> > -   raw_spin_lock(_lock);
> > retry = console_seq != log_next_seq;
> > +   /*
> > +* Check whether userland needs notification. Do this only when really
> > +* leaving to avoid race with console_trylock_spinning().
> > +*/
> > +   if (seen_seq != log_next_seq && !retry) {
> > +   wake_klogd = true;
> > +   seen_seq = log_next_seq;
> > +   }
> 
> Let's add the "why" part. This "!retry" might be hard to understand. We
> are looking at
> 
> - CPUa is about to leave console_unlock()
> - printk on CPUb appends a new message
> - CPUa detects that `console_seq != log_next_seq', updates `seen_seq'
> - printk on CPUb is getting preempted
> - CPUa re-takes the console_sem via retry path
> - printk CPUb is becoming TASK_RUNNING again - it now spins for console_sem,
>   since we have an active console_sem owner
> - CPUa detects that there is a console_sem waiter, so it offloads the
>   printing task, without ever waking up klogd

Yes, this is the scenario. I agree that it is very tricky.

> Either we can have that complex "seen_seq != log_next_seq && !retry"
> check - or we simply can add
> 
>   if (console_lock_spinning_disable_and_check()) {
>   printk_safe_exit_irqrestore(flags);
>   if (wake_klogd)
>   wake_up_klogd();
>   }
> 
> to the offloading return path.
> 
> The later is *may be* simpler to follow. The rule is: every
> !console_suspend and !cant-use-consoles return path from console_unlock()
> must wake_up_klogd() [if needed].

Yes, this looks more straighforward. It might cause earlier and more
often wakeup but we want to go this way anyway. I do not see any
real problem with it.

Okay, what about the following patch for 4.16-rc4?

>From 7450da0e7e0d7ee5926f09c8bbbaa44c67ae0b48 Mon Sep 17 00:00:00 2001
From: Petr Mladek 
Date: Mon, 26 Feb 2018 15:44:20 +0100
Subject: [PATCH] printk: Wake klogd when passing console_lock owner

wake_klogd is a local variable in console_unlock(). The information
is lost when the console_lock owner using the busy wait added by
the commit dbdda842fe96f8932 ("printk: Add console owner and waiter
logic to load balance console writes"). The following race is
possible:

CPU0CPU1
console_unlock()

  for (;;)
 /* calling console for last message */

printk()
  log_store()
log_next_seq++;

 /* see new message */
 if (seen_seq != log_next_seq) {
wake_klogd = true;
seen_seq = log_next_seq;
 }

 console_lock_spinning_enable();

  if (console_trylock_spinning())
 /* spinning */

 if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
return;

  console_unlock()
if (seen_seq != log_next_seq) {
/* already seen */
/* nothing to do */

Result: Nobody would wakeup klogd.

One solution would be to make a global variable from wake_klogd.
But then we would need to manipulate it under a lock or so.

This patch wakes klogd also when console_lock is passed to the
spinning waiter. It looks like the right way to go. Also userspace
should have a chance to see and store any "flood" of messages.

Note that the very late klogd wake up was a historic solution.
It made sense on single CPU systems or when sys_syslog() operations
were synchronized using the big kernel lock like in v2.1.113.
But it is questionable these days.

Fixes: dbdda842fe96f8932 ("printk: Add console owner and waiter logic to load 
balance console writes")
Suggested-by: Sergey Senozhatsky 
Signed-off-by: Petr Mladek 
---
 kernel/printk/printk.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc1123583fa6..f274fbef821d 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2397,7 +2397,7 @@ void console_unlock(void)
 
if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
-   return;
+   goto out;
}
 
printk_safe_exit_irqrestore(flags);
@@ -2430,6 +2430,7 @@ void console_unlock(void)
if (retry && console_trylock())
goto again;
 
+out:
if (wake_klogd)
wake_up_klogd();
 }
-- 
2.13.6

Re: [PATCH v3] printk: Relocate wake_klogd check close to the end of console_unlock()

[Sergey Senozhatsky]

On (02/19/18 17:01), Petr Mladek wrote:
[..]
> - raw_spin_lock(_lock);
>   retry = console_seq != log_next_seq;
> + /*
> +  * Check whether userland needs notification. Do this only when really
> +  * leaving to avoid race with console_trylock_spinning().
> +  */
> + if (seen_seq != log_next_seq && !retry) {
> + wake_klogd = true;
> + seen_seq = log_next_seq;
> + }

Let's add the "why" part. This "!retry" might be hard to understand. We
are looking at

- CPUa is about to leave console_unlock()
- printk on CPUb appends a new message
- CPUa detects that `console_seq != log_next_seq', updates `seen_seq'
- printk on CPUb is getting preempted
- CPUa re-takes the console_sem via retry path
- printk CPUb is becoming TASK_RUNNING again - it now spins for console_sem,
  since we have an active console_sem owner
- CPUa detects that there is a console_sem waiter, so it offloads the
  printing task, without ever waking up klogd


Either we can have that complex "seen_seq != log_next_seq && !retry"
check - or we simply can add

if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
if (wake_klogd)
wake_up_klogd();
}

to the offloading return path.

The later is *may be* simpler to follow. The rule is: every
!console_suspend and !cant-use-consoles return path from console_unlock()
must wake_up_klogd() [if needed].

-ss

Re: [PATCH v3] printk: Relocate wake_klogd check close to the end of console_unlock()

[Sergey Senozhatsky]

On (02/19/18 17:01), Petr Mladek wrote:
[..]
> - raw_spin_lock(_lock);
>   retry = console_seq != log_next_seq;
> + /*
> +  * Check whether userland needs notification. Do this only when really
> +  * leaving to avoid race with console_trylock_spinning().
> +  */
> + if (seen_seq != log_next_seq && !retry) {
> + wake_klogd = true;
> + seen_seq = log_next_seq;
> + }

Let's add the "why" part. This "!retry" might be hard to understand. We
are looking at

- CPUa is about to leave console_unlock()
- printk on CPUb appends a new message
- CPUa detects that `console_seq != log_next_seq', updates `seen_seq'
- printk on CPUb is getting preempted
- CPUa re-takes the console_sem via retry path
- printk CPUb is becoming TASK_RUNNING again - it now spins for console_sem,
  since we have an active console_sem owner
- CPUa detects that there is a console_sem waiter, so it offloads the
  printing task, without ever waking up klogd


Either we can have that complex "seen_seq != log_next_seq && !retry"
check - or we simply can add

if (console_lock_spinning_disable_and_check()) {
printk_safe_exit_irqrestore(flags);
if (wake_klogd)
wake_up_klogd();
}

to the offloading return path.

The later is *may be* simpler to follow. The rule is: every
!console_suspend and !cant-use-consoles return path from console_unlock()
must wake_up_klogd() [if needed].

-ss

[PATCH v3] printk: Relocate wake_klogd check close to the end of console_unlock()

[Petr Mladek]

From: Tejun Heo 

We mark for waking up klogd whenever we see a new message sequence in
the main loop.  However, the actual wakeup is always at the end of the
function and we can easily test for the wakeup condition when we do
the final should-we-repeat check.

Move the wake_klogd condition check out of the main loop.  This avoids
doing the same thing repeatedly and groups similar checks into a
common place.

This fixes a race introduced by the commit dbdda842fe96f8932 ("printk: Add
console owner and waiter logic to load balance console writes").
The current console owner might process the newly added message before
the related printk() start waiting for the console lock. Then the lock
is passed without waking klogd. The new owner sees the already updated
seen_seq and does not know that the wakeup is needed.

Fixes: dbdda842fe96f8932 ("printk: Add console owner and waiter logic to load 
balance console writes")
Signed-off-by: Tejun Heo 
[pmla...@suse.com: Fix and describe a new race with console waiter]
Signed-off-by: Petr Mladek 
Cc: Petr Mladek 
Cc: Sergey Senozhatsky 
Cc: Steven Rostedt 
---
Changes against v2:

+ check wake_klogd only when really leaving

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index db4b9b8929eb..aaa28c1409ab 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2335,10 +2335,6 @@ void console_unlock(void)
 
printk_safe_enter_irqsave(flags);
raw_spin_lock(_lock);
-   if (seen_seq != log_next_seq) {
-   wake_klogd = true;
-   seen_seq = log_next_seq;
-   }
 
if (console_seq < log_first_seq) {
len = sprintf(text, "** %u printk messages dropped 
**\n",
@@ -2416,14 +2412,22 @@ void console_unlock(void)
 
up_console_sem();
 
+   raw_spin_lock(_lock);
/*
 * Someone could have filled up the buffer again, so re-check if there's
 * something to flush. In case we cannot trylock the console_sem again,
 * there's a new owner and the console_unlock() from them will do the
 * flush, no worries.
 */
-   raw_spin_lock(_lock);
retry = console_seq != log_next_seq;
+   /*
+* Check whether userland needs notification. Do this only when really
+* leaving to avoid race with console_trylock_spinning().
+*/
+   if (seen_seq != log_next_seq && !retry) {
+   wake_klogd = true;
+   seen_seq = log_next_seq;
+   }
raw_spin_unlock(_lock);
printk_safe_exit_irqrestore(flags);
 
-- 
2.13.6

[PATCH v3] printk: Relocate wake_klogd check close to the end of console_unlock()

[Petr Mladek]

From: Tejun Heo 

We mark for waking up klogd whenever we see a new message sequence in
the main loop.  However, the actual wakeup is always at the end of the
function and we can easily test for the wakeup condition when we do
the final should-we-repeat check.

Move the wake_klogd condition check out of the main loop.  This avoids
doing the same thing repeatedly and groups similar checks into a
common place.

This fixes a race introduced by the commit dbdda842fe96f8932 ("printk: Add
console owner and waiter logic to load balance console writes").
The current console owner might process the newly added message before
the related printk() start waiting for the console lock. Then the lock
is passed without waking klogd. The new owner sees the already updated
seen_seq and does not know that the wakeup is needed.

Fixes: dbdda842fe96f8932 ("printk: Add console owner and waiter logic to load 
balance console writes")
Signed-off-by: Tejun Heo 
[pmla...@suse.com: Fix and describe a new race with console waiter]
Signed-off-by: Petr Mladek 
Cc: Petr Mladek 
Cc: Sergey Senozhatsky 
Cc: Steven Rostedt 
---
Changes against v2:

+ check wake_klogd only when really leaving

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

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index db4b9b8929eb..aaa28c1409ab 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2335,10 +2335,6 @@ void console_unlock(void)
 
printk_safe_enter_irqsave(flags);
raw_spin_lock(_lock);
-   if (seen_seq != log_next_seq) {
-   wake_klogd = true;
-   seen_seq = log_next_seq;
-   }
 
if (console_seq < log_first_seq) {
len = sprintf(text, "** %u printk messages dropped 
**\n",
@@ -2416,14 +2412,22 @@ void console_unlock(void)
 
up_console_sem();
 
+   raw_spin_lock(_lock);
/*
 * Someone could have filled up the buffer again, so re-check if there's
 * something to flush. In case we cannot trylock the console_sem again,
 * there's a new owner and the console_unlock() from them will do the
 * flush, no worries.
 */
-   raw_spin_lock(_lock);
retry = console_seq != log_next_seq;
+   /*
+* Check whether userland needs notification. Do this only when really
+* leaving to avoid race with console_trylock_spinning().
+*/
+   if (seen_seq != log_next_seq && !retry) {
+   wake_klogd = true;
+   seen_seq = log_next_seq;
+   }
raw_spin_unlock(_lock);
printk_safe_exit_irqrestore(flags);
 
-- 
2.13.6