On Sat, Apr 30, 2022 at 11:14PM +0206, John Ogness wrote: [...]
I am not familiar with how this works. Is the tracepoint getting set on call_console_drivers()? Or on call_console_driver()?
It's at the start of call_console_drivers(). See trace_console_rcuidle() call.
If so, there are a couple problems with that. First off, the prototype for that function has changed. Second, that function is called when text is printed, but this is not when the text was created. With the kthreads, the printing can be significantly delayed.
Since printk() is now lockless and console printing is delayed, it becomes a bit tricky to parse the records in the existing code using a tracepoint.
I wonder if creating a NOP function for the kfence probe to attach to would be more appropriate. In printk_sprint() we get the text after space has been reserved, but before the text is committed to the ringbuffer. This is guaranteed to be called from within the printk() context.
I think we just need to fix the existing tracepoint, since it has changed its semantics vs. what it was intended to be:
| commit 95100358491abaa2e9a5483811370059bbca4645 | Author: Johannes Berg johannes.berg@intel.com | Date: Thu Nov 24 20:03:08 2011 +0100 | | printk/tracing: Add console output tracing | | Add a printk.console trace point to record any printk | messages into the trace, regardless of the current | console loglevel. This can help correlate (existing) | printk debugging with other tracing. | | Link: http://lkml.kernel.org/r/1322161388.5366.54.camel@jlt3.sipsolutions.net | | Acked-by: Frederic Weisbecker fweisbec@gmail.com | Cc: Christoph Hellwig hch@infradead.org | Cc: Ingo Molnar mingo@redhat.com | Acked-by: Peter Zijlstra a.p.zijlstra@chello.nl | Acked-by: Thomas Gleixner tglx@linutronix.de | Signed-off-by: Johannes Berg johannes.berg@intel.com | Signed-off-by: Steven Rostedt rostedt@goodmis.org
Specifically using it to "correlate (existing) printk debugging with other tracing" is now broken.
Here is an example of what I am thinking...
--- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -2227,6 +2227,10 @@ static u16 printk_sprint(char *text, u16 size, int facility, } } +#ifdef CONFIG_KFENCE_KUNIT_TEST
- printk_kfence_check(text, text_len);
+#endif
- return text_len;
} The probe_console() could attach to a NOP function printk_kfence_check().
Thanks for this! However, I think we can't have a KFENCE-specific helper, it needs to be a tracepoint, because there are more tests that want to check console output (kernel/kcsan/kcsan_test.c did this before the KFENCE test actually).
My proposal would be to fix the tracepoint like so:
| --- a/kernel/printk/printk.c | +++ b/kernel/printk/printk.c | @@ -2002,8 +2002,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", | @@ -2178,6 +2176,8 @@ static u16 printk_sprint(char *text, u16 size, int facility, | } | } | | + trace_console_rcuidle(text, text_len); | + | return text_len; | }
This fixes the KFENCE and KCSAN tests.
Unless I hear objections, I'll prepare a patch explaining why we need to fix the tracepoint.
Thanks, -- Marco