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

[Jan Kara]

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