Serial console is causing system lock-up

Serial console is causing system lock-up

[Mikulas Patocka]

Hi

I was debugging some kernel lockup with storage drivers and it turned out 
that the lockup is caused by the serial console subsystem. If we use 
serial console and if we write to it excessively, the kernel sometimes 
lockup, sometimes reports rcu stalls and NMI backtraces. Sometimes it will 
just print the console messages without donig anything else.

This program tests the issue - on framebuffer console, the system is 
sluggish, but it is possible to unload the module with rmmod. On serial 
console, it locks up to the point that unloading the module is not 
possible.

Mikulas



------------

#include <linux/module.h>
#include <linux/init.h>
#include <linux/delay.h>
#include <linux/slab.h>
#include <linux/kthread.h>

int n_threads = 0;
int sleep_ms = 0;

module_param_named(n_threads, n_threads, int, S_IRUGO);
MODULE_PARM_DESC(n_threads, "The number of kernel threads");

module_param_named(sleep_ms, sleep_ms, int, S_IRUGO);
MODULE_PARM_DESC(sleep_ms, "Sleep time in milliseconds");

struct task_struct **tasks;

static int console_dumper(void *data)
{
	int t = (int)(long)data;
	while (!kthread_should_stop()) {
		printk("line from thread %d ---------------------------------------------------------------------------------------------------------------------------------------\n", t);
		if (sleep_ms > 0)
			msleep(sleep_ms);
		cond_resched();
	}
	return 0;
}

static int __init dump_init(void)
{
	int i;
	if (n_threads <= 0)
		n_threads = num_online_cpus();
	tasks = kmalloc(n_threads * sizeof(struct task_struct *), GFP_KERNEL);
	if (!tasks)
		return -ENOMEM;
	for (i = 0; i < n_threads; i++) {
		tasks[i] = kthread_create(console_dumper, (void *)(long)i, "console_dumper");
		if (!tasks[i]) {
			while (i--)
				kthread_stop(tasks[i]);
			kfree(tasks);
			return -ENOMEM;
		}
		wake_up_process(tasks[i]);
	}
	return 0;
}

static void __exit dump_exit(void)
{
	int i;
	for (i = 0; i < n_threads; i++) {
		kthread_stop(tasks[i]);
	}
	kfree(tasks);
}

module_init(dump_init)
module_exit(dump_exit)
MODULE_LICENSE("GPL");

Re: Serial console is causing system lock-up

[Petr Mladek]

On Wed 2019-03-06 09:27:13, Mikulas Patocka wrote:
> Hi
> 
> I was debugging some kernel lockup with storage drivers and it turned out 
> that the lockup is caused by the serial console subsystem. If we use 
> serial console and if we write to it excessively, the kernel sometimes 
> lockup, sometimes reports rcu stalls and NMI backtraces. Sometimes it will 
> just print the console messages without donig anything else.

This is a very old problem that we have been trying to solve for
years. There are two conflicting requirements on printk():
be fast and reliable.

The historical solution is that printk() callers store the messages
into the log buffer and then just _try_ to take the console lock.
The winner who succeeds is responsible for flushing all
pending messages to the console. As a result a random victim
might get blocked by the console handling for a long time.

An obvious solution is offloading the console handling. But
it is against the reliability. There are no guarantees that
the offload mechanism (kthread, irq) would happen when the
system is on their knees.

Anyway, which kernel version are you using, please?

