From 701850dc0c31bfadf75a0a74af7d2c97859945ec Mon Sep 17 00:00:00 2001 From: Marco Elver Date: Tue, 3 May 2022 09:38:44 +0200 Subject: printk, tracing: fix console tracepoint The original intent of the 'console' tracepoint per the commit 95100358491a ("printk/tracing: Add console output tracing") had been to "[...] record any printk messages into the trace, regardless of the current console loglevel. This can help correlate (existing) printk debugging with other tracing." Petr points out [1] that calling trace_console_rcuidle() in call_console_driver() had been the wrong thing for a while, because "printk() always used console_trylock() and the message was flushed to the console only when the trylock succeeded. And it was always deferred in NMI or when printed via printk_deferred()." With the commit 09c5ba0aa2fc ("printk: add kthread console printers"), things only got worse, and calls to call_console_driver() no longer happen with typical printk() calls but always appear deferred [2]. As such, the tracepoint can no longer serve its purpose to clearly correlate printk() calls and other tracing, as well as breaks usecases that expect every printk() call to result in a callback of the console tracepoint. Notably, the KFENCE and KCSAN test suites, which want to capture console output and assume a printk() immediately gives us a callback to the console tracepoint. Fix the console tracepoint by moving it into printk_sprint() [3]. One notable difference is that by moving tracing into printk_sprint(), the 'text' will no longer include the "header" (loglevel and timestamp), but only the raw message. Arguably this is less of a problem now that the console tracepoint happens on the printk() call and isn't delayed. Link: https://lore.kernel.org/all/Ym+WqKStCg%2FEHfh3@alley/ [1] Link: https://lore.kernel.org/all/CA+G9fYu2kS0wR4WqMRsj2rePKV9XLgOU1PiXnMvpT+Z=c2ucHA@mail.gmail.com/ [2] Link: https://lore.kernel.org/all/87fslup9dx.fsf@jogness.linutronix.de/ [3] Reported-by: Linux Kernel Functional Testing Signed-off-by: Marco Elver Cc: John Ogness Cc: Petr Mladek Reviewed-by: Petr Mladek Acked-by: John Ogness Acked-by: Steven Rostedt (Google) Signed-off-by: Petr Mladek Link: https://lore.kernel.org/r/20220503073844.4148944-1-elver@google.com --- kernel/printk/printk.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'kernel/printk') diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index f66d6e72a642..a3e1035929b0 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2064,8 +2064,6 @@ static void call_console_driver(struct console *con, const char *text, size_t le { size_t dropped_len; - trace_console_rcuidle(text, len); - if (con->dropped && dropped_text) { dropped_len = snprintf(dropped_text, DROPPED_TEXT_MAX, "** %lu printk messages dropped **\n", @@ -2240,6 +2238,8 @@ static u16 printk_sprint(char *text, u16 size, int facility, } } + trace_console_rcuidle(text, text_len); + return text_len; } -- cgit v1.2.3