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

[Sergey Senozhatsky]

On (04/20/18 11:12), Petr Mladek wrote:
[..]
> Will 1000 lines within 1 hour be enough for you, please?

I'm afraid it won't.

> I am lost. In the mail
[..]
> My understanding of the older mail is that you called
> console_drivers() in printk_safe() context only because it was
> easier to disable printk_safe context later together with
> enabling irqs.

Correct.

> My understanding of today's mail is that it is important
> to call console drivers in printk_safe() context.

No, I don't think that it is what I said.

> It is a contradiction. Could you please explain?

Let me try again.

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:
kobjects, spin locks, tty, sdp, uart, vt, fbdev, dri, kms, timers,
timekeeping, networking, mm, scheduler, you name it. Thousands and
thousands lines of code, which are not executed exclusively by the
console drivers. That core kernel code that we are dealing with has its
own fault/error reporting mechanisms, some of which comes in forms of
WARN_ON()-s or printk()-s, or dump_stack()-s, or BUG_ON()-s and so on.

Now, for many, many years printk()-s from console_unlock()->call_console_driver()
were absolutely legal and fine. And it was useful, and helpful mechanism,
and that's why people used it (and continue to do so). A very quick
googling:
	https://bugzilla.altlinux.org/attachment.cgi?id=5811
or
	https://access.redhat.com/solutions/702533
or
	https://bugzilla.redhat.com/attachment.cgi?id=561164
or
	https://lists.gt.net/linux/kernel/2341113
or
	https://www.systutorials.com/linux-kernels/56987/ib-mlx4-reduce-sriov-multicast-cleanup-warning-message-to-debug-level-linux-4-10-17/
or
	https://github.com/raspberrypi/linux/issues/663
or
	https://bugs.openvz.org/browse/VZWEB-36
or
  any other bug report which involves console_unlock()->call_console_drivers(),
there are *tons* of them. And the reason why those printk()-s were, and
they still are, legal was [and is] because those printk()-s were [and are]
harmless - they didn't [don't] deadlock the system. [not to mention VT, console
drivers, etc. debugging]. Throttling down that error mechanism to 100 lines
per hour, or 1000 lines per hour is unlikely will be welcomed.

When we introduced printk_safe() we had a completely different goal.
printk_safe() did not make call_console_drivers() any safer. Because
printk_safe() has *nothing* to do with console drivers or the underlying
code. The only thing that has changed on the console_drivers side with
the introduction of printk_safe() was that we enabled lockdep, and thus
RCU sanity checks, in printk() and console_drivers. So we just opened up
one more error reporting channel - a small, but very important, addition
to already existing numerous error reporting printk()-s, dump_stack()-s
which call_console_drivers()->foo() can trigger. And that additional
console_drivers error reporting channel works really well for us:
	http://lkml.kernel.org/r/20170928120405.18273-1-sergey.senozhatsky@xxxxxxxxx
or
	http://lkml.kernel.org/r/20170217015932.11898-1-sergey.senozhatsky@xxxxxxxxx
or
	lkml.kernel.org/r/alpine.LFD.2.20.1703201736070.1753@schleppi
or
	so on. We have a number of those "additional" reports.

When it comes to call_console_drivers() neither lockdep nor RCU need
printk_safe(). Because console_unlock()->call_console_drivers()->printk()
is totally normal, legal, fine, and has been around for years. We need
printk_safe() because of the way vprintk_emit() works - we protect logbuf
spin_lock and console_sem spin_lock with print_safe, -- not because of the
console_drivers [which don't deal with logbuf or console_sem to begin
with]. In other words, printk_safe() is *irrelevant* when it comes to
console drivers.

If we continue calling console_drivers under printk_safe(), and I don't
think that we should do so [I said it several times], then it is *absolutely*
important to keep it as permissive as possible [I also said it several times].
But let me be crystal clear - we better stop calling console_drivers under
printk_safe, it is pointless, useless and introduces unneeded IRQ->work->flush
dependency. It is also my believe that printk()-s from call_console_drivers()
must stay "un-throttled", exactly the way there were [and they are] for years.
Otherwise, we simply will "secretly" and "suprisingly" turn a HUGE number of
printk()-s, dump_stack(), WARN_ON()-s, etc. in sched, net, mm, tty, fbdev, vt,
you name it, into rate-limited printk() for no reason. We will shut up quite a
number of valid, useful and important error reporting channels. This does look
and smell like a massive, massive regression.

Basically, from the vt, tty, timekeeping, sched, net, mm, you name it,
prospective, what we do is:

---

 kernel/printk/printk.c | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 247808333ba4..8df861e6e0a3 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1828,6 +1828,7 @@ asmlinkage int vprintk_emit(int facility, int level,
 			    const char *dict, size_t dictlen,
 			    const char *fmt, va_list args)
 {
+	static DEFINE_RATELIMIT_STATE(ratelimit_console, 60 * 60 * HZ, 100);
 	static char textbuf[LOG_LINE_MAX];
 	char *text = textbuf;
 	size_t text_len;
@@ -1836,6 +1837,9 @@ asmlinkage int vprintk_emit(int facility, int level,
 	int printed_len;
 	bool in_sched = false;
 
+	if (!__ratelimit(&ratelimit_console))
+		return 0;
+
 	if (level == LOGLEVEL_SCHED) {
 		level = LOGLEVEL_DEFAULT;
 		in_sched = true;

---

It is really so.

What part of this plan works for us?

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.
Whatever comes from any of the underlying subsystems [networking, vt, mm,
you name it] comes for a reason, we should not blindly and boldly discard
those messages. And I really love that part of Tejun's patch.

But let's think about it - we haven't even looked at the messages that are
supposedly killing Tejun's boxes. We can't be serious now. We don't even
know what we are dealing with, we don't even know what [and why] the kernel
was reporting to us. We should have looked at the logs in the first place,
and probably consider some rate-limiting in the misbehaving code, like we
always do.

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

So I'm going to volunteer and I'm willing to take a look at the logs
(hopefully Tejun can send some).

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

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();
 
 		if (console_lock_spinning_disable_and_check()) {
 			printk_safe_exit_irqrestore(flags);
-- 
2.17.0