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

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

[Denys Vlasenko]

At the end of each printk(), kernel attempts to take console_sem.
If this succeeds, it feeds buffered message data to console devices
until there is nothing left, and releases console_sem:

        if (console_trylock_for_printk(this_cpu))
                console_unlock();

The livelock exists because code in console_unlock() has no
limit on the amount of buffered data it would process under
console_sem. This is bad if printk() was called with IRQs disabled.

This patch makes console_unlock() release console_sem after 5
iterations, which usually amounts to 5 lines of printk messages,
and give other printk'ing CPUs a chance to acquire console_sem.

If some CPU grabs it, console_unlock() finishes.
If no one takes the semaphore, console_unlock() re-acquires it
and loops back for another cycle of console output.

This seems to be a hard-to-trigger, but long-existing problem:

I did not observe the bug myself. I have two separate user reports,
from two different kernels, who report hangs on boot
when a RAID driver produces a voluminous printk flood of disk
detection errors. Some of them are reported by a printk from
IRQ-off region. If that IRQ-off printk gets to print all the
other printks from all other CPUs, the machine hangs.

This patch is reported to make affected user's machine survive.

Signed-off-by: Denys Vlasenko <dvlasenk@redhat.com>
CC: linux-kernel@vger.kernel.org
CC: srostedt@redhat.com
CC: Steven Rostedt <rostedt@goodmis.org>
CC: Tejun Heo <tj@kernel.org>
CC: Peter Hurley <peter@hurleysoftware.com>
---
 kernel/printk/printk.c | 25 +++++++++++++++++++++++++
 1 file changed, 25 insertions(+)

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;
+		while (--cnt != 0) {
+			cpu_relax();
+			if (console_seq == log_next_seq) {
+				/* 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 */
+		/* Nope, someone else holds console_sem! Good */
+	}
+out:
 	if (wake_klogd)
 		wake_up_klogd();
 }
-- 
1.8.1.4

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

[Steven Rostedt]

On Mon,  8 Feb 2016 21:35:03 +0100
Denys Vlasenko <dvlasenk@redhat.com> wrote:


> This patch is reported to make affected user's machine survive.

Would be nice to have a test case for this. Make a test module to
reproduce the issue?

> 
> Signed-off-by: Denys Vlasenko <dvlasenk@redhat.com>
> CC: linux-kernel@vger.kernel.org
> CC: srostedt@redhat.com
> CC: Steven Rostedt <rostedt@goodmis.org>
> CC: Tejun Heo <tj@kernel.org>
> CC: Peter Hurley <peter@hurleysoftware.com>
> ---
>  kernel/printk/printk.c | 25 +++++++++++++++++++++++++
>  1 file changed, 25 insertions(+)
> 
> 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) {

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. Not to mention the race of another task moving log_next_seq
too and this could have been on another CPU changing both console_seq
and log_next_seq.

Perhaps just save off console_seq and see if it changes at all.


> +				/* 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. But again,
this just sounds like playing with heuristics, and I hate heuristics.

There's gotta be a better solution.

-- Steve

> +		/* Nope, someone else holds console_sem! Good */
> +	}
> +out:
>  	if (wake_klogd)
>  		wake_up_klogd();
>  }

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.

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

[Steven Rostedt]

On Tue, 09 Feb 2016 15:59:48 +0100
Denys Vlasenko <dvlasenk@redhat.com> wrote:

> > 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.

We released all locks, why can't it be true? What prevents another task
on another CPU from coming into this section and updating everything?

> 
> 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.

cpu_relax() is a compiler barrier, not a memory barrier. Yes, the
compiler wont cache the variables, but nothing stops the CPU from doing
so. All archs use this code.

> )
> 
> 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?

Again, READ_ONCE() is only good for the compiler, not the hardware.

spin_locks() are memory barriers, and will sync everything.