I wonder if you already have the dbdda842fe96f8932 ("printk: Add
console owner and waiter logic to load balance console writes").
It improves the situation a lot. There was a hope that it would
be enough in the real life.


> This program tests the issue - on framebuffer console, the system is 
> sluggish, but it is possible to unload the module with rmmod. On serial 
> console, it locks up to the point that unloading the module is not 
> possible.

Is there any chance to send us logs from the original (real life)
problem, please?

Best regards,
Petr

Re: Serial console is causing system lock-up

[Mikulas Patocka]

On Wed, 6 Mar 2019, Petr Mladek wrote:

> On Wed 2019-03-06 09:27:13, Mikulas Patocka wrote:
> > Hi
> > 
> > I was debugging some kernel lockup with storage drivers and it turned out 
> > that the lockup is caused by the serial console subsystem. If we use 
> > serial console and if we write to it excessively, the kernel sometimes 
> > lockup, sometimes reports rcu stalls and NMI backtraces. Sometimes it will 
> > just print the console messages without donig anything else.
> 
> This is a very old problem that we have been trying to solve for
> years. There are two conflicting requirements on printk():
> be fast and reliable.
> 
> The historical solution is that printk() callers store the messages
> into the log buffer and then just _try_ to take the console lock.
> The winner who succeeds is responsible for flushing all
> pending messages to the console. As a result a random victim
> might get blocked by the console handling for a long time.

This bug only happens if we select large logbuffer (millions of 
characters). With smaller log buffer, there are messages "** X printk 
messages dropped", but there's no lockup.

The kernel apparently puts 2 million characters into a console log buffer, 
then takes some lock and than tries to write all of them to a slow serial 
line.

> An obvious solution is offloading the console handling. But
> it is against the reliability. There are no guarantees that
> the offload mechanism (kthread, irq) would happen when the
> system is on their knees.
> 
> Anyway, which kernel version are you using, please?

RHEL8-4.18, Debian-4.19, Upstream 5.0. I didn't try older versions.

> I wonder if you already have the dbdda842fe96f8932 ("printk: Add
> console owner and waiter logic to load balance console writes").
> It improves the situation a lot. There was a hope that it would
> be enough in the real life.

Yes - this patch is present in the kernels that I tried.

> > This program tests the issue - on framebuffer console, the system is 
> > sluggish, but it is possible to unload the module with rmmod. On serial 
> > console, it locks up to the point that unloading the module is not 
> > possible.
> 
> Is there any chance to send us logs from the original (real life)
> problem, please?
> 
> Best regards,
> Petr

I uploaded the logs here: 
http://people.redhat.com/~mpatocka/testcases/console-lockup/

Mikulas

Re: Serial console is causing system lock-up

[Theodore Y. Ts'o]

On Wed, Mar 06, 2019 at 11:07:55AM -0500, Mikulas Patocka wrote:
> This bug only happens if we select large logbuffer (millions of 
> characters). With smaller log buffer, there are messages "** X printk 
> messages dropped", but there's no lockup.
> 
> The kernel apparently puts 2 million characters into a console log buffer, 
> then takes some lock and than tries to write all of them to a slow serial 
> line.

What are the messages; from what kernel subsystem?  Why are you seeing
so many log messages?

					- Ted

Re: Serial console is causing system lock-up

[Mikulas Patocka]

On Wed, 6 Mar 2019, Theodore Y. Ts'o wrote:

> On Wed, Mar 06, 2019 at 11:07:55AM -0500, Mikulas Patocka wrote:
> > This bug only happens if we select large logbuffer (millions of 
> > characters). With smaller log buffer, there are messages "** X printk 
> > messages dropped", but there's no lockup.
> > 
> > The kernel apparently puts 2 million characters into a console log buffer, 
> > then takes some lock and than tries to write all of them to a slow serial 
> > line.
> 
> What are the messages; from what kernel subsystem?  Why are you seeing
> so many log messages?
> 
> 					- Ted

The dm-integity subsystem (drivers/md/dm-integrity.c) can be attached to a 
block device to provide checksum protection. It will return -EILSEQ and 
print a message to a log for every corrupted block.

Nigel Croxon was testing MD-RAID recovery capabilities in such a way that 
he activated RAID-5 array with one leg replaced by a dm-integrity block 
device that had all checksums invalid.

The MD-RAID is supposed to recalculate data for the corrupted device and 
bring it back to life. However, scrubbing the MD-RAID device resulted in a 
lot of reads from the device with bad checksums, these were reported to 
the log and killed the machine.


I made a patch to dm-integrity to rate-limit the error messages. But 
anyway - killing the machine in case of too many log messages seems bad. 
If the log messages are produced faster than the kernel can write them, 
the kernel should discard some of them, not kill itself.

Mikulas

Re: Serial console is causing system lock-up

[Steven Rostedt]

On Wed, 6 Mar 2019 12:11:10 -0500 (EST)
Mikulas Patocka <mpatocka@redhat.com> wrote:

> On Wed, 6 Mar 2019, Theodore Y. Ts'o wrote:
> 
> > On Wed, Mar 06, 2019 at 11:07:55AM -0500, Mikulas Patocka wrote:  
> > > This bug only happens if we select large logbuffer (millions of 
> > > characters). With smaller log buffer, there are messages "** X printk 
> > > messages dropped", but there's no lockup.
> > > 
> > > The kernel apparently puts 2 million characters into a console log buffer, 
> > > then takes some lock and than tries to write all of them to a slow serial 
> > > line.  
> > 
> > What are the messages; from what kernel subsystem?  Why are you seeing
> > so many log messages?
> > 
> > 					- Ted  
> 
> The dm-integity subsystem (drivers/md/dm-integrity.c) can be attached to a 
> block device to provide checksum protection. It will return -EILSEQ and 
> print a message to a log for every corrupted block.
> 
> Nigel Croxon was testing MD-RAID recovery capabilities in such a way that 
> he activated RAID-5 array with one leg replaced by a dm-integrity block 
> device that had all checksums invalid.
> 
> The MD-RAID is supposed to recalculate data for the corrupted device and 
> bring it back to life. However, scrubbing the MD-RAID device resulted in a 
> lot of reads from the device with bad checksums, these were reported to 
> the log and killed the machine.
> 
> 
> I made a patch to dm-integrity to rate-limit the error messages. But 
> anyway - killing the machine in case of too many log messages seems bad. 
> If the log messages are produced faster than the kernel can write them, 
> the kernel should discard some of them, not kill itself.

Sounds like another aurgment for the new printk design.

-- Steve

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-06, Steven Rostedt <rostedt@goodmis.org> wrote:
>> This bug only happens if we select large logbuffer (millions of
>> characters). With smaller log buffer, there are messages "** X printk
>> messages dropped", but there's no lockup.
>> 
>> The kernel apparently puts 2 million characters into a console log
>> buffer, then takes some lock and than tries to write all of them to a
>> slow serial line.
>>
>> [...]
>>
>> The MD-RAID is supposed to recalculate data for the corrupted device
>> and bring it back to life. However, scrubbing the MD-RAID device
>> resulted in a lot of reads from the device with bad checksums, these
>> were reported to the log and killed the machine.
>> 
>> I made a patch to dm-integrity to rate-limit the error messages. But
>> anyway - killing the machine in case of too many log messages seems
>> bad.  If the log messages are produced faster than the kernel can
>> write them, the kernel should discard some of them, not kill itself.
>
> Sounds like another aurgment for the new printk design.

Assuming the bad checksum messages are considered an emergency (for
example, at least loglevel KERN_WARN), then the new printk design would
print those messages synchronously to the slow serial line in the
context of the driver as the driver is producing them.

There wouldn't be a lock-up, but it would definitely slow down the
driver. The situation of "messages being produced faster than the kernel
can write them" would never exist because the printk() call will only
return after the writing is completed. I am curious if that would be
acceptable here?

John Ogness

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/06/19 23:43), John Ogness wrote:
> > Sounds like another aurgment for the new printk design.
> 
> Assuming the bad checksum messages are considered an emergency (for
> example, at least loglevel KERN_WARN), then the new printk design would
> print those messages synchronously to the slow serial line in the
> context of the driver as the driver is producing them.

I wonder if we have several CPU doing the checksum verification.
New sync printk mechanism has a Big-Konsole-spin-Lock, all CPUs that
want to printk() should line up and wait, in whatever context they
currently are.

> There wouldn't be a lock-up, but it would definitely slow down the
> driver. The situation of "messages being produced faster than the kernel
> can write them" would never exist because the printk() call will only
> return after the writing is completed.

If the serial console is a really slow one and we have a CPU in atomic
context spinnig on prb_lock, while the prb_lock is always acquired by
other CPUs, then it may look like a lock-up scenario.

	-ss

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-07, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
>>> Sounds like another aurgment for the new printk design.
>> 
>> Assuming the bad checksum messages are considered an emergency (for
>> example, at least loglevel KERN_WARN), then the new printk design
>> would print those messages synchronously to the slow serial line in
>> the context of the driver as the driver is producing them.
>
> I wonder if we have several CPU doing the checksum verification.
> New sync printk mechanism has a Big-Konsole-spin-Lock, all CPUs that
> want to printk() should line up and wait, in whatever context they
> currently are.
>
>> There wouldn't be a lock-up, but it would definitely slow down the
>> driver. The situation of "messages being produced faster than the
>> kernel can write them" would never exist because the printk() call
>> will only return after the writing is completed.
>
> If the serial console is a really slow one and we have a CPU in atomic
> context spinnig on prb_lock, while the prb_lock is always acquired by
> other CPUs, then it may look like a lock-up scenario.

When the console is constantly printing messages, I wouldn't say that
looks like a lock-up scenario. It looks like the system is busy printing
critical information to the console (which it is).

John Ogness

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/07/19 09:17), John Ogness wrote:
> > If the serial console is a really slow one and we have a CPU in atomic
> > context spinnig on prb_lock, while the prb_lock is always acquired by
> > other CPUs, then it may look like a lock-up scenario.
> 
> When the console is constantly printing messages, I wouldn't say that
> looks like a lock-up scenario. It looks like the system is busy printing
> critical information to the console (which it is).

What if we have N tasks/CPUs calling printk() simultaneously?

	-ss

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-07, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
>>> If the serial console is a really slow one and we have a CPU in
>>> atomic context spinnig on prb_lock, while the prb_lock is always
>>> acquired by other CPUs, then it may look like a lock-up scenario.
>> 
>> When the console is constantly printing messages, I wouldn't say that
>> looks like a lock-up scenario. It looks like the system is busy
>> printing critical information to the console (which it is).
>
> What if we have N tasks/CPUs calling printk() simultaneously?

Then they take turns printing their messages to the console, spinning
until they get their turn. This still is not and does not look like a
lock-up. But I think you already know this, so I don't understand the
reasoning behind asking the question. Maybe you could clarify what you
are getting at.

John Ogness

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/07/19 09:34), John Ogness wrote:
> >> When the console is constantly printing messages, I wouldn't say that
> >> looks like a lock-up scenario. It looks like the system is busy
> >> printing critical information to the console (which it is).
> >
> > What if we have N tasks/CPUs calling printk() simultaneously?
> 
> Then they take turns printing their messages to the console, spinning
> until they get their turn. This still is not and does not look like a
> lock-up. But I think you already know this, so I don't understand the
> reasoning behind asking the question. Maybe you could clarify what you
> are getting at.

