Re: [PATCH] printk: Ratelimit messages printed by console drivers

[Petr Mladek]

On Mon 2018-04-23 14:21:33, Sergey Senozhatsky wrote:
> On (04/20/18 11:12), Petr Mladek wrote:
> call_console_drivers() is super complex, unbelievable complex. In fact,
> it's so complex that we never know where we will end up, because it can
> pass the control to almost every core kernel mechanism or subsystem:

I fully agree. We will never be able to completely avoid messages
from these code paths and it would even be contra-productive. People
need to see the problems and be able to debug them. BTW: I wrote
this in the patch description.

> A very quick googling:

Nice collection. Just note that the useful (ratelimited) information
always fits into the first 100 lines in all these examples:

> 	https://bugzilla.altlinux.org/attachment.cgi?id=5811

The two WARNINGs starts repeating after 65 lines.

Note that the backtraces at the end of the log are from
NMI watchdog => not ratelimited by this patch (with the extra fix)


> 	https://access.redhat.com/solutions/702533

fits into 52 lines

> 	https://bugzilla.redhat.com/attachment.cgi?id=561164

both warnings fit into 54 lines

> 	https://lists.gt.net/linux/kernel/2341113

BUG report fits into 26 lines

> 	https://www.systutorials.com/linux-kernels/56987/ib-mlx4-reduce-sriov-multicast-cleanup-warning-message-to-debug-level-linux-4-10-17/

NMI bactrace => not affected by this patch (with the extra fix)

> 	https://github.com/raspberrypi/linux/issues/663

Bug report fits into 29 lines

> 	https://bugs.openvz.org/browse/VZWEB-36

Starts to repeat after 79 lines. I wonder if it ever ended without
killing the system.




> Throttling down that error mechanism to 100 lines
> per hour, or 1000 lines per hour is unlikely will be welcomed.

I wonder if you have bigger problems with the number of lines
or with the length of the period.

We simply _must_ limit the number of lines. Otherwise we would
never be able to break an _infinite_ loop.

But we could eventually replace the time period with a more
complex solution. For example, if we call console drivers
outside printk_safe context then the "recursive" messages
will be written to the mail log buffer directly. Then we could
reset the counter of the recursive messages when leaving
console_unlock() the regular way. I mean when all lines are
handled.


> Among all the patches and proposal that we saw so far, one stands out - it's
> the original Tejun's patch [offloading to work queue]. Because it has zero
> interference with the existing call_console_drivers()->printk()
> channels.

The only problem is that it does not solve the infinite loop. If
writing one line produces one or more new lines (warnings/errors)
than the only way out is to start dropping the recursive messages.
Offloading would just move the infinite loop to another process.

Note that the offload might help if there is a deadlock/livelock
between the original printk() caller and console drivers. Then moving
console_unlock() to another "safe" context helps to unblock the
situation. But the offload has its own problems and limiting
the number of recursive messages would solve this as well.


> What is so special about this case that we decided to screw up printk()
> instead?

There are many situations where printk() is limited. For example, we
are limited to 8kB in NMI or printk_safe() context. The printk_safe()
context is about printk debugging. Also messages from console drivers
are about printk debugging. There must be some limitations by
definition.


> I think that we need to apply the patch below.
> That call_console_drivers()->printk->IRQ_work->irq->flush appears to be
> pointless.

I agree that calling console drivers in printk_safe context is
pointless. Normal vprintk_emit() can be safely called because
logbuf_lock is not taken here. Also console_unlock() will
never by called recursively because it is guarded by console_sem.

> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@xxxxxxxxx>
> ---
>  kernel/printk/printk.c | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index 247808333ba4..484c456c095a 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -2385,9 +2385,11 @@ void console_unlock(void)
>  		 */
>  		console_lock_spinning_enable();
>  
> +		__printk_safe_exit();
>  		stop_critical_timings();	/* don't trace print latency */
>  		call_console_drivers(ext_text, ext_len, text, len);
>  		start_critical_timings();
> +		__printk_safe_enter();

Is this by intention? What is the reason to call
console_lock_spinning_disable_and_check() in printk_safe() context, please?

>  		if (console_lock_spinning_disable_and_check()) {
>  			printk_safe_exit_irqrestore(flags);

Best Regards,
Petr