> 
> >> +				/* 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.

Because if this CPU is the one spamming the other CPU, it will widen
the window to be the one that takes the lock.

I still think this is very hacky.

-- Steve

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

[Denys Vlasenko]

On 02/09/2016 04:17 PM, Steven Rostedt wrote:
> On Tue, 09 Feb 2016 15:59:48 +0100
> Denys Vlasenko <dvlasenk@redhat.com> wrote:
> 
>>> 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.
> 
> We released all locks, why can't it be true? What prevents another task
> on another CPU from coming into this section and updating everything?

If we see that happening, it means another CPU started serving printk
backlog. In which case, we (this CPU) no longer have the obligation
to service it.

>> 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.
> 
> cpu_relax() is a compiler barrier, not a memory barrier. Yes, the
> compiler wont cache the variables, but nothing stops the CPU from doing
> so. All archs use this code.

We expect caches to be coherent. If another CPU modifies these variables,
our CPU will (eventually) see modified values.

My code does not depend on always catching "console_seq != log_next_seq"
==> "console_seq == log_next_seq" transition. It's okay to miss it.

> spin_locks() are memory barriers, and will sync everything.

They are also much heavier than memory reads.

>>>> +				/* 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.
> 
> Because if this CPU is the one spamming the other CPU, it will widen
> the window to be the one that takes the lock.

If we reached this code, we aren't the spamming CPU. We are the CPU
which is being spammed (we are in the loop which services the backlog).

> I still think this is very hacky.

I'm not insisting on my patch. Propose a different solution.

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

[Steven Rostedt]

On Tue, 09 Feb 2016 16:24:29 +0100
Denys Vlasenko <dvlasenk@redhat.com> wrote:


> > We released all locks, why can't it be true? What prevents another task
> > on another CPU from coming into this section and updating everything?  
> 
> If we see that happening, it means another CPU started serving printk
> backlog. In which case, we (this CPU) no longer have the obligation
> to service it.

I'm saying is that we can repeat when not needed to.

> > cpu_relax() is a compiler barrier, not a memory barrier. Yes, the
> > compiler wont cache the variables, but nothing stops the CPU from doing
> > so. All archs use this code.  
> 
> We expect caches to be coherent. If another CPU modifies these variables,
> our CPU will (eventually) see modified values.

Perhaps, but is that guaranteed on all archs? Maybe not. I have worked
on archs with non coherent caches. They are a pain.

> 
> My code does not depend on always catching "console_seq != log_next_seq"
> ==> "console_seq == log_next_seq" transition. It's okay to miss it.  
> 
> > spin_locks() are memory barriers, and will sync everything.  
> 
> They are also much heavier than memory reads.

Because they are barriers ;-) But don't worry, a printk is never a fast
path. The overhead of taking the locks is not going to be noticed by
anyone.

> 
> >>>> +				/* 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.  
> > 
> > Because if this CPU is the one spamming the other CPU, it will widen
> > the window to be the one that takes the lock.  
> 
> If we reached this code, we aren't the spamming CPU. We are the CPU
> which is being spammed (we are in the loop which services the backlog).

No, I mentioned the taking of console sem. The spamming task will be
trying that a bit, failing and then letting this CPU continue doing its
bidding. The above hopes that the spamming task takes the CPU between
the time this CPU lets go of the lock and does the for loop. But is
that for loop slow enough to catch the spamming CPU writing out more.
Of course, if we add the necessary memory barriers, we don't need to do
that.

> 
> > I still think this is very hacky.  
> 
> I'm not insisting on my patch. Propose a different solution.

I haven't thought about it enough. Perhaps someone else can come up
with something. One thing is to find the spamming code and fix that.

-- Steve

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

[Denys Vlasenko]

On 02/09/2016 04:50 PM, Steven Rostedt wrote:
> One thing is to find the spamming code and fix that.

We can't rely that there won't be never-ending concurrent printks,
right? For one, in many setups user can cause printk flood.

I think we must ensure that printk does not livelock.

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

[Steven Rostedt]

On Tue, 09 Feb 2016 17:07:42 +0100
Denys Vlasenko <dvlasenk@redhat.com> wrote:

> On 02/09/2016 04:50 PM, Steven Rostedt wrote:
> > One thing is to find the spamming code and fix that.  
> 
> We can't rely that there won't be never-ending concurrent printks,
> right? For one, in many setups user can cause printk flood.

No, that would be a bug. This is why we have printk_ratelimit for.

> 
> I think we must ensure that printk does not livelock.

printk is a kernel utility. The users of printk must ensure this.

-- Steve

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

[Denys Vlasenko]

On 02/09/2016 04:50 PM, Steven Rostedt wrote:
> On Tue, 09 Feb 2016 16:24:29 +0100
>>>>>> +				/* 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.  
>>>
>>> Because if this CPU is the one spamming the other CPU, it will widen
>>> the window to be the one that takes the lock.  
>>
>> If we reached this code, we aren't the spamming CPU. We are the CPU
>> which is being spammed (we are in the loop which services the backlog).
> 
> No, I mentioned the taking of console sem. The spamming task will be
> trying that a bit, failing and then letting this CPU continue doing its
> bidding.

That's exactly what we *don't* want to happen.
We want that other CPU to get the lock.

How do you plan to achieve that, if not by giving it a grace period
when it can grab a lock?

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

[Steven Rostedt]

On Tue, 09 Feb 2016 17:41:25 +0100
Denys Vlasenko <dvlasenk@redhat.com> wrote:

 
> > No, I mentioned the taking of console sem. The spamming task will be
> > trying that a bit, failing and then letting this CPU continue doing its
> > bidding.  
> 
> That's exactly what we *don't* want to happen.
> We want that other CPU to get the lock.

I know. I meant that if the task fails to get the lock, it will let the
other continue to do its bidding. Hence the multiple tries. But this is
moot, because it's just adding onto the hacks.


> 
> How do you plan to achieve that, if not by giving it a grace period
> when it can grab a lock?

What really needs to be done is to find out why a CPU is spamming with
printks and fix that. Is it a bug that is triggering?

-- Steve

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

[Petr Mladek]

Sent again with a correct mail header, hopefully.

On Mon 2016-02-08 21:35:03, Denys Vlasenko wrote:
> At the end of each printk(), kernel attempts to take console_sem.
> If this succeeds, it feeds buffered message data to console devices
> until there is nothing left, and releases console_sem:
> 
>         if (console_trylock_for_printk(this_cpu))
>                 console_unlock();
> 
> The livelock exists because code in console_unlock() has no
> limit on the amount of buffered data it would process under
> console_sem. This is bad if printk() was called with IRQs disabled.
> 
> This patch makes console_unlock() release console_sem after 5
> iterations, which usually amounts to 5 lines of printk messages,
> and give other printk'ing CPUs a chance to acquire console_sem.
> 
> If some CPU grabs it, console_unlock() finishes.
> If no one takes the semaphore, console_unlock() re-acquires it
> and loops back for another cycle of console output.
> 
> This seems to be a hard-to-trigger, but long-existing problem:

Yup, and there are more people trying to handle this. I add some
of them into CC.

Sadly, the problem is much more complicated that it looks. Jan Kara
(jack) has already provided many possible solutions that were not
accepted. The last one can be seen at
http://thread.gmane.org/gmane.linux.kernel/2105183/focus=2113787

See below some comments to your approach.

> Signed-off-by: Denys Vlasenko <dvlasenk@redhat.com>
> CC: linux-kernel@vger.kernel.org
> CC: srostedt@redhat.com
> CC: Steven Rostedt <rostedt@goodmis.org>
> CC: Tejun Heo <tj@kernel.org>
> CC: Peter Hurley <peter@hurleysoftware.com>
> ---
>  kernel/printk/printk.c | 25 +++++++++++++++++++++++++
>  1 file changed, 25 insertions(+)
> 
> 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;
> +		while (--cnt != 0) {
> +			cpu_relax();
> +			if (console_seq == log_next_seq) {

This condition is true when all available messages are printed to
the console. It means that there is nothing to do at all. It is
quite late. A much better solution would be to store console_seq
to a local variable and check it is being modified by an other CPU.


> +				/* 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 */
> +		/* Nope, someone else holds console_sem! Good */

