Re: [PATCH] printk: avoid livelock if another CPU printks continuously

[Denys Vlasenko]

On 02/08/2016 10:11 PM, Steven Rostedt wrote:
> On Mon,  8 Feb 2016 21:35:03 +0100
>> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
>> index c963ba5..ca4f9d55 100644
>> --- a/kernel/printk/printk.c
>> +++ b/kernel/printk/printk.c
>> @@ -2235,6 +2235,7 @@ void console_unlock(void)
>>  	unsigned long flags;
>>  	bool wake_klogd = false;
>>  	bool do_cond_resched, retry;
>> +	unsigned cnt;
>>  
>>  	if (console_suspended) {
>>  		up_console_sem();
>> @@ -2257,6 +2258,7 @@ void console_unlock(void)
>>  	/* flush buffered message fragment immediately to console */
>>  	console_cont_flush(text, sizeof(text));
>>  again:
>> +	cnt = 5;
>>  	for (;;) {
>>  		struct printk_log *msg;
>>  		size_t ext_len = 0;
>> @@ -2284,6 +2286,9 @@ skip:
>>  		if (console_seq == log_next_seq)
>>  			break;
>>  
>> +		if (--cnt == 0)
>> +			break;	/* Someone else printk's like crazy */
>> +
>>  		msg = log_from_idx(console_idx);
>>  		if (msg->flags & LOG_NOCONS) {
>>  			/*
>> @@ -2350,6 +2355,26 @@ skip:
>>  	if (retry && console_trylock())
>>  		goto again;
>>  
>> +	if (cnt == 0) {
>> +		/*
>> +		 * Other CPU(s) printk like crazy, filling log_buf[].
>> +		 * Try to get rid of the "honor" of servicing their data:
>> +		 * give _them_ time to grab console_sem and start working.
>> +		 */
>> +		cnt = 9999;
> 
> I'll ignore that this looks very hacky.
> 
>> +		while (--cnt != 0) {
>> +			cpu_relax();
>> +			if (console_seq == log_next_seq) {
>> +                               goto out;
>> +                    }
>> +             }
> 
> First, console_seq needs logbuf_lock protection. On some archs, this may
> hit 9999 every time as the console_seq is most likely in cache and isn't
> updating.

We end up here only in one case:

               if (console_seq == log_next_seq)
                       break;

               if (--cnt == 0)
                       break;  /* Someone else printk's like crazy */

- if this second "break" triggers.
In this case, "console_seq == log_next_seq" can't be true.

Therefore, if we later see that console_seq become
equal to log_next_seq (even if momentarily), then other CPU definitely
entered printk servicing loop. Which means that we are off the hook
- that other CPU is responsible now. We can bail out.

I saw this as a cheap (no locking ops, no writes) way to check whether
we can exit cpu_relax() loop early. It is not reliable, yes.
The definitive check for the case where no one took the job is later,
"if (console_trylock())". If that trylock succeeds, we must iterate
over the buffer once again - there might be unserviced printk messages.

(Why early exit check it is effective?
IIRC cpu_relax() is a memory barrier. Compiler is not allowed to cache
memory variables across it, thus "if (console_seq == log_next_seq)..."
check always re-reads these variables from memory.
)

Not that I am particularly attached to this particular form of the check.
Propose a better method. Do you prefer
"if (console_seq != saved_console_seq)"? Do you want READ_ONCE() there?

>> +				/* Good, other CPU entered "for(;;)" loop */
>> +				goto out;
>> +			}
>> +		}
>> +		/* No one seems to be willing to take it... */
>> +		if (console_trylock())
>> +			goto again; /* we took it */
> 
> Perhaps add a few loops to the taking of the console sem.

Why?

If we fail to take the lock, another CPU took it.
There is no need to try harder, as soon as we know that any
other CPU took that lock, we can safely exit this function.