Sorry John, the reasoning is that I'm trying to understand
why this does not look like soft or hard lock-up or RCU stall
scenario.

The CPU which spins on prb_lock() can have preemption disabled and,
additionally, can have local IRQs disabled, or be under RCU read
side lock. If consoles are busy, then there are CPUs which printk()
data and keep prb_lock contended; prb_lock() does not seem to be
fair. What am I missing? You probably talk about the case when all
printing CPUs are in preemptible contexts (assumingly this is what
is happening in dm-integrity case) so they can spin on prb_lock(),
that's OK. The case I'm talking about is - what if we have the same
situation, but then one of the CPUs printk()-s from !preemptible.
Does this make sense?

	-ss

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-07, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
>>>> When the console is constantly printing messages, I wouldn't say
>>>> that looks like a lock-up scenario. It looks like the system is
>>>> busy printing critical information to the console (which it is).
>>>
>>> What if we have N tasks/CPUs calling printk() simultaneously?
>> 
>> Then they take turns printing their messages to the console, spinning
>> until they get their turn. This still is not and does not look like a
>> lock-up. But I think you already know this, so I don't understand the
>> reasoning behind asking the question. Maybe you could clarify what
>> you are getting at.
>
> Sorry John, the reasoning is that I'm trying to understand
> why this does not look like soft or hard lock-up or RCU stall
> scenario.

The reason is that you are seeing data being printed on the console. The
watchdogs (soft, hard, rcu, nmi) are all touched with each emergency
message.

> The CPU which spins on prb_lock() can have preemption disabled and,
> additionally, can have local IRQs disabled, or be under RCU read
> side lock. If consoles are busy, then there are CPUs which printk()
> data and keep prb_lock contended; prb_lock() does not seem to be
> fair. What am I missing?

You are correct. Making prb_lock fair might be something we want to look
into. Perhaps also based on the loglevel of what needs to be
printed. (For example, KERN_ALERT always wins over KERN_CRIT.)

> You probably talk about the case when all
> printing CPUs are in preemptible contexts (assumingly this is what
> is happening in dm-integrity case) so they can spin on prb_lock(),
> that's OK. The case I'm talking about is - what if we have the same
> situation, but then one of the CPUs printk()-s from !preemptible.
> Does this make sense?

Yes, you are referring to a worst case. We could have local_irqs
disabled on every CPU while every CPU is hit with an NMI and all those
NMIs want to dump a load of messages. The rest of the system will be
frozen until those NMI printers can finish. But that is still not a
lock-up. At some point those printers should finish and eventually the
system should be able to resume.

John Ogness

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/07/19 11:37), John Ogness wrote:
> > Sorry John, the reasoning is that I'm trying to understand
> > why this does not look like soft or hard lock-up or RCU stall
> > scenario.
> 
> The reason is that you are seeing data being printed on the console. The
> watchdogs (soft, hard, rcu, nmi) are all touched with each emergency
> message.

Correct. Please see below.

> > The CPU which spins on prb_lock() can have preemption disabled and,
> > additionally, can have local IRQs disabled, or be under RCU read
> > side lock. If consoles are busy, then there are CPUs which printk()
> > data and keep prb_lock contended; prb_lock() does not seem to be
> > fair. What am I missing?
> 
> You are correct. Making prb_lock fair might be something we want to look
> into. Perhaps also based on the loglevel of what needs to be
> printed. (For example, KERN_ALERT always wins over KERN_CRIT.)

Good.

I'm not insisting, but I have a feeling that touching watchdogs after
call_console_drivers() might be too late, sometimes. When we spin in
prb_lock() we wait for all CPUs which are before/ahead of us to
finish their call_console_drivers(), one by one. So if CPUZ is very
unlucky and is in atomic context, then prb_lock() for that CPUZ can
last for  N * call_console_drivers().  And depending on N (which also
includes unfairness) and call_console_drivers() timings NMI watchdog
may pay CPUZ a visit before it gets its chance to touch watchdogs.

*May be* sometimes we might want to touch watchdogs in prb_lock().

So, given the design of new printk(), I can't help thinking about the
fact that current
	"the winner takes it all"
may become
	"the winner waits for all".

Mikulas mentioned that he observes "** X messages dropped" warnings.
And this suggests that, _most likely_, we had significantly more that
2 CPUs calling printk() concurrently.

- A single source - single CPU calling printk() - would not lose messages,
  because it would print its own message before it printk() another one (we
  still could have another CPU rescheduling under console_sem, but I don't
  think this is the case).

- Two CPUs would also probably not lose messages, Steven's console_owner
  would throttle them down.

So I think what we have was a spike of WARN/ERR printk-s comming from
N CPUs concurrently.

And this brings us to another pessimistic scenario: a very unlucky
CPUZ has to spin in prb_lock() waiting for other CPUs to print out
the very same 2 million chars. Which in terms of printk() latency
looks to me just like current printk.

John, sorry to ask this, does new printk() design always provide
latency guarantees good enough for PREEMPT_RT?

I'm surely missing something. Where am I wrong?

	-ss

Re: Serial console is causing system lock-up

[Mikulas Patocka]

On Thu, 7 Mar 2019, Sergey Senozhatsky wrote:

> On (03/07/19 11:37), John Ogness wrote:
> > > Sorry John, the reasoning is that I'm trying to understand
> > > why this does not look like soft or hard lock-up or RCU stall
> > > scenario.
> > 
> > The reason is that you are seeing data being printed on the console. The
> > watchdogs (soft, hard, rcu, nmi) are all touched with each emergency
> > message.
> 
> Correct. Please see below.
> 
> > > The CPU which spins on prb_lock() can have preemption disabled and,
> > > additionally, can have local IRQs disabled, or be under RCU read
> > > side lock. If consoles are busy, then there are CPUs which printk()
> > > data and keep prb_lock contended; prb_lock() does not seem to be
> > > fair. What am I missing?
> > 
> > You are correct. Making prb_lock fair might be something we want to look
> > into. Perhaps also based on the loglevel of what needs to be
> > printed. (For example, KERN_ALERT always wins over KERN_CRIT.)
> 
> Good.
> 
> I'm not insisting, but I have a feeling that touching watchdogs after
> call_console_drivers() might be too late, sometimes. When we spin in

There are still NMI stacktraces - see here 
http://people.redhat.com/~mpatocka/testcases/console-lockup/

> prb_lock() we wait for all CPUs which are before/ahead of us to
> finish their call_console_drivers(), one by one. So if CPUZ is very
> unlucky and is in atomic context, then prb_lock() for that CPUZ can
> last for  N * call_console_drivers().  And depending on N (which also
> includes unfairness) and call_console_drivers() timings NMI watchdog
> may pay CPUZ a visit before it gets its chance to touch watchdogs.
> 
> *May be* sometimes we might want to touch watchdogs in prb_lock().
> 
> So, given the design of new printk(), I can't help thinking about the
> fact that current
> 	"the winner takes it all"
> may become
> 	"the winner waits for all".
> 
> Mikulas mentioned that he observes "** X messages dropped" warnings.
> And this suggests that, _most likely_, we had significantly more that
> 2 CPUs calling printk() concurrently.

When I observe these messages (usually with small log buffer size), it 
doesn't lockup.

