Re: [PATCH] printk: rebalance printk

[Pan Xinhui <xinhuix.pan@intel.com>]

I think you have already known how to reproduce it. Let me still share the debug patch to hit this printk issue in several seconds.

+static int auto_printk(void *data)
+{
+       int irq = (int)data;
+       char b[64] = {
+               [0 ... 61] = 'F',
+               '\n',
+               0,
+       };
+
+       int bytes_per_second = 115200/8; //minicom console ratelimit
+       int lines_per_second = bytes_per_second/(sizeof(b)+16);//16 is count of extra bytes including log_prefix
+       int lines_with_5sec = lines_per_second * 5;
+       int i = lines_with_5sec;
+
+       if (irq)
+               local_irq_disable();
+       unsigned long j = jiffies;
+       unsigned long k = jiffies;
+       while (i--) {
+               k = jiffies;
+               if (k > j + 5 * HZ) {
+                       printk("XINHUI: long time %d,%d\n", irq, irqs_disabled());
+               }
+               j = k;
+       }
+       if (irq)
+               local_irq_enable();
+       return 0;
+}
+static int xh_th(const char *val, struct kernel_param *kp)
+{
+       kthread_run(auto_printk, 1, "XH_T1");
+       kthread_run(auto_printk, 0, "XH_T0");
+}
+module_param_call(th, NULL, xh_th, NULL, 0664);
+

thanks
xinhui

