[PATCH] kcsan: test: Do not count report printing time against test duration

[PATCH] kcsan: test: Do not count report printing time against test duration

[Marco Elver]

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 <elver@google.com>
---
 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;
-- 
2.56.0.385.gd3acb90ef8-goog