The lockups happen because the messages are stuffed into a 2MiB buffer and 
then printed over 115200 baud serial line.

You can see this: 
http://people.redhat.com/~mpatocka/testcases/console-lockup/5.0-total-lockup.txt

Here it attempted to write 1355277 bytes over the slow serial line - it 
takes a few minutes.

> - A single source - single CPU calling printk() - would not lose messages,
>   because it would print its own message before it printk() another one (we
>   still could have another CPU rescheduling under console_sem, but I don't
>   think this is the case).
> 
> - Two CPUs would also probably not lose messages, Steven's console_owner
>   would throttle them down.
> 
> So I think what we have was a spike of WARN/ERR printk-s comming from
> N CPUs concurrently.

Losing messages is in my opinion reasonable (if they are produced faster 
than they could be printed). Another possibility is to always write the 
message synchronously and exit printk only after it is written.

> And this brings us to another pessimistic scenario: a very unlucky
> CPUZ has to spin in prb_lock() waiting for other CPUs to print out
> the very same 2 million chars. Which in terms of printk() latency
> looks to me just like current printk.
> 
> John, sorry to ask this, does new printk() design always provide
> latency guarantees good enough for PREEMPT_RT?
> 
> I'm surely missing something. Where am I wrong?
> 
> 	-ss

Mikulas

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-07, Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:
>>> The CPU which spins on prb_lock() can have preemption disabled and,
>>> additionally, can have local IRQs disabled, or be under RCU read
>>> side lock. If consoles are busy, then there are CPUs which printk()
>>> data and keep prb_lock contended; prb_lock() does not seem to be
>>> fair. What am I missing?
>> 
>> You are correct. Making prb_lock fair might be something we want to
>> look into. Perhaps also based on the loglevel of what needs to be
>> printed. (For example, KERN_ALERT always wins over KERN_CRIT.)
>
> Good.
>
> I'm not insisting, but I have a feeling that touching watchdogs after
> call_console_drivers() might be too late, sometimes. When we spin in
> prb_lock() we wait for all CPUs which are before/ahead of us to
> finish their call_console_drivers(), one by one. So if CPUZ is very
> unlucky and is in atomic context, then prb_lock() for that CPUZ can
> last for  N * call_console_drivers().  And depending on N (which also
> includes unfairness) and call_console_drivers() timings NMI watchdog
> may pay CPUZ a visit before it gets its chance to touch watchdogs.
>
> *May be* sometimes we might want to touch watchdogs in prb_lock().

This is an excellent point. The handling of the watchdogs needs to be
more carefully considered/placed.

> So, given the design of new printk(), I can't help thinking about the
> fact that current
> 	"the winner takes it all"
> may become
> 	"the winner waits for all".

I am open to looking at implementing a fair prb_cpulock(). I think
without it, your observation for these "multi-CPU emergency message
flood" cases is correct.

> [...]
>
> And this brings us to another pessimistic scenario: a very unlucky
> CPUZ has to spin in prb_lock() waiting for other CPUs to print out
> the very same 2 million chars. Which in terms of printk() latency
> looks to me just like current printk.

If the prb_cpulock() is fair, they are both taking turns printing. The
prb_cpulock() is taken for _each_ printk() call and not (like in the
current printk) for the complete unprinted contents of the ringbuffer.

> John, sorry to ask this, does new printk() design always provide
> latency guarantees good enough for PREEMPT_RT?

Yes, because it is assumed that emergency messages will never occur for
a correctly running system. We've run tests where we pr_info() from all
contexts and the console_loglevel is set such that KERN_INFO is printed
to the console. The storage of the messages into the printk ringbuffer
do not cause any unacceptable latencies. And printing those messages to
the consoles via the fully preemptible printk-kthread also causes no
unacceptable latencies.

Obviously as soon as any emergency message appears, an _unacceptable_
latency occurs. But that is considered OK because the system is no
longer running correctly and it is worth the price to pay to get those
messages with such high reliability.

In a previous response[0] to Petr, I talk about defining _all_ console
printing as emergency and requiring userspace to handle informational
messages. With that definition, one could argue that the atomic consoles
are enough and we could avoid the printk-kthread(s) altogether. I am not
absolutely against this idea. But there (most likely) will be consoles
that cannot support atomic. And how should they be handled? We could
keep the current (quite complex) implementation in place just for
them. But I really wonder if all that is necessary just for those (few?)
consoles. printk-kthreads seem to me to be the ideal solution
(particularly when dealing with PREEMPT_RT, where nearly everything
important becomes a kthread). My RFC series implements a very simple
(naive) approach to kthread printing. I believe there is a lot[1][2] we
can do to make the printk-kthread printing more reliable.

John Ogness

[0] https://lkml.kernel.org/r/87k1hbbq2m.fsf@linutronix.de
[1] https://lkml.kernel.org/r/87o96p9gtx.fsf@linutronix.de
[2] https://lkml.kernel.org/r/87lg1rggcz.fsf@linutronix.de

Re: Serial console is causing system lock-up

[Petr Mladek]

On Thu 2019-03-07 15:21:50, John Ogness wrote:
> On 2019-03-07, Sergey Senozhatsky <sergey.senozhatsky@gmail.com> wrote:
> >>> The CPU which spins on prb_lock() can have preemption disabled and,
> >>> additionally, can have local IRQs disabled, or be under RCU read
> >>> side lock. If consoles are busy, then there are CPUs which printk()
> >>> data and keep prb_lock contended; prb_lock() does not seem to be
> >>> fair. What am I missing?
> >> 
> >> You are correct. Making prb_lock fair might be something we want to
> >> look into. Perhaps also based on the loglevel of what needs to be
> >> printed. (For example, KERN_ALERT always wins over KERN_CRIT.)
> >
> > Good.
> >
> > I'm not insisting, but I have a feeling that touching watchdogs after
> > call_console_drivers() might be too late, sometimes. When we spin in
> > prb_lock() we wait for all CPUs which are before/ahead of us to
> > finish their call_console_drivers(), one by one. So if CPUZ is very
> > unlucky and is in atomic context, then prb_lock() for that CPUZ can
> > last for  N * call_console_drivers().  And depending on N (which also
> > includes unfairness) and call_console_drivers() timings NMI watchdog
> > may pay CPUZ a visit before it gets its chance to touch watchdogs.
> >
> > *May be* sometimes we might want to touch watchdogs in prb_lock().
> 
> This is an excellent point. The handling of the watchdogs needs to be
> more carefully considered/placed.
> 
> > So, given the design of new printk(), I can't help thinking about the
> > fact that current
> > 	"the winner takes it all"
> > may become
> > 	"the winner waits for all".
>
> I am open to looking at implementing a fair prb_cpulock(). I think
> without it, your observation for these "multi-CPU emergency message
> flood" cases is correct.

This should be rather discussed in the thread about the new printk
implementation.

Anyway, the first version should be acceptable even with the unfair
lock. Please, do not spend time on this now.

There is a bigger problem with the lock. It is not NMI safe as I wrote
in
https://lkml.kernel.org/r/20190227135504.gqtcsdwpy4rd7xvs@pathway.suse.cz
Therefore I am not sure if we could use it at all.