On 2015年08月11日 19:23, Pan Xinhui wrote:
> From: Pan Xinhui <xinhuix.pan@intel.com>
> 
> printk can be called in any context, It's very useful to output debug
> info.
> 
> But it might cause very bad issues on some special cases. For example,
> some driver hit errors, and it dumps many messages like reg values, etc. 
> 
> Sometimes, printk is called when irqs disabled. This is OKay if there is
> a few messages. But What would happen if many messages outputted by other
> drivers at same time.
> 
> Here is the scenario.
> CPUA					CPUB
> 					local_irq_save(flags);
> 					printk()
> while(..) {					--> console_unlock
> 	printk(...);			
> 	//hundreds or thousands loops
> }				//all messages flushed out to consoles
> 					local_irq_restore(flags);
> 
> printk runs on CPUA just store the messages in the buf and return.
> printk runs on CPUB(who owns the console_sem lock) would take the duty
> to flush all messages to consoles. It would take a long time to flush
> messages out, IOW, irq would be disabled for a long time. Such case is
> too bad.  We hit many interrupt related panics, for example, cpu did not
> respond to IPI.
> 
> Here is the solution, if we detect such case above, try to rebalance it.
> Let CPUA take the duty to flush messages to consoles.
> 
> The idea is simple, but the implementation is a little difficult.
> Introduce many help functions to fix it.
> 
> Signed-off-by: Pan Xinhui <xinhuix.pan@intel.com>
> ---
>  kernel/printk/printk.c | 101 ++++++++++++++++++++++++++++++++++++++++++++++++-
>  1 file changed, 100 insertions(+), 1 deletion(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index cf8c242..3dc2f60 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1652,6 +1652,65 @@ static size_t cont_print_text(char *text, size_t size)
>  	return textlen;
>  }
>  
> +static struct {
> +	unsigned int request:1;/* set it with logbuf_lock and console_sem held
> +				* clear it with logbuf_lock held.
> +				*/
> +	unsigned int reply:1; /* set/clear it with logbuf_lock held*/
> +	struct semaphore help_sem;
> +} help_t = {
> +	.request = 0,
> +	.reply = 0,
> +	.help_sem = __SEMAPHORE_INITIALIZER(help_t.help_sem, 0),
> +};
> +
> +/* protected by logbuf_lock*/
> +static int check_help(void)
> +{
> +	return !!help_t.request;
> +}
> +
> +/* protected by logbuf_lock and console_sem*/
> +static void request_help(void)
> +{
> +	help_t.request = 1;
> +}
> +
> +/* protected by logbuf_lock*/
> +static void cancel_help(void)
> +{
> +	help_t.request = 0;
> +}
> +
> +/* protected by logbuf_lock*/
> +static void reply_help(void)
> +{
> +	help_t.request = 0;
> +	help_t.reply = 1;
> +}
> +
> +/* protected by logbuf_lock*/
> +static int ack_help(void)
> +{
> +	return !!help_t.reply;
> +}
> +
> +/* protected by logbuf_lock*/
> +static void close_help(void)
> +{
> +	help_t.reply = 0;
> +}
> +
> +static void thanks_help(void)
> +{
> +	up(&help_t.help_sem);
> +}
> +
> +static int done_help(void)
> +{
> +	return !down_trylock(&help_t.help_sem);
> +}
> +
>  asmlinkage int vprintk_emit(int facility, int level,
>  			    const char *dict, size_t dictlen,
>  			    const char *fmt, va_list args)
> @@ -1667,6 +1726,8 @@ asmlinkage int vprintk_emit(int facility, int level,
>  	bool in_sched = false;
>  	/* cpu currently holding logbuf_lock in this function */
>  	static unsigned int logbuf_cpu = UINT_MAX;
> +	bool help = 0;
> +	bool can_help = !(irqs_disabled() || in_sched || in_interrupt());
>  
>  	if (level == LOGLEVEL_SCHED) {
>  		level = LOGLEVEL_DEFAULT;
> @@ -1701,6 +1762,10 @@ asmlinkage int vprintk_emit(int facility, int level,
>  
>  	lockdep_off();
>  	raw_spin_lock(&logbuf_lock);
> +	if (can_help && check_help()) {
> +		reply_help();
> +		help = true;
> +	}
>  	logbuf_cpu = this_cpu;
>  
>  	if (unlikely(recursion_bug)) {
> @@ -1811,6 +1876,9 @@ asmlinkage int vprintk_emit(int facility, int level,
>  		 */
>  		preempt_disable();
>  
> +		if (help)
> +			while (!done_help())
> +				cpu_relax();
>  		/*
>  		 * Try to acquire and then immediately release the console
>  		 * semaphore.  The release will print out buffers and wake up
> @@ -2230,6 +2298,8 @@ void console_unlock(void)
>  	unsigned long flags;
>  	bool wake_klogd = false;
>  	bool retry;
> +	bool help = !!(irqs_disabled() || in_interrupt());
> +	bool skip_ack = true;
>  
>  	if (console_suspended) {
>  		up_console_sem();
> @@ -2248,6 +2318,21 @@ again:
>  		int level;
>  
>  		raw_spin_lock_irqsave(&logbuf_lock, flags);
> +		if (help) {
> +			if (!skip_ack) {
> +				if (ack_help()) {
> +					/*
> +					* If request got replyed by another
> +					* printk-on-going, close the request.
> +					*/
> +					close_help();
> +					break;
> +				}
> +				cancel_help();
> +			}
> +			request_help();
> +			skip_ack = 0;
> +		}
>  		if (seen_seq != log_next_seq) {
>  			wake_klogd = true;
>  			seen_seq = log_next_seq;
> @@ -2265,8 +2350,13 @@ again:
>  			len = 0;
>  		}
>  skip:
> -		if (console_seq == log_next_seq)
> +		if (console_seq == log_next_seq) {
> +			if (help) {
> +				cancel_help();
> +				help = 0;
> +			}
>  			break;
> +		}
>  
>  		msg = log_from_idx(console_idx);
>  		if (msg->flags & LOG_NOCONS) {
> @@ -2318,6 +2408,14 @@ skip:
>  
>  	up_console_sem();
>  
> +	if (help) {
> +		/*
> +		* Need call up_console_sem first.
> +		*/
> +		thanks_help();
> +		goto wake_up;
> +	}
> +
>  	/*
>  	 * 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,
> @@ -2331,6 +2429,7 @@ skip:
>  	if (retry && console_trylock())
>  		goto again;
>  
> +wake_up:
>  	if (wake_klogd)
>  		wake_up_klogd();
>  }
>