Re: [PATCH v3] printk: Avoid softlockups in console_unlock()

[Jan Kara <jack@suse.cz>]

  Hello Paul,

On Wed 27-02-13 09:59:45, Paul E. McKenney wrote:
> On Wed, Feb 27, 2013 at 02:16:59AM +0100, Jan Kara wrote:
> > A CPU can be caught in console_unlock() for a long time (tens of seconds
> > are reported by our customers) when other CPUs are using printk heavily
> > and serial console makes printing slow. Despite serial console drivers
> > are calling touch_nmi_watchdog() this triggers softlockup warnings
> > because interrupts are effectively disabled for the whole time printing
> > takes place. Thus IPIs cannot be processed and other CPUs get stuck
> > spinning in calls like smp_call_function_many(). Also RCU eventually
> > starts reporting lockups.
> > 
> > In my artifical testing I also managed to trigger a situation when disk
> > disappeared from the system apparently because commands to / from it
> > could not be delivered for long enough. This is why just silencing
> > watchdogs isn't a reliable solution to the problem.
> > 
> > One part of fixing the issue is changing vprintk_emit() to call
> > console_unlock() with interrupts enabled (this isn't perfect as printk()
> > itself can be called with interrupts disabled but it improves the
> > situation in lots of cases). Another part is limiting the time we spend
> > in console_unlock() printing loop to watchdog_thresh() / 4. Then we
> > release console_sem and wait for watchdog_thresh() / 4 to give a chance
> > to other printk() users to get the semaphore and start printing. If
> > printk() was called with interrupts enabled, it also gives CPU a chance
> > to process blocked interrupts. Then we recheck if there's still anything
> > to print, try to grab console_sem again and if we succeed, we go on with
> > printing.
> 
> If a CPU remains in your loop where you invoke rcu_cpu_stall_reset(),
> there is no indication of the stall.  Now, I do understand why having
> RCU add a CPU stall warning into the mix would be very bad, but it
> would be good to have some sort of indication that there is stalling.
> Perhaps a counter visible in sysfs?  Whatever it is, at least some way
> of diagnosing the stall condition would be very good.
  I see. If others (Andrew, ping?) are OK with the rest of the patch, I can
extend it and add a counter of printk() breaks we had to make. That looks
like a good idea.

								Honza