> In a previous response[0] to Petr, I talk about defining _all_ console
> printing as emergency and requiring userspace to handle informational
> messages. With that definition, one could argue that the atomic consoles
> are enough and we could avoid the printk-kthread(s) altogether. I am not
> absolutely against this idea. But there (most likely) will be consoles
> that cannot support atomic. And how should they be handled? We could
> keep the current (quite complex) implementation in place just for
> them. But I really wonder if all that is necessary just for those (few?)
> consoles.

We must keep it as a fallback as long as the "few" group is important
enough for users.


> printk-kthreads seem to me to be the ideal solution
> (particularly when dealing with PREEMPT_RT, where nearly everything
> important becomes a kthread).

This can be solved by a configuration setting. Real-time kernels
might do the offloading more aggressively.

Best Regards,
Petr

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/07/19 15:21), John Ogness wrote:
> > John, sorry to ask this, does new printk() design always provide
> > latency guarantees good enough for PREEMPT_RT?
> 
> Yes, because it is assumed that emergency messages will never occur for
> a correctly running system.
>
[..]
> Obviously as soon as any emergency message appears, an _unacceptable_
> latency occurs. But that is considered OK because the system is no
> longer running correctly and it is worth the price to pay to get those
> messages with such high reliability.

OK, so what *I'm learning* from this bug report:

10) WARN/ERR messages do not necessarily tell us that the stability of the
    system was jeopardized. The system can "run correctly" and be
    "perfectly healthy".

20) We can have N CPUs reporting issues simultaneously. Even in production.
    Such patterns exist in the kernel.

30) The "reporting part" - printk()->call_console_drivers() - can be the
    slowest one.

  In this particular case, given that Mikulas saw dropped messages,
  checksum calculation was significantly faster than call_console_drivers().
  Now, suppose we have new printk, and suppose we have CPUs A B C D, each of
  them reports a checksum error:

  A prb_lock owner    B prb_lock    C prb_lock    D prb_lock

  A calls call_console_drivers, unlocks prb_lock
  B grabs prb_lock
  B calls call_console_drivers
  A calculates new checksum mismatch
  A calls printk and spins on prb_lock, behind D

  So now we have:

  B prb_lock owner    C prb_lock    D prb_lock    A prb_lock

  And so on

  B C D A  ->  C D A B  ->  D A B C  ->  A B C D  ->  ...

  After M rounds of error reporting (M > N), each CPU, had have to busy
  wait M times (N - 1). Sounds quadratic.

40) goto 10

So I have some doubts regarding some of assumptions behind new printk
design. And the problem is not in prb_lock() unfairness. Current printk
design does look to me SMP-friendly; yes, it has unbound printing loop;
that can be addressed. But it doesn't turn SMP system into UP.

	-ss

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-12, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
>>> John, sorry to ask this, does new printk() design always provide
>>> latency guarantees good enough for PREEMPT_RT?
>> 
>> Yes, because it is assumed that emergency messages will never occur
>> for a correctly running system.
>>
> [..]
>> Obviously as soon as any emergency message appears, an _unacceptable_
>> latency occurs. But that is considered OK because the system is no
>> longer running correctly and it is worth the price to pay to get
>> those messages with such high reliability.
>
> OK, so what *I'm learning* from this bug report:
>
> 10) WARN/ERR messages do not necessarily tell us that the stability of
>     the system was jeopardized. The system can "run correctly" and be
>     "perfectly healthy".

If the messages from this report are not critical, they should not be
classified as emergency messages. It is a bug if they are.

> 20) We can have N CPUs reporting issues simultaneously. Even in
>     production.  Such patterns exist in the kernel.

Sure. But it is important to distinguish if these messages are critical
or just informational.

> 30) The "reporting part" - printk()->call_console_drivers() - can be
>     the slowest one.
>
>   In this particular case, given that Mikulas saw dropped messages,
>   checksum calculation was significantly faster than
>   call_console_drivers(). Now, suppose we have new printk, and
>   suppose we have CPUs A B C D, each of them reports a checksum error:
>
>   A prb_lock owner    B prb_lock    C prb_lock    D prb_lock
>
>   A calls call_console_drivers, unlocks prb_lock
>   B grabs prb_lock
>   B calls call_console_drivers
>   A calculates new checksum mismatch
>   A calls printk and spins on prb_lock, behind D
>
>   So now we have:
>
>   B prb_lock owner    C prb_lock    D prb_lock    A prb_lock
>
>   And so on
>
>   B C D A  ->  C D A B  ->  D A B C  ->  A B C D  ->  ...
>
>   After M rounds of error reporting (M > N), each CPU, had have to busy
>   wait M times (N - 1). Sounds quadratic.

If these are critical messages, then we are _not allowed to drop any_!
For critical messages printk must be synchronous. Thus for critical
messages the situation you illustrated is appropriate.

> 40) goto 10
>
> So I have some doubts regarding some of assumptions behind new printk
> design. And the problem is not in prb_lock() unfairness. Current
> printk design does look to me SMP-friendly; yes, it has unbound
> printing loop; that can be addressed.

Let us not forget, it deadlocked the machine. That's the reason this
thread exists.

> But it doesn't turn SMP system into UP.

In this example it turned it into a brick.

The problems I see are:

1. The current loglevels used in the kernel are not sufficient to
   distinguish between emergency and informational messages. Addressing
   this issue may require things like using a new printk flag and
   manually marking the printks that we(?) decide are critical. I was
   hoping we could use existing loglevels, but this appears to be such a
   mess that it is probably not practically/politically fixable
   [0]. Maybe it could be a combination of flag and loglevel, where
   certain messages have been flagged by the kernel developers as
   emergency (for example BUG output) and the user still has the
   flexibility of setting a loglevel. I need more input here.

2. You seem unwilling to acknowledge the difference between emergency
   and informational messages. A message is either critical or it is
   not. If it is, it should be handled as such, regardless of
   interference, regardless if it means turning an SMP machine into a UP
   machine. If it is not critical, it should be sent along a
   non-interfering path so the the system is _not_ affected.

The current printk implementation is handling all console printing as
best effort. Trying hard enough to dramatically affect the system, but
not trying hard enough to guarantee success.

John Ogness

[0] https://lkml.kernel.org/r/f60d844d-9d3b-3154-4eec-982432c8e502@redhat.com

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/12/19 09:17), John Ogness wrote:
> >   wait M times (N - 1). Sounds quadratic.
> 
> If these are critical messages, then we are _not allowed to drop any_!
> For critical messages printk must be synchronous. Thus for critical
> messages the situation you illustrated is appropriate.
> 
> > 40) goto 10
> >
> > So I have some doubts regarding some of assumptions behind new printk
> > design. And the problem is not in prb_lock() unfairness. Current
> > printk design does look to me SMP-friendly; yes, it has unbound
> > printing loop; that can be addressed.
> 
> Let us not forget, it deadlocked the machine. That's the reason this
> thread exists.

It didn't deadlock the machine. It was a typical soft lockup. Printing
CPU loop-ed in console_unlock() with preemption disabled; soft lockup
hrtimer was running on that CPU, but due to disabled preemption around
console_unlock() soft lockup's per-CPU kthread could not get scheduled
and could not update per-CPU touch_ts. Soft lockup hrtimer detected it:

[ 5128.552442] watchdog: BUG: soft lockup - CPU#9 stuck for 23s! [kworker/9:53:4131]

Along with that RCU was not able to get scheduled. Which was detected
by RCU stall detector:

[ 4891.199009] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
[ 4891.221308] device-mapper: integrity: Checksum failed at sector 0x118d4f
[ 4891.251366] rcu:     9-....: (1923 ticks this GP) idle=7fa/1/0x4000000000000002 softirq=2190/2190 fqs=15013
[ 4891.251367] rcu:     (detected by 16, t=60054 jiffies, g=24641, q=351)
[ 4891.311941] Sending NMI from CPU 16 to CPUs 9:

[..]
> 2. You seem unwilling to acknowledge the difference between emergency
>    and informational messages. A message is either critical or it is
>    not. If it is, it should be handled as such, regardless of
>    interference, regardless if it means turning an SMP machine into a UP
>    machine. If it is not critical, it should be sent along a
>    non-interfering path so the the system is _not_ affected.

OK.
Let's move on then.

	-ss

Re: Serial console is causing system lock-up

[Mikulas Patocka]

On Tue, 12 Mar 2019, John Ogness wrote:

> > But it doesn't turn SMP system into UP.
> 
> In this example it turned it into a brick.
> 
> The problems I see are:
> 
> 1. The current loglevels used in the kernel are not sufficient to
>    distinguish between emergency and informational messages. Addressing
>    this issue may require things like using a new printk flag and
>    manually marking the printks that we(?) decide are critical. I was

It depends on what the user considers important. The kernel doesn't know 
what's critical and can't know it.

For example, if the user plugs an USB stick and the USB stick reports an 
I/O error, it is not critical condition.

If the user runs the whole system from the USB stick and the USB stick 
reports an I/O error, it is critical condition.

The filesystems and the block device drivers can't know if the data stored 
on them are important.

Mikulas

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-12, Mikulas Patocka <mpatocka@redhat.com> wrote:
>>> But it doesn't turn SMP system into UP.
>> 
>> In this example it turned it into a brick.
>> 
>> The problems I see are:
>> 
>> 1. The current loglevels used in the kernel are not sufficient to
>>    distinguish between emergency and informational messages. Addressing
>>    this issue may require things like using a new printk flag and
>>    manually marking the printks that we(?) decide are critical. I was
>
> It depends on what the user considers important. The kernel doesn't
> know what's critical and can't know it.
>
> For example, if the user plugs an USB stick and the USB stick reports
> an I/O error, it is not critical condition.
>
> If the user runs the whole system from the USB stick and the USB stick
> reports an I/O error, it is critical condition.

I would argue that it is _not_ a critical condition. I/O errors are
something that happen. This is normal operation.

_My_ definition of critical is when something with the _kernel itself_
has gone wrong. If the kernel is in error paths that should never happen
(for example, when a WARN_ON is hit) or if a BUG/panic is hit. This is
critical information.

> The filesystems and the block device drivers can't know if the data
> stored on them are important.

Perhaps it would be nice if an administrator could additionally "mark"
what _they_ consider critical, i.e. they are aware of and accept the
consequences of a synchronous printk for certain messages. When I look
at things like dynamic_printk and ftrace, I see mechanisms that provide
excellent runtime tuning without much complexity.

We could extend dynamic_printk to include all printk messages and also
support the emergency classification. We could have something like
ftrace-events, where certain _events_ (i.e a group of printk messages)
could be classified as an emergency (for example, a WARN_ON event, a
watchdog event, a general stacktrace event, etc.).

These are just ideas that I'm bouncing around my brain. But as you said,
only the administrator can know what is important. So perhaps we need to
provide the administrator an interface to specify that.

John Ogness

Re: Serial console is causing system lock-up

[Petr Mladek]

On Tue 2019-03-12 14:19:56, John Ogness wrote:
> On 2019-03-12, Mikulas Patocka <mpatocka@redhat.com> wrote:
> >>> But it doesn't turn SMP system into UP.
> >> 
> >> In this example it turned it into a brick.
> >> 
> >> The problems I see are:
> >> 
> >> 1. The current loglevels used in the kernel are not sufficient to
> >>    distinguish between emergency and informational messages. Addressing
> >>    this issue may require things like using a new printk flag and
> >>    manually marking the printks that we(?) decide are critical. I was
> 
> Perhaps it would be nice if an administrator could additionally "mark"
> what _they_ consider critical, i.e. they are aware of and accept the
> consequences of a synchronous printk for certain messages. When I look
> at things like dynamic_printk and ftrace, I see mechanisms that provide
> excellent runtime tuning without much complexity.
> 
> We could extend dynamic_printk to include all printk messages and also
> support the emergency classification. We could have something like
> ftrace-events, where certain _events_ (i.e a group of printk messages)
> could be classified as an emergency (for example, a WARN_ON event, a
> watchdog event, a general stacktrace event, etc.).
> 
> These are just ideas that I'm bouncing around my brain. But as you said,
> only the administrator can know what is important. So perhaps we need to
> provide the administrator an interface to specify that.

Interesting idea. But I am very sceptical about it. I can't imagine
that anyone would like to configure 100k messages or so.

It is even worse than kernel configuration. And the trend is
to avoid config options where possible. It is because it is
almost impossible to understand all existing options and
make qualified decisions. And it is hard to expect that
users would be able to make a better decision than a developer
who implemented the code behind the option.

Our discussion is a nice example. Even we have troubles to
understand all consequences of different approaches. Even
if we reach a conclusion and document it. Then nobody
would want to read several pages long tutorial how to
configure printk ;-)

Best Regards,
Petr

Re: Serial console is causing system lock-up

[Petr Mladek]

On Tue 2019-03-12 09:17:49, John Ogness wrote:
> On 2019-03-12, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> The problems I see are:
> 
> 1. The current loglevels used in the kernel are not sufficient to
>    distinguish between emergency and informational messages. Addressing
>    this issue may require things like using a new printk flag and
>    manually marking the printks that we(?) decide are critical. I was
>    hoping we could use existing loglevels, but this appears to be such a
>    mess that it is probably not practically/politically fixable
>    [0]. Maybe it could be a combination of flag and loglevel, where
>    certain messages have been flagged by the kernel developers as
>    emergency (for example BUG output) and the user still has the
>    flexibility of setting a loglevel. I need more input here.

No, please! No extra flag could safe us if people are not able
to set loglevel correctly. Also the importance depends on the
situation. Any message is as important as it helps to resolve
the problem.


> 2. You seem unwilling to acknowledge the difference between emergency
>    and informational messages. A message is either critical or it is
>    not. If it is, it should be handled as such, regardless of
>    interference, regardless if it means turning an SMP machine into a UP
>    machine. If it is not critical, it should be sent along a
>    non-interfering path so the the system is _not_ affected.

This means that any critical message is always more important than any
workload. It opens doors for iteresting DOS attacks.


> The current printk implementation is handling all console printing as
> best effort. Trying hard enough to dramatically affect the system, but
> not trying hard enough to guarantee success.

I agree that direct output is more reliable. It might be very useful
for debugging some types of problems. The question is
if it is worth the cost (code complexity, serializing CPUs
== slowing down the entire system).

