From bd3cc16d1d7d584911f856adc458f242b1c7e85f Mon Sep 17 00:00:00 2001 From: Marco Elver Date: Sat, 10 Oct 2026 11:14:11 +0000 Subject: [PATCH] kcsan: test: Do not count report printing time against test duration Since commit d3539347022a ("serial: 8250: Switch to nbcon console, take 2"), several KCSAN tests fail with CONFIG_KCSAN_VERBOSE=y when using the 8250 console. With CONFIG_KCSAN_VERBOSE=y, the report prints the racing tasks' IRQ trace events via print_irqtrace_events(), which marks its output as a printk emergency section. Within an emergency section, printk() flushes all pending messages to nbcon consoles synchronously. With a slow console, the reporting thread can therefore stall for over a second while holding report_lock, i.e. before the remaining lines of the report are stored. The test, however, stops checking for reports after a fixed deadline, which is easily exceeded by a single slow report: | [ 5.360278] BUG: KCSAN: data-race in test_kernel_read / test_kernel_write | [ 5.360303] write to 0xffffffffab95a478 of 8 bytes by task 237 on cpu 7: | ... | [ 5.360411] irq event stamp: 23 | [ 6.059836] # test_basic: EXPECTATION FAILED at kernel/kcsan/kcsan_test.c:735 | ... | [ 6.616416] read to 0xffffffffab95a478 of 8 bytes by task 238 on cpu 9: Waiting for in-progress reports to complete is insufficient: a slow report that does not match the expected report still uses up the time to observe the expected report. Fix it by pausing the test's time budget while a test-related report is being printed, bounded by an upper limit to avoid stalling the test forever. Once a report completes, always check it at least once. Assisted-by: Antigravity Signed-off-by: Marco Elver --- kernel/kcsan/kcsan_test.c | 34 +++++++++++++++++++++++++++++++++- 1 file changed, 33 insertions(+), 1 deletion(-) diff --git a/kernel/kcsan/kcsan_test.c b/kernel/kcsan/kcsan_test.c index ae758150ccb9..760686e130ad 100644 --- a/kernel/kcsan/kcsan_test.c +++ b/kernel/kcsan/kcsan_test.c @@ -48,6 +48,9 @@ static void (*access_kernels[2])(void); static struct task_struct **threads; /* Lists of threads. */ static unsigned long end_time; /* End time of test. */ +static unsigned long end_time_max; /* Upper bound for end time of test. */ +static unsigned long report_budget; /* Time left when report printing began. */ +static bool report_paused; /* Paused while a report is printing. */ /* Report as observed from console. */ static struct { @@ -69,17 +72,46 @@ begin_test_checks(void (*func1)(void), void (*func2)(void)) * least one race is reported. */ end_time = jiffies + msecs_to_jiffies(CONFIG_KCSAN_REPORT_ONCE_IN_MS + 500); + end_time_max = end_time + msecs_to_jiffies(10000); + report_paused = false; /* Signal start; release potential initialization of shared data. */ smp_store_release(&access_kernels[0], func1); smp_store_release(&access_kernels[1], func2); } +/* + * Printing a report may take a while, e.g. if a printk emergency section (such + * as with CONFIG_KCSAN_VERBOSE) flushes a console backlog synchronously. Do not + * count the time a test-related report is being printed against the test's + * time budget, so that a slow report is neither missed, nor prevents observing + * other reports. Returns true if checking must continue. + */ +static __no_kcsan bool pause_for_report(void) +{ + const int nlines = READ_ONCE(observed.nlines); + const bool in_progress = nlines == 1 || nlines == 2; + + if (in_progress && !report_paused) { + report_paused = true; + report_budget = time_before(jiffies, end_time) ? end_time - jiffies : 0; + } else if (!in_progress && report_paused) { + report_paused = false; + end_time = jiffies + report_budget; + if (time_after(end_time, end_time_max)) + end_time = end_time_max; + /* Check the now complete report at least once. */ + return true; + } + + return report_paused && time_before(jiffies, end_time_max); +} + /* End test checking loop. */ static __no_kcsan inline bool end_test_checks(bool stop) { - if (!stop && time_before(jiffies, end_time)) { + if (!stop && (pause_for_report() || time_before(jiffies, end_time))) { /* Continue checking */ might_sleep(); return false;