> > Signed-off-by: Jan Kara <jack@suse.cz>
> > ---
> >  include/linux/nmi.h |   18 ++++++++++++++++++
> >  kernel/printk.c     |   44 ++++++++++++++++++++++++++++++++++++++------
> >  2 files changed, 56 insertions(+), 6 deletions(-)
> > 
> > Andrew, I was playing with this problem some more and this patch is the least
> > scary fix I found ;). It may slow down printing in heavy-printk cases though.
> > What do you think?
> > 
> > diff --git a/include/linux/nmi.h b/include/linux/nmi.h
> > index db50840..ce32959 100644
> > --- a/include/linux/nmi.h
> > +++ b/include/linux/nmi.h
> > @@ -51,6 +51,24 @@ extern int watchdog_thresh;
> >  struct ctl_table;
> >  extern int proc_dowatchdog(struct ctl_table *, int ,
> >  			   void __user *, size_t *, loff_t *);
> > +/*
> > + * Return the maximum number of nanosecond for which interrupts may be disabled
> > + * on the current CPU
> > + */
> > +static inline u64 max_interrupt_disabled_duration(void)
> > +{
> > +	/*
> > +	 * We give us some headroom because timers need time to fire before the
> > +	 * watchdog period expires.
> > +	 */
> > +	return ((u64)watchdog_thresh) * NSEC_PER_SEC / 2;
> > +}
> > +#else
> > +static inline u64 max_interrupt_disabled_duration(void)
> > +{
> > +	/* About the value we'd get with the default watchdog setting */
> > +	return 5ULL * NSEC_PER_SEC;
> > +}
> >  #endif
> > 
> >  #endif
> > diff --git a/kernel/printk.c b/kernel/printk.c
> > index 0b31715..2f4d9a4 100644
> > --- a/kernel/printk.c
> > +++ b/kernel/printk.c
> > @@ -1522,7 +1522,8 @@ asmlinkage int vprintk_emit(int facility, int level,
> >  		 */
> >  		if (!oops_in_progress && !lockdep_recursing(current)) {
> >  			recursion_bug = 1;
> > -			goto out_restore_irqs;
> > +			local_irq_restore(flags);
> > +			return printed_len;
> >  		}
> >  		zap_locks();
> >  	}
> > @@ -1616,17 +1617,19 @@ asmlinkage int vprintk_emit(int facility, int level,
> >  	/*
> >  	 * Try to acquire and then immediately release the console semaphore.
> >  	 * The release will print out buffers and wake up /dev/kmsg and syslog()
> > -	 * users.
> > +	 * users. We call console_unlock() with interrupts enabled if possible
> > +	 * since printing can take a long time.
> >  	 *
> >  	 * The console_trylock_for_printk() function will release 'logbuf_lock'
> >  	 * regardless of whether it actually gets the console semaphore or not.
> >  	 */
> > -	if (console_trylock_for_printk(this_cpu))
> > +	if (console_trylock_for_printk(this_cpu)) {
> > +		local_irq_restore(flags);
> >  		console_unlock();
> > +	} else
> > +		local_irq_restore(flags);
> > 
> >  	lockdep_on();
> > -out_restore_irqs:
> > -	local_irq_restore(flags);
> > 
> >  	return printed_len;
> >  }
> > @@ -2046,6 +2049,8 @@ void console_unlock(void)
> >  	unsigned long flags;
> >  	bool wake_klogd = false;
> >  	bool retry;
> > +	u64 end_time, now;
> > +	int cur_cpu;
> > 
> >  	if (console_suspended) {
> >  		up(&console_sem);
> > @@ -2053,6 +2058,15 @@ void console_unlock(void)
> >  	}
> > 
> >  	console_may_schedule = 0;
> > +	preempt_disable();
> > +	cur_cpu = smp_processor_id();
> > +	/*
> > +	 * We give us some headroom because we check the time only after
> > +	 * printing the whole message
> > +	 */
> > +	end_time = cpu_clock(cur_cpu) + max_interrupt_disabled_duration() / 2;
> > +	preempt_enable();
> > +
> > 
> >  	/* flush buffered message fragment immediately to console */
> >  	console_cont_flush(text, sizeof(text));
> > @@ -2075,7 +2089,8 @@ again:
> >  			console_prev = 0;
> >  		}
> >  skip:
> > -		if (console_seq == log_next_seq)
> > +		now = sched_clock_cpu(cur_cpu);
> > +		if (console_seq == log_next_seq || now > end_time)
> >  			break;
> > 
> >  		msg = log_from_idx(console_idx);
> > @@ -2121,6 +2136,23 @@ skip:
> >  	up(&console_sem);
> > 
> >  	/*
> > +	 * If the printing took too long, wait a bit to give other CPUs a
> > +	 * chance to take console_sem or at least provide some time for
> > +	 * interrupts to be processed (if we are lucky enough and they are
> > +	 * enabled at this point).
> > +	 */
> > +	if (now > end_time) {
> > +		/*
> > +		 * We won't reach RCU quiescent state anytime soon, silence
> > +		 * the warnings.
> > +		 */
> > +		local_irq_save(flags);
> > +		rcu_cpu_stall_reset();
> > +		local_irq_restore(flags);
> > +		ndelay(max_interrupt_disabled_duration() / 2);
> > +	}
> > +
> > +	/*
> >  	 * 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
> > -- 
> > 1.7.1
> > 
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> > Please read the FAQ at  http://www.tux.org/lkml/
> > 
> 
-- 
Jan Kara <jack@suse.cz>
SUSE Labs, CR