But it is is possible that a reasonable offloading (in the direction
of last Sergey's approach) might be a better deal.


I suggest the following way forward (separate patchsets):

    1. Replace log buffer (least controversial thing)
    2. Reliable offload to kthread (would be useful anyway)
    3. Atomic consoles (a lot of tricky code, might not be
		worth the effort)

Could we agree on this?

Best Regards,
Petr

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-12, Petr Mladek <pmladek@suse.com> wrote:
> On Tue 2019-03-12 09:17:49, John Ogness wrote:
>> The current printk implementation is handling all console printing as
>> best effort. Trying hard enough to dramatically affect the system,
>> but not trying hard enough to guarantee success.
>
> I agree that direct output is more reliable. It might be very useful
> for debugging some types of problems. The question is if it is worth
> the cost (code complexity, serializing CPUs == slowing down the
> entire system).
>
> But it is is possible that a reasonable offloading (in the direction
> of last Sergey's approach) might be a better deal.
>
>
> I suggest the following way forward (separate patchsets):
>
>     1. Replace log buffer (least controversial thing)
>     2. Reliable offload to kthread (would be useful anyway)
>     3. Atomic consoles (a lot of tricky code, might not be
> 		worth the effort)
>
> Could we agree on this?

Since this is about the new RFC printk design, I've responded in that
thread [0].

John Ogness

[0] https://lkml.kernel.org/r/874l8815uc.fsf@linutronix.de

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/12/19 13:08), Petr Mladek wrote:
> > 2. You seem unwilling to acknowledge the difference between emergency
> >    and informational messages. A message is either critical or it is
> >    not. If it is, it should be handled as such, regardless of
> >    interference, regardless if it means turning an SMP machine into a UP
> >    machine. If it is not critical, it should be sent along a
> >    non-interfering path so the the system is _not_ affected.
> 
> This means that any critical message is always more important than any
> workload. It opens doors for iteresting DOS attacks.

Agreed.

So what I thought about "mutual exclusive error reporting with
quadratic latencies" was that if any workload involves error
reporting then it might be a good idea to _not_ parallelize such
workload anymore.

> > The current printk implementation is handling all console printing as
> > best effort. Trying hard enough to dramatically affect the system, but
> > not trying hard enough to guarantee success.
>
> I agree that direct output is more reliable. It might be very useful
> for debugging some types of problems. The question is
> if it is worth the cost (code complexity, serializing CPUs
> == slowing down the entire system).

Agreed.

I'm very skeptical about "serializing CPUs" part. It looks like one
"print or die trying" is replaced with another "print or die trying".
What happened to  log_store() + flush_on_panic()?

	-ss

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-13, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
>>> The current printk implementation is handling all console printing
>>> as best effort. Trying hard enough to dramatically affect the
>>> system, but not trying hard enough to guarantee success.
>>
>> I agree that direct output is more reliable. It might be very useful
>> for debugging some types of problems. The question is
>> if it is worth the cost (code complexity, serializing CPUs
>> == slowing down the entire system).
>
> Agreed.
>
> I'm very skeptical about "serializing CPUs" part. It looks like one
> "print or die trying" is replaced with another "print or die trying".
> What happened to log_store() + flush_on_panic()?

We are literally discussing in a thread where the current printk
implementation failed to get messages out (lots of dropped messages)
_and_ printk console printing was responsible for _killing_ the machine.

What would my proposal do in _this_ situation:

1. If no emergency console was available or the messages were not
classified as emergency, messages would have been dropped during console
printing and the system would have run unaffected. The number of dropped
messages might not even be more if the scheduler could run the printk
kthread effectively.

OR

2. If an emergency console was available and the messages were
classified as emergency, _no_ messages would have dropped, the system
would have become very slow on the CPUs generating the messages, and
then eventually it would have recovered.


I don't understand how you can think "print or die trying" is replaced
with another "print or die trying". But it is probably not constructive
to debate this right now. Petr has laid out a good course that will
allow us to advance in smaller, more conservative, steps.

By the way, Sergey, I appreciate your skepticism.

John Ogness

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/13/19 09:43), John Ogness wrote:
> I don't understand how you can think "print or die trying" is replaced
> with another "print or die trying".

Sorry, let me explain. In some contexts CPUs which are spinning on
prb_lock don't do anything else. A careful placement of

        touch_softlockup_watchdog_sync();
        clocksource_touch_watchdog();
        rcu_cpu_stall_reset();
        touch_nmi_watchdog();

keeps the watchdogs away, yes, but that doesn't mean that we are not
sitting on a time bomb. Think of RCU, for instance. We keep rcu_cpu_stall
silent and things can look OK, but that doesn't mean that RCU is OK in
reality; spinning CPUs may hold off grace periods. So now a relatively
simple issue - raid checksum mismatch in this particular case - has
potential to become OOM. Quadratic CPU serialisation doesn't scale.
Throw enough reporting CPUs on it and we may get very close to some
big problems. Does this make sense?

This bug report demonstrates that we can have N CPUs reporting warns
simultaneously. And I think that people would want to have pr_warns
and WARN_ONs to be printed as emergency level messages (it sort of
sounds reasonable. I understand that you have different opinion on this).

And what I'm thinking is that *probably* we can have a bit less radical
approach - the system is not always doomed when it WARNs us - and a bit
more "best effort" one. *May be* we don't need to apply full serialisation
all the time. *May be* full serialisation can be applied only when we see
that we are about to run out of free space in logbuf. Or may be can
start dynamically resize the logbuf. And so on.

> By the way, Sergey, I appreciate your skepticism.

Sorry, John. I know I'm a PITA.

	-ss

Re: Serial console is causing system lock-up

[John Stoffel]

>>>>> "John" == John Ogness <john.ogness@linutronix.de> writes:

John> On 2019-03-06, Steven Rostedt <rostedt@goodmis.org> wrote:
>>> This bug only happens if we select large logbuffer (millions of
>>> characters). With smaller log buffer, there are messages "** X printk
>>> messages dropped", but there's no lockup.
>>> 
>>> The kernel apparently puts 2 million characters into a console log
>>> buffer, then takes some lock and than tries to write all of them to a
>>> slow serial line.
>>> 
>>> [...]
>>> 
>>> The MD-RAID is supposed to recalculate data for the corrupted device
>>> and bring it back to life. However, scrubbing the MD-RAID device
>>> resulted in a lot of reads from the device with bad checksums, these
>>> were reported to the log and killed the machine.
>>> 
>>> I made a patch to dm-integrity to rate-limit the error messages. But
>>> anyway - killing the machine in case of too many log messages seems
>>> bad.  If the log messages are produced faster than the kernel can
>>> write them, the kernel should discard some of them, not kill itself.
>> 
>> Sounds like another aurgment for the new printk design.

John> Assuming the bad checksum messages are considered an emergency
John> (for example, at least loglevel KERN_WARN), then the new printk
John> design would print those messages synchronously to the slow
John> serial line in the context of the driver as the driver is
John> producing them.

John> There wouldn't be a lock-up, but it would definitely slow down
John> the driver. The situation of "messages being produced faster
John> than the kernel can write them" would never exist because the
John> printk() call will only return after the writing is completed. I
John> am curious if that would be acceptable here?

The real problem is the disconnect between serial console speed and
capacity in bits/sec and that of the regular console.  Serial, esp at
9600 baud is just a slow and limited resource which needs to be
handled differently than a graphical console.

I'm also big on ratelimiting messages, even critical warning
messages.  Too much redundant info doesn't help anyone.  And what a
subsystem thinks is critical, may not be critical to the system as a
whole.

In this case, if these checksum messages are telling us that there's
corruption, why isn't dm-integrity going readonly and making the block
device get the filesystem to also go readonly and to stop the damage
right away?