The cycle gives a big chance other CPUs to enter console_unlock().
It means that more CPUs might end up in the above busy cycle.

It gives a chance to move the printing to another CPU. It likely
slows down the flood of messages because the producer end up
here as well.

So, it probably works but the performance is far from optimal.
Many CPUs might end up doing nothing. I am afraid that this is
not the right way to go.

Best Regards,
Petr

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

[Petr Mladek]

On Wed 2016-02-10 09:44:07, Steven Rostedt wrote:
> On Wed, 10 Feb 2016 15:36:49 +0100
> Petr Mladek <pmladek@suse.com> wrote:
> 
> > Bcc: 
> > Subject: Re: [PATCH] printk: avoid livelock if another CPU printks
> >  continuously
> > Reply-To: 
> > In-Reply-To: <1454963703-20433-1-git-send-email-dvlasenk@redhat.com>
> > 
> 
> Hmm, playing with mail headers?

Yeah. I am trying to do this reply back in the original thread.

> > > +				/* 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 */
> > > +		/* Nope, someone else holds console_sem! Good */  
> > 
> > The cycle gives a big chance other CPUs to enter console_unlock().
> > It means that more CPUs might end up in the above busy cycle.
> > 
> > It gives a chance to move the printing to another CPU. It likely
> > slows down the flood of messages because the producer end up
> > here as well.
> > 
> > So, it probably works but the performance is far from optimal.
> > Many CPUs might end up doing nothing. I am afraid that this is
> > not the right way to go.
> 
> Note, it's not that performance critical, and the loop only happens if
> someone else is adding to the console, which hopefully, should be rare.

I probably used too strong words. It is possible that the performance
impact will not be critical. But the behavior is non-deterministic.
I think that the approach taken by Jack is more promising.
I mean the offloading of the console stuff to a workqueue.

Best Regards,
Petr

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

[Steven Rostedt]

On Wed, 10 Feb 2016 17:10:16 +0100
Petr Mladek <pmladek@suse.com> wrote:

> > Note, it's not that performance critical, and the loop only happens if
> > someone else is adding to the console, which hopefully, should be rare.  
> 
> I probably used too strong words. It is possible that the performance
> impact will not be critical. But the behavior is non-deterministic.
> I think that the approach taken by Jack is more promising.
> I mean the offloading of the console stuff to a workqueue.

