Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit
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
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
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
Re: [PATCH 2/2] printk: wake up klogd in vprintk_emit
On Wed, 18 Apr 2018 17:02:14 +0200 Petr Mladek 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
On Wed 2018-04-18 10:29:43, Steven Rostedt wrote: > On Sat, 14 Apr 2018 12:01:45 +0900 > Sergey Senozhatsky 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
On Sat, 14 Apr 2018 12:01:45 +0900 Sergey Senozhatsky 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
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 > --- > 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
[PATCH 2/2] printk: wake up klogd in vprintk_emit
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 --- 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