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

[Paul E. McKenney]

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.

Hello, Jan,

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.

							Thanx, Paul

> Signed-off-by: Jan Kara <jack@xxxxxxx>
> ---
>  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@xxxxxxxxxxxxxxx
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
> 

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/