If it's just a warning for the niceness, then please rate limit them,
or summarize them in some more useful way.  Or even log them to
somewhere else than the console once the problem is noted.

John

Re: Serial console is causing system lock-up

[Mikulas Patocka]

On Thu, 7 Mar 2019, John Stoffel wrote:

> The real problem is the disconnect between serial console speed and
> capacity in bits/sec and that of the regular console.  Serial, esp at
> 9600 baud is just a slow and limited resource which needs to be
> handled differently than a graphical console.
>
> I'm also big on ratelimiting messages, even critical warning
> messages.  Too much redundant info doesn't help anyone.  And what a
> subsystem thinks is critical, may not be critical to the system as a
> whole.

Perhaps a proper solution would be to drop excessive messages to serial 
console unless Oops or BUG has happened?

> In this case, if these checksum messages are telling us that there's
> corruption, why isn't dm-integrity going readonly and making the block
> device get the filesystem to also go readonly and to stop the damage
> right away?

Because we don't want to kill the filesystem. dm-integrity detects an 
error and returns the error code to md-raid5. md-raid5 recalculates the 
correct data from the remaining disks. And then, md-raid5 submits the 
correct data to the filesystem and also writes the correct data to the 
device that had the error.

In a real-life scenario, there would be few errors. When we are testing 
it, we deliberately create a device with all errorneous sectors.

> If it's just a warning for the niceness, then please rate limit them,
> or summarize them in some more useful way.  Or even log them to
> somewhere else than the console once the problem is noted.
> 
> John

I made a patch that rate-limits the message. But still, killing the 
machine is wrong.

Mikulas

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/07/19 09:26), Mikulas Patocka wrote:
> On Thu, 7 Mar 2019, John Stoffel wrote:
> 
> > The real problem is the disconnect between serial console speed and
> > capacity in bits/sec and that of the regular console.  Serial, esp at
> > 9600 baud is just a slow and limited resource which needs to be
> > handled differently than a graphical console.
> >
> > I'm also big on ratelimiting messages, even critical warning
> > messages.  Too much redundant info doesn't help anyone.  And what a
> > subsystem thinks is critical, may not be critical to the system as a
> > whole.
> 
> Perhaps a proper solution would be to drop excessive messages to serial 
> console unless Oops or BUG has happened?

Technically, we can have a per-console loglevel configuration. We have
several use cases for this already. Slower consoles will filter out more
messages and print only ERR/CRIT/ALERT/EMERG.

dm-integrity uses WARN level, which is below ERR; so it seems that
per-console loglevel can do the trick.

	-ss

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/08/19 10:22), Sergey Senozhatsky wrote:
> > Perhaps a proper solution would be to drop excessive messages to serial 
> > console unless Oops or BUG has happened?
> 
> Technically, we can have a per-console loglevel configuration. We have
> several use cases for this already.

JFI,

lore.kernel.org/r/cover.1551486732.git.calvinowens@fb.com

	-ss

Re: Serial console is causing system lock-up

[John Ogness]

On 2019-03-08, Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
>>> Perhaps a proper solution would be to drop excessive messages to
>>> serial console unless Oops or BUG has happened?
>> 
>> Technically, we can have a per-console loglevel configuration. We
>> have several use cases for this already.
>
> JFI,
>
> lore.kernel.org/r/cover.1551486732.git.calvinowens@fb.com

FWIW, I support the patch. It makes consoles into actual objects rather
than just a collection of callbacks. I feel like Calvin is pushing in a
similar direction to what I would like to see: decoupling of console
drivers to allow for individual behavior and performance tuning. As we
move into the highly SMP systems of the future, I am convinced this is
inevitable.

John Ogness

Re: Serial console is causing system lock-up

[Petr Mladek]

On Wed 2019-03-06 12:11:10, Mikulas Patocka wrote:
> 
> 
> On Wed, 6 Mar 2019, Theodore Y. Ts'o wrote:
> 
> > On Wed, Mar 06, 2019 at 11:07:55AM -0500, Mikulas Patocka wrote:
> > > This bug only happens if we select large logbuffer (millions of 
> > > characters). With smaller log buffer, there are messages "** X printk 
> > > messages dropped", but there's no lockup.
> > > 
> > > The kernel apparently puts 2 million characters into a console log buffer, 
> > > then takes some lock and than tries to write all of them to a slow serial 
> > > line.
> > 
> > What are the messages; from what kernel subsystem?  Why are you seeing
> > so many log messages?
> > 
> > 					- Ted
> 
> The dm-integity subsystem (drivers/md/dm-integrity.c) can be attached to a 
> block device to provide checksum protection. It will return -EILSEQ and 
> print a message to a log for every corrupted block.
> 
> Nigel Croxon was testing MD-RAID recovery capabilities in such a way that 
> he activated RAID-5 array with one leg replaced by a dm-integrity block 
> device that had all checksums invalid.
> 
> The MD-RAID is supposed to recalculate data for the corrupted device and 
> bring it back to life. However, scrubbing the MD-RAID device resulted in a 
> lot of reads from the device with bad checksums, these were reported to 
> the log and killed the machine.
> 
> 
> I made a patch to dm-integrity to rate-limit the error messages. But 
> anyway - killing the machine in case of too many log messages seems
> bad. If the log messages are produced faster than the kernel can write them, 
> the kernel should discard some of them, not kill itself.

printk() could not easily detect where the messages come from and
if it is acceptable to drop them.

In general, an "unlimited" output of messages that are not much useful
looks like a bug on the caller side. Some rate-limiting in
dm-integrity code looks appropriate here.

Even better might be to stop printing the messages after X occurrences
until the check is completed. It might do something like:

int errors_count = 0;

while(find_error()) {
	errors_count++;
	if (errors_count <= 10)
		pr_err("...");
	else if (errors_count == 11)
		pr_error(¨Too many errors. Continuing check silently\n");
}

if (errors_count)
	pr_error("Check finished. %d errors detected\n", errors_count);


Note that rate-limit is a bit ugly. It does not have feedback from
printk/consoles how long it takes to get the messages out. It might
not be enough if the console is very slow and if there are other
printk() users at the same time.


That said. I agree that printk() should not kill the system. It should
survive these "mistakes". On the other hand, printk() users must
cooperate. The log buffer and console bandwith is a limited resource.


Best Regards,
Petr

Re: Serial console is causing system lock-up

[Sergey Senozhatsky]

On (03/06/19 11:07), Mikulas Patocka wrote:
> This bug only happens if we select large logbuffer (millions of 
> characters). With smaller log buffer, there are messages "** X printk 
> messages dropped", but there's no lockup.
> 
> The kernel apparently puts 2 million characters into a console log buffer, 
> then takes some lock and than tries to write all of them to a slow serial 
> line.

Do you run a preemtible kernel?

	-ss

Re: Serial console is causing system lock-up

[Mikulas Patocka]

On Thu, 7 Mar 2019, Sergey Senozhatsky wrote:

> On (03/06/19 11:07), Mikulas Patocka wrote:
> > This bug only happens if we select large logbuffer (millions of 
> > characters). With smaller log buffer, there are messages "** X printk 
> > messages dropped", but there's no lockup.
> > 
> > The kernel apparently puts 2 million characters into a console log buffer, 
> > then takes some lock and than tries to write all of them to a slow serial 
> > line.
> 
> Do you run a preemtible kernel?
> 
> 	-ss

The kernel has voluntary preemption.

Mikulas