Re: [RFC][PATCHv2 2/8] printk: introduce printing kernel thread

[Pavel Machek]

Hi!

> printk() is quite complex internally and, basically, it does two
> slightly independent things:
>  a) adds a new message to a kernel log buffer (log_store())
>  b) prints kernel log messages to serial consoles (console_unlock())
> 
> while (a) is guaranteed to be executed by printk(), (b) is not, for a
> variety of reasons, and, unlike log_store(), it comes at a price:
> 
>  1) console_unlock() attempts to flush all pending kernel log messages
> to the console. Thus, it can loop indefinitely.
> 
>  2) while console_unlock() is executed on one particular CPU, printing
> pending kernel log messages, other CPUs can simultaneously append new
> messages to the kernel log buffer.
> 
>  3) the time it takes console_unlock() to print kernel messages also
> depends on the speed of the console -- which may not be fast at all.
> 
>  4) console_unlock() is executed in the same context as printk(), so
> it may be non-preemptible/atomic, which makes 1)-3) dangerous.
> 
> As a result, nobody knows how long a printk() call will take, so
> it's not really safe to call printk() in a number of situations,
> including atomic context, RCU critical sections, interrupt context,
> and more.

You have made good argumentation for not flushing unlimited ammount of
messages from printk() -- okay. But I don't think this is good idea:

> @@ -1765,17 +1803,40 @@ asmlinkage int vprintk_emit(int facility, int level,
>  
>  	printed_len += log_output(facility, level, lflags, dict, dictlen, text, text_len);
>  
> +	/*
> +	 * Emergency level indicates that the system is unstable and, thus,
> +	 * we better stop relying on wake_up(printk_kthread) and try to do
> +	 * a direct printing.
> +	 */
> +	if (level == LOGLEVEL_EMERG)
> +		printk_kthread_disabled = true;
> +
> +	set_bit(PRINTK_PENDING_OUTPUT, &printk_pending);

Messages lower then _EMERG may be important, too.. and usually are,
for debugging.

And you keep both code paths, anyway, so they have to work. So you did
not really "fix" issues you are pointing out -- they still remain
there for _EMERG and above.

I agree that printing too much is a problem. Could you just print
"(messages delayed)" in that case, then wake a kernel thread to [rint
the rest?

								Pavel


>  	logbuf_unlock_irqrestore(flags);
>  
>  	/* If called from the scheduler, we can not call up(). */
>  	if (!in_sched) {
>  		/*
> -		 * Try to acquire and then immediately release the console
> -		 * semaphore.  The release will print out buffers and wake up
> -		 * /dev/kmsg and syslog() users.
> +		 * Under heavy printing load/slow serial console/etc
> +		 * console_unlock() can stall CPUs, which can result in
> +		 * soft/hard-lockups, lost interrupts, RCU stalls, etc.
> +		 * Therefore we attempt to print the messages to console
> +		 * from a dedicated printk_kthread, which always runs in
> +		 * schedulable context.
>  		 */
> -		if (console_trylock())
> -			console_unlock();
> +		if (printk_kthread_enabled()) {
> +			printk_safe_enter_irqsave(flags);
> +			wake_up_process(printk_kthread);
> +			printk_safe_exit_irqrestore(flags);
> +		} else {
> +			/*
> +			 * Try to acquire and then immediately release the
> +			 * console semaphore. The release will print out
> +			 * buffers and wake up /dev/kmsg and syslog() users.
> +			 */
> +			if (console_trylock())
> +				console_unlock();
> +		}
>  	}
>


-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Attachment: signature.asc
Description: Digital signature