[PATCH 2/2] printk: wake up klogd in vprintk_emit

[PATCH 2/2] printk: wake up klogd in vprintk_emit

[Sergey Senozhatsky]

We wake up klogd very late - only when current console_sem owner
is done pushing pending kernel messages to the serial/net consoles.
In some cases this results in lost syslog messages, because kernel
log buffer is a circular buffer and if we don't wakeup syslog long
enough there are chances that logbuf simply will wrap around.

The patch moves the klog wake up call to vprintk_emit(), which is
the only legit way for a kernel message to appear in the logbuf,
right before we attempt to grab the console_sem (possibly spinning
on it waiting for the hand off) and call console drivers.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 14 ++------------
 1 file changed, 2 insertions(+), 12 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2f4af216bd6e..86f0b337cbf6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1888,6 +1888,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 
 	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
 
+	wake_up_klogd();
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -2289,9 +2290,7 @@ void console_unlock(void)
 {
 	static char ext_text[CONSOLE_EXT_LOG_MAX];
 	static char text[LOG_LINE_MAX + PREFIX_MAX];
-	static u64 seen_seq;
 	unsigned long flags;
-	bool wake_klogd = false;
 	bool do_cond_resched, retry;
 
 	if (console_suspended) {
@@ -2335,11 +2334,6 @@ void console_unlock(void)
 
 		printk_safe_enter_irqsave(flags);
 		raw_spin_lock(&logbuf_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",
 				      (unsigned)(log_first_seq - console_seq));
@@ -2397,7 +2391,7 @@ void console_unlock(void)
 
 		if (console_lock_spinning_disable_and_check()) {
 			printk_safe_exit_irqrestore(flags);
-			goto out;
+			return;
 		}
 
 		printk_safe_exit_irqrestore(flags);
@@ -2429,10 +2423,6 @@ void console_unlock(void)
 
 	if (retry && console_trylock())
 		goto again;
-
-out:
-	if (wake_klogd)
-		wake_up_klogd();
 }
 EXPORT_SYMBOL(console_unlock);
 
-- 
2.17.0

Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit

[Petr Mladek]

On Sat 2018-04-14 12:01:45, Sergey Senozhatsky wrote:
> We wake up klogd very late - only when current console_sem owner
> is done pushing pending kernel messages to the serial/net consoles.
> In some cases this results in lost syslog messages, because kernel
> log buffer is a circular buffer and if we don't wakeup syslog long
> enough there are chances that logbuf simply will wrap around.
> 
> The patch moves the klog wake up call to vprintk_emit(), which is
> the only legit way for a kernel message to appear in the logbuf,
> right before we attempt to grab the console_sem (possibly spinning
> on it waiting for the hand off) and call console drivers.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> ---
>  kernel/printk/printk.c | 14 ++------------
>  1 file changed, 2 insertions(+), 12 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 2f4af216bd6e..86f0b337cbf6 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1888,6 +1888,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  
>  	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
>  
> +	wake_up_klogd();
>  	logbuf_unlock_irqrestore(flags);

The change makes perfect sense and I am fine with the idea. I just
wonder if there is a strong reason to do the wake_up before
releasing the logbuf_lock. It makes an assumption that it needs
to be synchronized by logbuf_lock.

In fact, I would feel more comfortable if we move this to the end
of vprintk_emit() right before return printk_len. This will be
more close to the current behavior (console first). But it will
still wakeup klogd much earlier and regularly if there is
a flood of messages.

Best Regards,
Petr

Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit

[Sergey Senozhatsky]

On (04/18/18 16:04), Petr Mladek wrote:
[..]
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index 2f4af216bd6e..86f0b337cbf6 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1888,6 +1888,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> >  
> >  	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
> >  
> > +	wake_up_klogd();
> >  	logbuf_unlock_irqrestore(flags);
> 
> The change makes perfect sense and I am fine with the idea. I just
> wonder if there is a strong reason to do the wake_up before
> releasing the logbuf_lock. It makes an assumption that it needs
> to be synchronized by logbuf_lock.

No, not really, just wanted to wakeup klogd from the same CPU which
called printk().

> In fact, I would feel more comfortable if we move this to the end
> of vprintk_emit() right before return printk_len. This will be
> more close to the current behavior (console first). But it will
> still wakeup klogd much earlier and regularly if there is
> a flood of messages.

Hm, the idea of the patch is that the existing "push everything to slow
consoles first, then wakeup syslog" is not very robust. But probably we
can do what you suggested, yes.

	-ss

Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit

[Petr Mladek]

On Thu 2018-04-19 10:23:11, Sergey Senozhatsky wrote:
> On (04/18/18 16:04), Petr Mladek wrote:
> [..]
> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > > index 2f4af216bd6e..86f0b337cbf6 100644
> > > --- a/kernel/printk/printk.c
> > > +++ b/kernel/printk/printk.c
> > > @@ -1888,6 +1888,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> > >  
> > >  	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
> > >  
> > > +	wake_up_klogd();
> > >  	logbuf_unlock_irqrestore(flags);
> > 
> > In fact, I would feel more comfortable if we move this to the end
> > of vprintk_emit() right before return printk_len. This will be
> > more close to the current behavior (console first). But it will
> > still wakeup klogd much earlier and regularly if there is
> > a flood of messages.
> 
> Hm, the idea of the patch is that the existing "push everything to slow
> consoles first, then wakeup syslog" is not very robust.

I guess that you know why I suggested what I suggested ;-)
Just for record, I thought the following way:

The obsession about getting messages on consoles ASAP blocked
any softlockup prevention for years. There are surely situations
where this matter and we need to keep this in mind.

Loggers might preempt the current task because of priority
inversion. It is rather a corner case. The priority inversion is
problem on its own that probably do not have a good solution.


Our main target is to increase the chance to see the messages.
In theory userspace loggers might be faster than a slow console.
But they are not much reliable by definition. They need to get
scheduled, copy the message, store it into a file, the file need
to get synced to the disk. There are many things that might get
wrong there.


All in all, neither solution would work better in all situations.
I would just feel more comfortable if we do not go to the other
extreme, ...


> But probably we can do what you suggested, yes.

Thanks a lot for using this in v2.

Best Regards,
Petr

Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit

[Steven Rostedt]

On Sat, 14 Apr 2018 12:01:45 +0900
Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:

> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1888,6 +1888,7 @@ asmlinkage int vprintk_emit(int facility, int level,
>  
>  	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
>  
> +	wake_up_klogd();
>  	logbuf_unlock_irqrestore(flags);

You can't do this, because the scheduler can call printk_deferred()
with the rq lock held, and printk_deferred() will grab the logbuf lock.

Calling wake_up_klogd() will grab the rq lock and give us a A-B<->B-A
locking order.

-- Steve

Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit

[Petr Mladek]

On Wed 2018-04-18 10:29:43, Steven Rostedt wrote:
> On Sat, 14 Apr 2018 12:01:45 +0900
> Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:
> 
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1888,6 +1888,7 @@ asmlinkage int vprintk_emit(int facility, int level,
> >  
> >  	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
> >  
> > +	wake_up_klogd();
> >  	logbuf_unlock_irqrestore(flags);
> 
> You can't do this, because the scheduler can call printk_deferred()
> with the rq lock held, and printk_deferred() will grab the logbuf lock.
> 
> Calling wake_up_klogd() will grab the rq lock and give us a A-B<->B-A
> locking order.

wake_up_klogd() uses the lockless irq_work_queue(). So it is actually
safe.

But the name is confusing. We should rename it.

Best Regards,
Petr

Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit

[Steven Rostedt]

On Wed, 18 Apr 2018 17:02:14 +0200
Petr Mladek <pmladek@suse.com> wrote:

> > Calling wake_up_klogd() will grab the rq lock and give us a A-B<->B-A
> > locking order.  
> 
> wake_up_klogd() uses the lockless irq_work_queue(). So it is actually
> safe.

I didn't look at the code. OK then we don't need to worry about that.

> 
> But the name is confusing. We should rename it.

Yes, I would because the old wake_up_klogd() did do a wakeup. Perhaps
we should name it: kick_klogd().

-- Steve

Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit

[Sergey Senozhatsky]

On (04/18/18 11:10), Steven Rostedt wrote:
> 
> > > Calling wake_up_klogd() will grab the rq lock and give us a A-B<->B-A
> > > locking order.  
> > 
> > wake_up_klogd() uses the lockless irq_work_queue(). So it is actually
> > safe.
> 
> I didn't look at the code. OK then we don't need to worry about that.

OK.

> > 
> > But the name is confusing. We should rename it.
> 
> Yes, I would because the old wake_up_klogd() did do a wakeup. Perhaps
> we should name it: kick_klogd().

Agreed.

	-ss

[PATCHv2] printk: wake up klogd in vprintk_emit

[Sergey Senozhatsky]

We wake up klogd very late - only when current console_sem owner
is done pushing pending kernel messages to the serial/net consoles.
In some cases this results in lost syslog messages, because kernel
log buffer is a circular buffer and if we don't wakeup syslog long
enough there are chances that logbuf simply will wrap around.

The patch moves the klog wake up call to vprintk_emit(), which is
the only legit way for a kernel message to appear in the logbuf,
right before we attempt to grab the console_sem (possibly spinning
on it waiting for the hand off) and call console drivers.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
---
 kernel/printk/printk.c | 14 ++------------
 1 file changed, 2 insertions(+), 12 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 2f4af216bd6e..247808333ba4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1908,6 +1908,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 		preempt_enable();
 	}
 
+	wake_up_klogd();
 	return printed_len;
 }
 EXPORT_SYMBOL(vprintk_emit);