My worry about that is that it never comes out. The point about printk,
is that it should pretty much be guaranteed to print. If the system is
dying, and we push it off to a work queue, and that workqueue never
runs, then we lose critical data.

-- Steve

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

[Peter Hurley]

On 02/10/2016 08:25 AM, Steven Rostedt wrote:
> On Wed, 10 Feb 2016 17:10:16 +0100
> Petr Mladek <pmladek@suse.com> wrote:
> 
>>> Note, it's not that performance critical, and the loop only happens if
>>> someone else is adding to the console, which hopefully, should be rare.  
>>
>> I probably used too strong words. It is possible that the performance
>> impact will not be critical. But the behavior is non-deterministic.
>> I think that the approach taken by Jack is more promising.
>> I mean the offloading of the console stuff to a workqueue.
> 
> My worry about that is that it never comes out. The point about printk,
> is that it should pretty much be guaranteed to print. If the system is
> dying, and we push it off to a work queue, and that workqueue never
> runs, then we lose critical data.

I agree.

I thought a more promising approach was Pan Xinhui's patch from August [1]
which hands off console output to the incoming cpu. The reqd state machine
is described in more detail in the revised patch [2].

Unfortunately, the patch was abandoned. I think he may have misunderstood
when I also referred to Jack's patches; I meant to simply draw attention
to concurrent work for review and comparison.


[1] original https://lkml.org/lkml/2015/8/11/333
[2] revised https://lkml.org/lkml/2015/8/12/321

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

[Sergey Senozhatsky]

Hello,
Thanks for Cc-ing, and sorry for long reply, I'm traveling now.

On (02/10/16 11:25), Steven Rostedt wrote:
> On Wed, 10 Feb 2016 17:10:16 +0100
> Petr Mladek <pmladek@suse.com> wrote:
> 
> > > Note, it's not that performance critical, and the loop only happens if
> > > someone else is adding to the console, which hopefully, should be rare.  
> > 
> > I probably used too strong words. It is possible that the performance
> > impact will not be critical. But the behavior is non-deterministic.
> > I think that the approach taken by Jack is more promising.
> > I mean the offloading of the console stuff to a workqueue.
> 
> My worry about that is that it never comes out. The point about printk,
> is that it should pretty much be guaranteed to print. If the system is
> dying, and we push it off to a work queue, and that workqueue never
> runs, then we lose critical data.

correct, IIRC Jan agreed to switch to 'direct' (current behaviour) printk when
one of the CPUs calls panic() (we still can use that approach even with
workqueue based printk)
	http://marc.info/?l=linux-kernel&m=145200464309562

the other thing with workqueues based approach is that all of them can be 'blocked'
in some OOM cases, so sort of fallback mechanism is also needed here
	http://marc.info/?l=linux-kernel&m=145251885502488

	-ss

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

[Petr Mladek]

On Thu 2016-02-11 17:21:12, Sergey Senozhatsky wrote:
> Hello,
> Thanks for Cc-ing, and sorry for long reply, I'm traveling now.
> 
> On (02/10/16 11:25), Steven Rostedt wrote:
> > On Wed, 10 Feb 2016 17:10:16 +0100
> > Petr Mladek <pmladek@suse.com> wrote:
> > 
> > > > Note, it's not that performance critical, and the loop only happens if
> > > > someone else is adding to the console, which hopefully, should be rare.  
> > > 
> > > I probably used too strong words. It is possible that the performance
> > > impact will not be critical. But the behavior is non-deterministic.
> > > I think that the approach taken by Jack is more promising.
> > > I mean the offloading of the console stuff to a workqueue.
> > 
> > My worry about that is that it never comes out. The point about printk,
> > is that it should pretty much be guaranteed to print. If the system is
> > dying, and we push it off to a work queue, and that workqueue never
> > runs, then we lose critical data.
> 
> correct, IIRC Jan agreed to switch to 'direct' (current behaviour) printk when
> one of the CPUs calls panic() (we still can use that approach even with
> workqueue based printk)
> 	http://marc.info/?l=linux-kernel&m=145200464309562

Yup.

> the other thing with workqueues based approach is that all of them can be 'blocked'
> in some OOM cases, so sort of fallback mechanism is also needed here
> 	http://marc.info/?l=linux-kernel&m=145251885502488

If this proves to be a problem. We could always use a workqueue with a
rescue worker.

Regarding the patch from Pan Xinhui. My main problem with it is that
it adds many handshakes and twists to the already complicated printk
code. Also it does not solve the problem if the flood of messages
comes entirely from an IRQ context.

Workqueues code is not trivial but mature. And the usage of the workqueues
in printk is quite straightforward.

Best Regards,
Petr