Re: [PATCH 1/7] printk: Hand over printing to console if printing too long

From: Jan Kara
Date: Tue Jan 12 2016 - 09:00:12 EST


On Mon 11-01-16 13:54:34, Petr Mladek wrote:
> On Tue 2015-12-22 14:47:30, Jan Kara wrote:
> > On Thu 10-12-15 23:52:51, Sergey Senozhatsky wrote:
> > > *** in this email and in every later emails ***
> > Over last few days I have worked on redoing the stuff as we
> > discussed with Linus and Andrew at Kernel Summit and I have new patches
> > which are working fine for me. I still want to test them on some machines
> > having real issues with udev during boot but so far stress-testing with
> > serial console slowed down to ~1000 chars/sec on other machines and VMs
> > looks promising.
> >
> > I'm attaching them in case you want to have a look. They are on top of
> > Tejun's patch adding cond_resched() (which is essential). I'll officially
> > submit the patches once the testing is finished (but I'm not sure when I
> > get to the problematic HW...).
> >
> > [1] http://www.spinics.net/lists/stable/msg111535.html
> > --
> > Jan Kara <jack@xxxxxxxx>
> > SUSE Labs, CR
>
> > >From 2e9675abbfc0df4a24a8c760c58e8150b9a31259 Mon Sep 17 00:00:00 2001
> > From: Jan Kara <jack@xxxxxxx>
> > Date: Mon, 21 Dec 2015 13:10:31 +0100
> > Subject: [PATCH 1/2] printk: Make printk() completely async
> >
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -1803,10 +1869,24 @@ asmlinkage int vprintk_emit(int facility, int level,
> > logbuf_cpu = UINT_MAX;
> > raw_spin_unlock(&logbuf_lock);
> > lockdep_on();
> > + /*
> > + * By default we print message to console asynchronously so that kernel
> > + * doesn't get stalled due to slow serial console. That can lead to
> > + * softlockups, lost interrupts, or userspace timing out under heavy
> > + * printing load.
> > + *
> > + * However we resort to synchronous printing of messages during early
> > + * boot, when oops is in progress, or when synchronous printing was
> > + * explicitely requested by kernel parameter.
> > + */
> > + if (keventd_up() && !oops_in_progress && !sync_print) {
> > + __this_cpu_or(printk_pending, PRINTK_PENDING_OUTPUT);
> > + irq_work_queue(this_cpu_ptr(&wake_up_klogd_work));
>
> I wonder if it is safe to use sync_print for early messages
> from the scheduler. Well, in this case, we might need to print
> the messages directly from the irq context because the system
> workqueue is not ready yet :-(

Yeah, you are right that early scheduler messages can currently result in a
deadlock. I'll handle this case. Thanks for catching this.

> > + } else
> > + sync_print = true;
> > local_irq_restore(flags);
> >
> > - /* If called from the scheduler, we can not call up(). */
> > - if (!in_sched) {
> > + if (sync_print) {
> > lockdep_off();
> > /*
> > * Disable preemption to avoid being preempted while holding
>
> > >From be116ae18f15f0d2d05ddf0b53eaac184943d312 Mon Sep 17 00:00:00 2001
> > From: Jan Kara <jack@xxxxxxx>
> > Date: Mon, 21 Dec 2015 14:26:13 +0100
> > Subject: [PATCH 2/2] printk: Skip messages on oops
> >
> > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> > index d455d1bd0d2c..fc67ab70e9c7 100644
> > --- a/kernel/printk/printk.c
> > +++ b/kernel/printk/printk.c
> > @@ -262,6 +262,9 @@ static u64 console_seq;
> > static u32 console_idx;
> > static enum log_flags console_prev;
> >
> > +/* current record sequence when oops happened */
> > +static u64 oops_start_seq;
> > +
> > /* the next printk record to read after the last 'clear' command */
> > static u64 clear_seq;
> > static u32 clear_idx;
> > @@ -1783,6 +1786,8 @@ asmlinkage int vprintk_emit(int facility, int level,
> > NULL, 0, recursion_msg,
> > strlen(recursion_msg));
> > }
> > + if (oops_in_progress && !sync_print && !oops_start_seq)
> > + oops_start_seq = log_next_seq;
>
> sync_print is false for scheduler messages here. Therefore we might
> skip messages even when user set printk.synchronous on the
> command line.

Ah, right. I'll fix this. Thanks!

Honza
--
Jan Kara <jack@xxxxxxxx>
SUSE Labs, CR