@@ -2289,9 +2290,7 @@ void console_unlock(void)
 {
 	static char ext_text[CONSOLE_EXT_LOG_MAX];
 	static char text[LOG_LINE_MAX + PREFIX_MAX];
-	static u64 seen_seq;
 	unsigned long flags;
-	bool wake_klogd = false;
 	bool do_cond_resched, retry;
 
 	if (console_suspended) {
@@ -2335,11 +2334,6 @@ void console_unlock(void)
 
 		printk_safe_enter_irqsave(flags);
 		raw_spin_lock(&logbuf_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",
 				      (unsigned)(log_first_seq - console_seq));
@@ -2397,7 +2391,7 @@ void console_unlock(void)
 
 		if (console_lock_spinning_disable_and_check()) {
 			printk_safe_exit_irqrestore(flags);
-			goto out;
+			return;
 		}
 
 		printk_safe_exit_irqrestore(flags);
@@ -2429,10 +2423,6 @@ void console_unlock(void)
 
 	if (retry && console_trylock())
 		goto again;
-
-out:
-	if (wake_klogd)
-		wake_up_klogd();
 }
 EXPORT_SYMBOL(console_unlock);
 
-- 
2.17.0

Re: [PATCHv2] printk: wake up klogd in vprintk_emit

[Petr Mladek]

On Thu 2018-04-19 10:42:50, Sergey Senozhatsky wrote:
> We wake up klogd very late - only when current console_sem owner
> is done pushing pending kernel messages to the serial/net consoles.
> In some cases this results in lost syslog messages, because kernel
> log buffer is a circular buffer and if we don't wakeup syslog long
> enough there are chances that logbuf simply will wrap around.
> 
> The patch moves the klog wake up call to vprintk_emit(), which is
> the only legit way for a kernel message to appear in the logbuf,
> right before we attempt to grab the console_sem (possibly spinning
> on it waiting for the hand off) and call console drivers.

The last two lines need an update. What about?

"right after the attempt to handle consoles. As a result, klog
will get waken either after flushing the new message to consoles
or immediately when consoles are still busy with older messages."

Otherwise, it looks nice:

Reviewed-by: Petr Mladek <pmladek@suse.com>

Best Regards,
Petr

Re: [PATCHv2] printk: wake up klogd in vprintk_emit

[Sergey Senozhatsky]

On (04/19/18 12:02), Petr Mladek wrote:
> On Thu 2018-04-19 10:42:50, Sergey Senozhatsky wrote:
> > We wake up klogd very late - only when current console_sem owner
> > is done pushing pending kernel messages to the serial/net consoles.
> > In some cases this results in lost syslog messages, because kernel
> > log buffer is a circular buffer and if we don't wakeup syslog long
> > enough there are chances that logbuf simply will wrap around.
> > 
> > The patch moves the klog wake up call to vprintk_emit(), which is
> > the only legit way for a kernel message to appear in the logbuf,
> > right before we attempt to grab the console_sem (possibly spinning
> > on it waiting for the hand off) and call console drivers.
> 
> The last two lines need an update. What about?

Ah. Indeed!

> "right after the attempt to handle consoles. As a result, klog
> will get waken either after flushing the new message to consoles
> or immediately when consoles are still busy with older messages."

Looks good. Do you want me to resend the patch?

> Otherwise, it looks nice:
> 
> Reviewed-by: Petr Mladek <pmladek@suse.com>

Thanks.

	-ss

Re: [PATCHv2] printk: wake up klogd in vprintk_emit

[Petr Mladek]

On Fri 2018-04-20 10:52:21, Sergey Senozhatsky wrote:
> On (04/19/18 12:02), Petr Mladek wrote:
> > On Thu 2018-04-19 10:42:50, Sergey Senozhatsky wrote:
> > > We wake up klogd very late - only when current console_sem owner
> > > is done pushing pending kernel messages to the serial/net consoles.
> > > In some cases this results in lost syslog messages, because kernel
> > > log buffer is a circular buffer and if we don't wakeup syslog long
> > > enough there are chances that logbuf simply will wrap around.
> > > 
> > > The patch moves the klog wake up call to vprintk_emit(), which is
> > > the only legit way for a kernel message to appear in the logbuf,
> > > right before we attempt to grab the console_sem (possibly spinning
> > > on it waiting for the hand off) and call console drivers.
> > 
> > The last two lines need an update. What about?
> 
> Ah. Indeed!
> 
> > "right after the attempt to handle consoles. As a result, klog
> > will get waken either after flushing the new message to consoles
> > or immediately when consoles are still busy with older messages."
> 
> Looks good. Do you want me to resend the patch?

No need to resend. I could update the patch when pushing.

I'll wait few more days to give people time to respond.

Best Regards,
Petr

Re: [PATCHv2] printk: wake up klogd in vprintk_emit

[Petr Mladek]

On Fri 2018-04-20 10:52:21, Sergey Senozhatsky wrote:
> On (04/19/18 12:02), Petr Mladek wrote:
> > On Thu 2018-04-19 10:42:50, Sergey Senozhatsky wrote:
> > > We wake up klogd very late - only when current console_sem owner
> > > is done pushing pending kernel messages to the serial/net consoles.
> > > In some cases this results in lost syslog messages, because kernel
> > > log buffer is a circular buffer and if we don't wakeup syslog long
> > > enough there are chances that logbuf simply will wrap around.
> > > 
> > > The patch moves the klog wake up call to vprintk_emit(), which is
> > > the only legit way for a kernel message to appear in the logbuf,
> > > right before we attempt to grab the console_sem (possibly spinning
> > > on it waiting for the hand off) and call console drivers.
> > 
> > The last two lines need an update. What about?
> 
> Ah. Indeed!
> 
> > "right after the attempt to handle consoles. As a result, klog
> > will get waken either after flushing the new message to consoles
> > or immediately when consoles are still busy with older messages."
> 
> Looks good. Do you want me to resend the patch?

JFYI, I have updated the commit message and pushed the patch into
printk.git, for-4.18 branch.

Best Regards,
Petr

Re: [PATCHv2] printk: wake up klogd in vprintk_emit

[Sergey Senozhatsky]

On (04/25/18 15:23), Petr Mladek wrote:
> > 
> > Looks good. Do you want me to resend the patch?
> 
> JFYI, I have updated the commit message and pushed the patch into
> printk.git, for-4.18 branch.

Thanks!

	-ss