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@xxxxxxxxx> | 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@xxxxxxxxxxxxxxxxxxxxx | | Acked-by: Frederic Weisbecker <fweisbec@xxxxxxxxx> | Cc: Christoph Hellwig <hch@xxxxxxxxxxxxx> | Cc: Ingo Molnar <mingo@xxxxxxxxxx> | Acked-by: Peter Zijlstra <a.p.zijlstra@xxxxxxxxx> | Acked-by: Thomas Gleixner <tglx@xxxxxxxxxxxxx> | Signed-off-by: Johannes Berg <johannes.berg@xxxxxxxxx> | Signed-off-by: Steven Rostedt <rostedt@xxxxxxxxxxx> 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
