* Re: [PATCH v2] stop_machine: Defer legacy console flushes while a CPU runs a stopper callback
2026-09-10 16:16 ` Bradley Morgan
@ 2026-09-11 11:02 ` Aditya Chillara
0 siblings, 0 replies; 4+ messages in thread
From: Aditya Chillara @ 2026-09-11 11:02 UTC (permalink / raw)
To: Bradley Morgan; +Cc: john.ogness, linux-kernel, pmladek, rostedt, senozhatsky
On 9/10/2026 9:46 PM, Bradley Morgan wrote:
> On 10 September 2026 04:53:55 BST, Aditya Chillara
> <aditya.chillara@oss.qualcomm.com> wrote:
>> The cpu stopper thread runs above every other scheduling class, so while a
>> stopper callback executes, nothing else on that CPU is scheduled. If such
>> a
>> callback emits a normal-priority printk(), the legacy console path can
>> synchronously flush the pending console backlog. On systems with a slow
>> UART and a large backlog, this holds the CPU long enough to starve RT
>> kthreads such as the watchdog pet, and for multi_cpu_stop() prevents the
>> CPU from advancing the state machine while the other CPUs wait.
> Oh!
>
>> The
>> resulting delay can prevent watchdog servicing long enough to trigger a
>> watchdog bark or bite.
>>
>> The same can happen from an interrupt taken during the callback:
>> multi_cpu_stop() keeps interrupts enabled during MULTI_STOP_PREPARE, and a
>> printk() may be emitted from a softirq run on irq exit.
>>
>> Run CPU stopper callbacks in printk-deferred context to prevent legacy
>> console flushes while they execute.
>>
>
> Wow! Thanks
>
> Reviewed-by: Bradley Morgan <brads@mainlining.org>
>
>
>> Signed-off-by: Aditya Chillara <aditya.chillara@oss.qualcomm.com>
>> ---
>> A device using a legacy UART console (console=ttyMSM0,115200n8) hit a
>> watchdog bark/bite about 40 seconds after boot.
>>
>
> Which SOC?
It is "Hawi" (actively being upstreamed as of now)
>
>> stop_machine() (used here for kprobe text patching) stops every CPU by
>> running multi_cpu_stop() on each of them, through the per-CPU
>> "migration/%u" threads. These threads run at a higher priority than the
>> msm_watchdog thread. At bite time, all eight CPUs were still spinning in
>> multi_cpu_stop()'s MULTI_STOP_PREPARE state, where interrupts are left
>> enabled.
>>
>> Heavy SELinux denial logging had built up a large backlog on the
>> console. One CPU took an interrupt while spinning in MULTI_STOP_PREPARE.
>> Handling it eventually led to a printk(), and because the console was a
>> legacy console, that printk() synchronously drained the whole backlog
>> over the slow UART. While the drain was still running, the watchdog bark
>> interrupt hit the same CPU, found no recent pet, and escalated to a
>> bite.
>>
>> The captured stack for that CPU, innermost frame first:
>>
>> qcom_soc_set_wdt_bite
>> qcom_wdt_bark_handler
>> __handle_irq_event_percpu
>> handle_irq_event
>> handle_fasteoi_irq
>> generic_handle_domain_irq
>> gic_handle_irq
>> do_interrupt_handler
>> el1_interrupt
>> el1h_64_irq_handler
>> el1h_64_irq
>> console_flush_all
>> console_unlock
>> vprintk_emit
>> dev_vprintk_emit
>> dev_printk_emit
>> __dev_printk
>> _dev_err
>> btspi_sleep_timeout_handler
>> call_timer_fn
>> __run_timer_base
>> run_timer_softirq
>> handle_softirqs
>> __do_softirq
>> ____do_softirq
>> call_on_irq_stack
>> do_softirq_own_stack
>> __irq_exit_rcu
>> irq_exit_rcu
>> el1_interrupt
>> el1h_64_irq_handler
>> el1h_64_irq
>> multi_cpu_stop
>> cpu_stopper_thread
>> smpboot_thread_fn
>> kthread
>> ret_from_fork
>
> Same question as above, but a added "Is this a modern SOC?"
Yes
>
>>
>> Every other CPU stayed parked in the rendezvous the whole time, since
>> their stopper threads outrank msm_watchdog. Nothing could pet the
>> watchdog until the drain finished.
>>
>> This was observed through multi_cpu_stop(), but the hazard is not
>> specific to it. Every cpu stopper callback runs in stop_sched_class,
>> above msm_watchdog and every other thread on the CPU, so a slow flush
>>from any of them (including single-CPU callbacks such as the migration
>> and task-migration stoppers) can starve the watchdog just as well. The
>> fix therefore covers all stopper callbacks, not only multi_cpu_stop().
>>
>> Fix this by running the CPU stopper callbacks in printk-deferred context.
>>
>> Reproduced and verified with an out-of-tree test module that triggers
>> stop_machine() with a queued console backlog and a printk() inside the
>> rendezvous, paired with a kprobe-based script that flags any console
>> flush happening while a CPU is inside a stopper callback.
>
> Hmm, interesting, could you provide what you did? (Not in the description,
> but to me so I can have a look at it)
Sure, here's what I used (the testing code is generated by Claude Code
with claude-opus-4-8 and includes remnants from v1's testing):
diff --git a/drivers/mcs/mcs_repro.c b/drivers/mcs/mcs_repro.c
new file mode 100644
index 0000000000000..ce851212e0950
--- /dev/null
+++ b/drivers/mcs/mcs_repro.c
@@ -0,0 +1,206 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * mcs_repro.c - Reproduce the pre-fix bug targeted by the [DNM] patch
+ * "printk: Defer legacy console flushes from multi_cpu_stop()".
+ *
+ * The bug: a normal-priority printk() issued by a CPU that is *inside*
+ * multi_cpu_stop() takes the legacy_direct flush path and synchronously
+ * drives a slow legacy console (e.g. the ttyMSM0 UART) while the other
+ * rendezvous participants spin waiting for it. The patch adds an
+ * !in_multi_cpu_stop() guard in printk_get_console_flush_type() that forces
+ * legacy_offload instead, so no console flush happens in-window.
+ *
+ * Why a module, and why stop_machine():
+ * The flush must originate ON a CPU that is executing multi_cpu_stop().
+ * A userspace/process-context printk (e.g. writes to /dev/kmsg) runs on
+ * some *other* CPU and can never satisfy this. stop_machine(fn, ...) runs
+ * @fn on the active participant CPU during MULTI_STOP_RUN, at which point
+ * this_cpu(multi_cpu_stop_active) is already true (set at the top of
+ * multi_cpu_stop(), cleared only at its very end). A plain printk() from
+ * @fn therefore observes:
+ * in_multi_cpu_stop() == true
+ * is_printk_legacy_deferred() == false (not RT, not NMI, no
+ * printk_context, not cpu_sync)
+ * -> unpatched: ft.legacy_direct = true -> console_unlock() flushes now
+ * -> patched: ft.legacy_offload = true -> deferred, no in-window flush.
+ *
+ * Detection: run mcs-printk-probe.sh --baseline while triggering this module.
+ * A "flushes while PROTECTED > 0" result is the reproduced bug.
+ *
+ * Usage (on target, as root):
+ * insmod mcs_repro.ko # fires 'iters' rendezvous on load
+ * echo 1 > /sys/kernel/mcs_repro/fire # fire another batch on demand
+ * rmmod mcs_repro
+ *
+ * Module params:
+ * iters=N rendezvous to trigger on load / per fire (default 5)
+ * backlog=N records to pre-queue via printk() before each rendezvous so
+ * the in-window console_unlock() has real work to flush and the
+ * stall is observable (default 200)
+ * loud=0/1 also printk() a marker outside the window (default 1)
+ */
+#include <linux/module.h>
+#include <linux/kernel.h>
+#include <linux/init.h>
+#include <linux/stop_machine.h>
+#include <linux/smp.h>
+#include <linux/delay.h>
+#include <linux/kobject.h>
+#include <linux/sysfs.h>
+
+static unsigned int iters = 5;
+module_param(iters, uint, 0644);
+MODULE_PARM_DESC(iters, "rendezvous to trigger per fire (default 5)");
+
+static unsigned int backlog = 200;
+module_param(backlog, uint, 0644);
+MODULE_PARM_DESC(backlog, "records to pre-queue before each rendezvous (default 200)");
+
+static int loud = 1;
+module_param(loud, int, 0644);
+MODULE_PARM_DESC(loud, "emit an out-of-window marker printk too (default 1)");
+
+static unsigned int flood;
+module_param(flood, uint, 0644);
+MODULE_PARM_DESC(flood,
+ "in-window printk lines per rendezvous (default 0). On an unpatched "
+ "kernel every one flushes the legacy console synchronously while all "
+ "CPUs are captured in the rendezvous; a large value (e.g. 6000) stalls "
+ "long enough that nothing can pet the watchdog -> bark then bite/reset.");
+
+/*
+ * Runs on the active participant CPU during MULTI_STOP_RUN, i.e. with
+ * this_cpu(multi_cpu_stop_active) == true. This normal-priority printk() is
+ * the payload: on an unpatched kernel it flushes the legacy console right
+ * here, inside the rendezvous window the probe script is watching.
+ *
+ * IRQs are disabled in this phase, but that does NOT defer legacy printing:
+ * is_printk_legacy_deferred() checks printk_context / in_nmi / cpu_sync, none
+ * of which are set by local_irq_disable(). So the legacy_direct path is live.
+ */
+static int mcs_repro_fn(void *arg)
+{
+ unsigned long n = (unsigned long)arg;
+ unsigned int k;
+
+ /*
+ * One in-window flush is a definitive *invariant* reproduction, but a
+ * single line drains in a few hundred us -- far too short to trip any
+ * watchdog. To reproduce the severe form (bark -> bite -> reset), loop:
+ * on an unpatched kernel each of these printk()s takes the legacy_direct
+ * path and synchronously pushes bytes out the slow UART, right here,
+ * while every other CPU spins in the rendezvous with IRQs disabled.
+ * Nothing can pet the watchdog, so a large 'flood' produces an unbounded
+ * in-window stall.
+ *
+ * Keep these at a NORMAL level (KERN_INFO). The flush type is decided by
+ * nbcon_get_default_prio(): a normal printk() stays NBCON_PRIO_NORMAL,
+ * which is the *only* branch the patch guards with !in_multi_cpu_stop().
+ * A higher-priority message (e.g. KERN_EMERG raising NBCON_PRIO_EMERGENCY)
+ * would take the unguarded emergency branch and flush in-window even on a
+ * patched kernel -- a false FAIL. So the message must be normal-priority;
+ * the caller (the .sh runner) raises console_loglevel to 8 so these INFO
+ * lines actually reach the console and get flushed.
+ *
+ * We are stopping every CPU; do NOT sleep here. The stall is the point.
+ */
+ printk(KERN_INFO
+ "mcs_repro: in-window printk (rendezvous %lu) on cpu %d flood=%u\n",
+ n, smp_processor_id(), flood);
+
+ for (k = 0; k < flood; k++)
+ printk(KERN_INFO
+ "mcs_repro: in-window flood %u/%u rendezvous %lu cpu %d\n",
+ k, flood, n, smp_processor_id());
+ return 0;
+}
+
+static void mcs_repro_fire(void)
+{
+ unsigned long i, j;
+
+ pr_info("mcs_repro: firing %u rendezvous (backlog=%u)\n", iters, backlog);
+
+ for (i = 0; i < iters; i++) {
+ /*
+ * Pre-queue records so the in-window console_unlock() has a
+ * backlog to drain: the longer the synchronous flush, the more
+ * clearly it overlaps the rendezvous. These run in process
+ * context here (out of window) -- they only build pressure.
+ */
+ for (j = 0; j < backlog; j++)
+ printk(KERN_INFO "mcs_repro: backlog %lu/%lu\n", j, i);
+
+ if (loud)
+ printk(KERN_WARNING
+ "mcs_repro: about to enter rendezvous %lu\n", i);
+
+ /*
+ * stop_machine() with a NULL cpumask stops every online CPU and
+ * runs mcs_repro_fn() on the active one -- from inside
+ * multi_cpu_stop(). This is the trigger.
+ */
+ stop_machine(mcs_repro_fn, (void *)i, NULL);
+
+ /* Let the console/UART drain between rounds. */
+ msleep(20);
+ }
+
+ pr_info("mcs_repro: done. If unpatched, check the probe for "
+ "'flushes while PROTECTED > 0'.\n");
+}
+
+/* --- optional on-demand trigger: echo 1 > /sys/kernel/mcs_repro/fire --- */
+static ssize_t fire_store(struct kobject *kobj, struct kobj_attribute *attr,
+ const char *buf, size_t count)
+{
+ mcs_repro_fire();
+ return count;
+}
+static struct kobj_attribute fire_attr = __ATTR_WO(fire);
+
+static struct attribute *mcs_repro_attrs[] = {
+ &fire_attr.attr,
+ NULL,
+};
+static const struct attribute_group mcs_repro_group = {
+ .attrs = mcs_repro_attrs,
+};
+static struct kobject *mcs_repro_kobj;
+
+static int __init mcs_repro_init(void)
+{
+ int ret;
+
+ mcs_repro_kobj = kobject_create_and_add("mcs_repro", kernel_kobj);
+ if (mcs_repro_kobj) {
+ ret = sysfs_create_group(mcs_repro_kobj, &mcs_repro_group);
+ if (ret) {
+ kobject_put(mcs_repro_kobj);
+ mcs_repro_kobj = NULL;
+ pr_warn("mcs_repro: sysfs group failed (%d); "
+ "on-demand /sys/kernel/mcs_repro/fire disabled\n",
+ ret);
+ }
+ } else {
+ pr_warn("mcs_repro: kobject failed; on-demand fire disabled\n");
+ }
+
+ /* Fire once on load so 'insmod' alone reproduces without extra steps. */
+ mcs_repro_fire();
+ return 0;
+}
+
+static void __exit mcs_repro_exit(void)
+{
+ if (mcs_repro_kobj)
+ kobject_put(mcs_repro_kobj);
+ pr_info("mcs_repro: unloaded\n");
+}
+
+module_init(mcs_repro_init);
+module_exit(mcs_repro_exit);
+
+MODULE_LICENSE("GPL");
+MODULE_DESCRIPTION("Reproduce in-window legacy console flush from multi_cpu_stop()");
+MODULE_AUTHOR("mcs-printk-probe");
diff --git a/mcs-printk-probe.sh b/mcs-printk-probe.sh
new file mode 100755
index 0000000000000..d575f55ae15fe
--- /dev/null
+++ b/mcs-printk-probe.sh
@@ -0,0 +1,478 @@
+#!/bin/sh
+# Verify: no legacy console flush on a CPU while it is inside multi_cpu_stop().
+#
+# Tests the [DNM] "printk: Defer legacy console flushes from multi_cpu_stop()"
+# patch by observable consequence, because both decision points are inlined
+# and cannot be probed directly:
+# in_multi_cpu_stop() __always_inline (include/linux/stop_machine.h)
+# printk_get_console_flush_type() static inline (kernel/printk/internal.h)
+#
+# Trigger: on arm64 every kprobe arm/disarm patches text via
+# aarch64_insn_patch_text() -> stop_machine_cpuslocked(), so probe management
+# is itself a rendezvous. No hotplug needed (but --hotplug widens the window).
+#
+# Usage:
+# ./mcs-printk-probe.sh # full run: setup, stress, report
+# ./mcs-printk-probe.sh --iters 50
+# ./mcs-printk-probe.sh --hotplug # add CPU hotplug as a second trigger
+# ./mcs-printk-probe.sh --no-backlog # skip /dev/kmsg log pressure
+# ./mcs-printk-probe.sh --no-requeue-probe # tolerate a missing requeue probe
+# ./mcs-printk-probe.sh --baseline # kernel WITHOUT the fix: expect the
+# # bug, so in-window flushes = success
+# # (implies --no-requeue-probe)
+# ./mcs-printk-probe.sh --report-only # re-analyse an existing trace
+# ./mcs-printk-probe.sh --cleanup # remove probes, restore tracing
+set -u
+
+ITERS=20
+USE_HOTPLUG=0
+USE_BACKLOG=1
+REPORT_ONLY=0
+CLEANUP_ONLY=0
+KEEP=0
+NO_REQUEUE=0
+BASELINE=0
+SAVE=/data/local/tmp/mcs-printk-trace.txt
+
+while [ $# -gt 0 ]; do
+ case "$1" in
+ --iters) ITERS=$2; shift 2 ;;
+ --hotplug) USE_HOTPLUG=1; shift ;;
+ --no-backlog) USE_BACKLOG=0; shift ;;
+ --no-requeue-probe) NO_REQUEUE=1; shift ;;
+ --baseline) BASELINE=1; NO_REQUEUE=1; shift ;;
+ --report-only) REPORT_ONLY=1; shift ;;
+ --cleanup) CLEANUP_ONLY=1; shift ;;
+ --keep) KEEP=1; shift ;;
+ --save) SAVE=$2; shift 2 ;;
+ -h|--help) sed -n '2,28p' "$0"; exit 0 ;;
+ *) echo "unknown option: $1" >&2; exit 2 ;;
+ esac
+done
+
+# ---------------------------------------------------------------- tracefs ----
+
+TR=
+for d in /sys/kernel/tracing /sys/kernel/debug/tracing; do
+ [ -f "$d/kprobe_events" ] && { TR=$d; break; }
+done
+if [ -z "$TR" ]; then
+ # --report-only just parses a saved trace; it needs no tracefs at all, so
+ # allow it to run off-target (e.g. analysing a pulled trace on a host).
+ if [ "$REPORT_ONLY" = 1 ] && [ -r "$SAVE" ]; then
+ echo "note: no tracefs; analysing $SAVE only." >&2
+ else
+ echo "FATAL: tracefs with kprobe_events not found." >&2
+ echo " need CONFIG_KPROBES=y + CONFIG_KPROBE_EVENTS=y; try: mount -t tracefs none /sys/kernel/tracing" >&2
+ exit 1
+ fi
+else
+ [ "$(id -u 2>/dev/null || echo 0)" = 0 ] || echo "WARN: not root; writes to $TR will likely fail." >&2
+fi
+
+# kprobe_events is global -- there is only one list of kprobe events, and any
+# tool opening it with O_TRUNC calls dyn_events_release_all() (see
+# kernel/trace/trace_kprobe.c) which deletes *everyone's* probes and resets the
+# buffer via tracing_reset_all_online_cpus(). On Android, Perfetto/traced_probes
+# does exactly this.
+#
+# The probe list cannot be made private, but the ring buffer, the per-event
+# enables and tracing_on can: a tracefs instance gets its own events/ tree and
+# its own tracing_on. Record into an instance so a competing tracer clearing the
+# top-level buffer does not silently discard our events.
+#
+# EV is where per-event enables and the buffer live; TR stays the top level,
+# which is the only place kprobe_events exists.
+INST=$TR/instances/mcsprintk
+EV=$TR
+USE_INST=0
+if [ -d "$TR/instances" ]; then
+ if [ -d "$INST" ] || mkdir "$INST" 2>/dev/null; then
+ if [ -f "$INST/tracing_on" ]; then
+ EV=$INST
+ USE_INST=1
+ fi
+ fi
+fi
+
+BACKLOG_PID=
+# PID of the shell that installed the exit trap, plus a filesystem sentinel.
+# Shell-variable guards alone are not enough: a subshell inherits both the trap
+# AND a copy of the variables, so it can believe it is the main shell. The
+# sentinel file is shared state, so whoever creates it first owns teardown.
+MAIN_PID=$$
+DONE_FLAG=/data/local/tmp/.mcs-printk-cleanup.$MAIN_PID
+case "$DONE_FLAG" in
+/data/local/tmp/*) [ -d /data/local/tmp ] || DONE_FLAG=/tmp/.mcs-printk-cleanup.$MAIN_PID ;;
+esac
+
+cleanup_probes() {
+ echo 0 > "$EV/tracing_on" 2>/dev/null
+ [ -f "$EV/events/kprobes/enable" ] && echo 0 > "$EV/events/kprobes/enable" 2>/dev/null
+ # Each removal is itself a rendezvous; harmless once tracing is off.
+ # kprobe_events lives only at the top level, never in an instance.
+ for p in trig flush flush2 deferred mcs_in mcs_out; do
+ echo "-:$p" >> "$TR/kprobe_events" 2>/dev/null
+ done
+ [ "$USE_INST" = 1 ] && rmdir "$INST" 2>/dev/null
+ :
+}
+
+on_exit() {
+ # Only the main shell tears down, and only once.
+ [ "$$" = "$MAIN_PID" ] || return 0
+ [ -e "$DONE_FLAG" ] && return 0
+ : > "$DONE_FLAG" 2>/dev/null
+ [ -n "$BACKLOG_PID" ] && kill "$BACKLOG_PID" 2>/dev/null
+ wait "$BACKLOG_PID" 2>/dev/null
+ [ "$KEEP" = 1 ] || cleanup_probes
+ rm -f "$DONE_FLAG" 2>/dev/null
+}
+
+if [ "$CLEANUP_ONLY" = 1 ]; then
+ cleanup_probes
+ echo "probes removed."
+ exit 0
+fi
+
+# ------------------------------------------------------- console sanity ------
+# If no legacy console is registered, have_legacy_console is false, the patched
+# branch in kernel/printk/internal.h never executes, and a clean trace proves
+# nothing. Report it rather than silently passing.
+
+LEGACY_HINT=unknown
+if [ -r /proc/consoles ]; then
+ echo "--- /proc/consoles ---"
+ cat /proc/consoles
+ echo "----------------------"
+ if grep -qi 'N.*C' /proc/consoles 2>/dev/null || grep -q 'tty' /proc/consoles 2>/dev/null; then
+ LEGACY_HINT=likely
+ fi
+fi
+
+# ------------------------------------------------------------- setup ---------
+
+if [ "$REPORT_ONLY" = 0 ]; then
+ trap on_exit EXIT INT TERM
+
+ cleanup_probes
+ # Re-create the instance: cleanup_probes removes it.
+ if [ "$USE_INST" = 1 ]; then
+ mkdir "$INST" 2>/dev/null
+ [ -f "$INST/tracing_on" ] || { EV=$TR; USE_INST=0
+ echo "WARN: could not create tracefs instance; using top level." >&2; }
+ fi
+ [ "$USE_INST" = 1 ] && echo "recording into instance: $INST"
+ echo nop > "$EV/current_tracer" 2>/dev/null
+ : > "$EV/trace"
+ # Remove any saved trace from a previous run. Two consecutive runs reporting
+ # byte-identical counts is the signature of analysing a stale file.
+ rm -f "$SAVE" 2>/dev/null
+
+ add_probe() { # name spec -> 0 if registered
+ if echo "$2" >> "$TR/kprobe_events" 2>/dev/null; then
+ return 0
+ fi
+ echo "note: could not register probe '$1' ($2)" >&2
+ return 1
+ }
+
+ # Observers first, armed before any trigger. A probe cannot observe its own
+ # arming: the breakpoint goes live inside aarch64_insn_patch_text_cb(), i.e.
+ # partway through a rendezvous the other CPUs already entered.
+ FLUSH_SYM=none
+ if add_probe flush 'p:flush console_flush_all'; then
+ FLUSH_SYM=console_flush_all
+ fi
+ # console_flush_all is static and may be inlined; console_unlock is the
+ # legacy loop's external entry point and survives inlining.
+ if add_probe flush2 'p:flush2 console_unlock'; then
+ [ "$FLUSH_SYM" = none ] && FLUSH_SYM=console_unlock
+ fi
+ if [ "$FLUSH_SYM" = none ]; then
+ echo "FATAL: neither console_flush_all nor console_unlock is probe-able." >&2
+ exit 1
+ fi
+
+ # printk_defer_console_output marks the requeue point: it runs *after* the
+ # per-CPU flag is cleared, so it is the boundary between the protected
+ # region and the benign tail of multi_cpu_stop(). See analysis notes.
+ #
+ # It is a *global* function, so it is in kallsyms unconditionally -- if the
+ # patch is present. Failure to probe it most likely means the running kernel
+ # does not carry the patch, in which case the whole run is moot. Say so.
+ if ! add_probe deferred 'p:deferred printk_defer_console_output'; then
+ if [ "$NO_REQUEUE" = 1 ]; then
+ echo "WARN: no requeue boundary (--no-requeue-probe); the benign tail of" >&2
+ echo " multi_cpu_stop() cannot be distinguished, so late flushes may be" >&2
+ echo " reported as violations. Treat any FAIL as needing manual review." >&2
+ else
+ echo "" >&2
+ echo "FATAL: cannot probe printk_defer_console_output." >&2
+ if [ -r /proc/kallsyms ] && ! grep -qw printk_defer_console_output /proc/kallsyms 2>/dev/null; then
+ if grep -qw multi_cpu_stop /proc/kallsyms 2>/dev/null; then
+ echo " Symbol absent from /proc/kallsyms while multi_cpu_stop is present:" >&2
+ echo " the running kernel does NOT carry the patch under test." >&2
+ echo " Reflash a kernel built with the [DNM] printk deferral patch." >&2
+ else
+ echo " /proc/kallsyms exposes no symbols (kptr_restrict?), cannot confirm." >&2
+ echo " Check: sysctl kernel.kptr_restrict (needs 0 to read symbol names)" >&2
+ fi
+ fi
+ echo " Override with --no-requeue-probe to test the flag window only." >&2
+ exit 1
+ fi
+ fi
+
+ add_probe mcs_in 'p:mcs_in multi_cpu_stop' || { echo "FATAL: cannot probe multi_cpu_stop." >&2; exit 1; }
+ add_probe mcs_out 'r:mcs_out multi_cpu_stop' || echo "WARN: no kretprobe; window end will be inferred." >&2
+
+ # Verify the enables actually took. Silent failure here (SELinux, or another
+ # tracer clearing kprobe_events via O_TRUNC) yields an empty buffer that
+ # looks indistinguishable from "no events occurred".
+ echo 1 > "$EV/events/kprobes/enable" 2>/dev/null
+ echo 1 > "$EV/tracing_on" 2>/dev/null
+ en=$(cat "$EV/events/kprobes/enable" 2>/dev/null)
+ on=$(cat "$EV/tracing_on" 2>/dev/null)
+ case "$en" in
+ 1*) ;;
+ *) echo "FATAL: events/kprobes/enable did not take (reads '$en')." >&2
+ echo " Probes are registered but disarmed, so nothing will be recorded." >&2
+ exit 1 ;;
+ esac
+ if [ "$on" != 1 ]; then
+ echo "FATAL: tracing_on did not take (reads '$on')." >&2
+ echo " Something is resetting tracefs -- most likely Perfetto/traced_probes." >&2
+ echo " Try: stop traced_probes (and 'start traced_probes' afterwards)" >&2
+ exit 1
+ fi
+
+ # Snapshot the probe list so we can tell afterwards whether someone deleted
+ # our probes out from under us (O_TRUNC on kprobe_events wipes all of them).
+ probes_before=$(grep -c . "$TR/kprobe_events" 2>/dev/null || echo 0)
+
+ # --------------------------------------------------------- stress --------
+ # The bug needs a normal-priority printk() from an interrupt during
+ # MULTI_STOP_PREPARE plus a pending backlog. An idle system shows nothing.
+ if [ "$USE_BACKLOG" = 1 ] && [ -w /dev/kmsg ]; then
+ # Run the backlog generator as a FRESH PROCESS (sh -c), not a subshell.
+ #
+ # A background subshell inherits the parent's trap handlers, and 'trap -'
+ # inside it is not reliably honoured across shells (notably Android's
+ # mksh). When such a subshell is killed it runs on_exit() ->
+ # cleanup_probes(), deleting our probes and rmdir'ing our instance while
+ # the main shell is still wrapping up. A separate process started by
+ # 'sh -c' has no access to this shell's traps, so it cannot do that.
+ sh -c 'i=0
+ while [ $i -lt 100000 ]; do
+ echo "mcs-probe backlog $i" > /dev/kmsg 2>/dev/null || break
+ i=$((i + 1))
+ done' &
+ BACKLOG_PID=$!
+ fi
+
+ HP_CPU=
+ if [ "$USE_HOTPLUG" = 1 ]; then
+ # take_cpu_down() spends far longer in MULTI_STOP_PREPARE than text
+ # patching does, so the interrupts-enabled window is much wider.
+ for c in $(ls -d /sys/devices/system/cpu/cpu[0-9]* 2>/dev/null | sort -r); do
+ f=$c/online
+ [ -w "$f" ] && [ "$(cat "$f" 2>/dev/null)" = 1 ] && { HP_CPU=$f; break; }
+ done
+ [ -n "$HP_CPU" ] || echo "WARN: no offline-able CPU found; hotplug trigger skipped." >&2
+ fi
+
+ echo "running $ITERS iterations (flush probe: $FLUSH_SYM, backlog: $USE_BACKLOG, hotplug: ${HP_CPU:-no})"
+
+ # Register the trigger probe ONCE, outside the loop.
+ #
+ # Deleting a dynamic event calls tracing_reset_all_online_cpus()
+ # (kernel/trace/trace_dynevent.c:114), which walks ftrace_trace_arrays and
+ # clears EVERY trace array -- including our instance. Deleting -:trig inside
+ # the loop therefore wiped the buffer on every iteration, leaving only the
+ # last iteration's events behind.
+ #
+ # enable/disable alone still patches text via arch_arm_kprobe() ->
+ # aarch64_insn_patch_text() -> stop_machine_cpuslocked(), so each toggle is
+ # a full rendezvous, and neither toggle resets the buffer.
+ echo 'p:trig schedule' >> "$TR/kprobe_events" 2>/dev/null
+ [ -f "$EV/events/kprobes/trig/enable" ] || echo "WARN: trigger probe unavailable; relying on hotplug only." >&2
+
+ i=0
+ while [ $i -lt "$ITERS" ]; do
+ # Two rendezvous per iteration: arm on enable, disarm on disable.
+ echo 1 > "$EV/events/kprobes/trig/enable" 2>/dev/null
+ echo 0 > "$EV/events/kprobes/trig/enable" 2>/dev/null
+
+ [ -n "$HP_CPU" ] && { echo 0 > "$HP_CPU" 2>/dev/null; echo 1 > "$HP_CPU" 2>/dev/null; }
+
+ i=$((i + 1))
+ done
+
+ [ -n "$BACKLOG_PID" ] && { kill "$BACKLOG_PID" 2>/dev/null; wait "$BACKLOG_PID" 2>/dev/null; BACKLOG_PID=; }
+
+ # Did tracing survive the run? If something reset it mid-flight the buffer
+ # will be short or empty, and that is a tooling failure, not a PASS.
+ on_after=$(cat "$EV/tracing_on" 2>/dev/null)
+ en_after=$(cat "$EV/events/kprobes/enable" 2>/dev/null)
+ probes_after=$(grep -c . "$TR/kprobe_events" 2>/dev/null || echo 0)
+ [ "$on_after" = 1 ] || echo "WARN: tracing_on became '$on_after' during the run (reset by another tracer?)." >&2
+ case "$en_after" in
+ 1*) ;;
+ *) echo "WARN: events/kprobes/enable became '$en_after' during the run." >&2 ;;
+ esac
+ if [ "$probes_after" -lt "$probes_before" ] 2>/dev/null; then
+ echo "" >&2
+ echo "DIAGNOSIS: kprobe_events shrank from $probes_before to $probes_after entries" >&2
+ echo " during the run, so events were lost. Note that ANY dynamic-event" >&2
+ echo " deletion also calls tracing_reset_all_online_cpus()" >&2
+ echo " (kernel/trace/trace_dynevent.c), which clears every trace array --" >&2
+ echo " including our instance. Possible causes:" >&2
+ echo " - another tracer opening kprobe_events with O_TRUNC (deletes ALL" >&2
+ echo " entries at once; on Android usually traced_probes/Perfetto)" >&2
+ echo " - a stray cleanup racing this run (deletes only OUR entries)" >&2
+ if [ -r "$TR/kprobe_events" ]; then
+ echo " Surviving entries:" >&2
+ sed 's/^/ /' "$TR/kprobe_events" >&2 2>/dev/null
+ fi
+ fi
+
+ # Guard these: if the instance was removed mid-run the writes would emit
+ # "can't create .../tracing_on: No such file or directory" noise.
+ if [ -f "$EV/tracing_on" ]; then
+ echo 0 > "$EV/tracing_on" 2>/dev/null
+ else
+ echo "WARN: $EV/tracing_on is gone; the recording buffer was destroyed." >&2
+ fi
+ if [ -r "$EV/trace" ]; then
+ cp "$EV/trace" "$SAVE" 2>/dev/null && echo "raw trace saved to $SAVE"
+ else
+ echo "" >&2
+ echo "FATAL: the recording buffer was destroyed before it could be saved." >&2
+ echo " Refusing to report: any verdict now would describe stale or absent" >&2
+ echo " data, not this run. Nothing was measured." >&2
+ echo " Re-run; if this repeats, something on the device is deleting kprobe" >&2
+ echo " events (see the DIAGNOSIS above for what survived)." >&2
+ exit 1
+ fi
+fi
+
+# ------------------------------------------------------------ analysis -------
+# Per CPU, walk the event stream and track state:
+# mcs_in -> PROTECTED (a flush here is a failure)
+# deferred -> TAIL (flag already cleared; a flush here is expected)
+# mcs_out -> IDLE (flushes here are normal operation)
+
+SRC=$SAVE
+if [ ! -r "$SRC" ]; then
+ if [ -n "$TR" ] && [ -r "$EV/trace" ]; then
+ SRC=$EV/trace
+ else
+ echo "FATAL: no trace to analyse ($SAVE unreadable)." >&2
+ exit 1
+ fi
+fi
+
+awk -v baseline="$BASELINE" '
+function ev(l) { # event name sits after the timestamp colon
+ if (match(l, /: [a-z_0-9]+:/)) {
+ s = substr(l, RSTART + 2, RLENGTH - 3)
+ return s
+ }
+ return ""
+}
+function cpuof(l) {
+ if (match(l, /\[[0-9]+\]/))
+ return substr(l, RSTART + 1, RLENGTH - 2) + 0
+ return -1
+}
+function tsof(l) {
+ if (match(l, /[0-9]+\.[0-9]+:/))
+ return substr(l, RSTART, RLENGTH - 1) + 0
+ return 0
+}
+/^#/ || /^$/ { next }
+{
+ e = ev($0); c = cpuof($0); t = tsof($0)
+ if (e == "" || c < 0) next
+ total++
+
+ if (e == "mcs_in") {
+ state[c] = "PROTECTED"; enter[c] = t; windows++
+ } else if (e == "deferred") {
+ if (state[c] == "PROTECTED") { state[c] = "TAIL"; requeues++ }
+ else { requeue_outside++ }
+ } else if (e == "mcs_out") {
+ if (state[c] == "PROTECTED" || state[c] == "TAIL") {
+ dur = t - enter[c]
+ if (dur > maxdur) maxdur = dur
+ sumdur += dur; ndur++
+ }
+ state[c] = "IDLE"
+ } else if (e == "flush" || e == "flush2") {
+ if (state[c] == "PROTECTED") {
+ viol++
+ if (viol <= 12)
+ printf(" VIOLATION cpu%-2d t=%.6f (%+.6fs into window) %s\n",
+ c, t, t - enter[c], e) > "/dev/stderr"
+ } else if (state[c] == "TAIL") {
+ tail_flush++
+ } else {
+ outside++
+ }
+ }
+}
+END {
+ printf("\n=========== multi_cpu_stop / legacy console flush ===========\n")
+ if (baseline == 1)
+ printf("mode : BASELINE (kernel WITHOUT the fix)\n")
+ printf("events parsed : %d\n", total)
+ printf("rendezvous windows : %d\n", windows)
+ if (ndur > 0)
+ printf("window duration : avg %.6fs max %.6fs\n", sumdur / ndur, maxdur)
+ printf("requeues (in-window) : %d\n", requeues + 0)
+ if (requeue_outside > 0)
+ printf("requeues (out-of-win) : %d <- unexpected; check probe pairing\n", requeue_outside)
+ printf("flushes outside window : %d\n", outside + 0)
+ printf("flushes in benign tail : %d (after requeue, flag already cleared)\n", tail_flush + 0)
+ printf("flushes while PROTECTED: %d\n", viol + 0)
+ printf("------------------------------------------------------------\n")
+
+ if (windows == 0) {
+ printf("INCONCLUSIVE: no rendezvous observed. Probes may not have armed,\n")
+ printf(" or tracing was off during the trigger loop.\n")
+ } else if (outside == 0 && tail_flush == 0 && viol == 0) {
+ printf("INCONCLUSIVE: no legacy console flush seen anywhere. The absence of\n")
+ printf(" in-window flushes proves nothing unless flushes happen at all --\n")
+ printf(" check /proc/consoles for a legacy (non-nbcon) console and re-run\n")
+ printf(" with log pressure.\n")
+ } else if (baseline == 1) {
+ # Inverted expectation: without the fix, in-window flushes are the bug
+ # being demonstrated, and their absence means the stress never landed.
+ if (viol > 0) {
+ printf("REPRODUCED: %d legacy flush(es) inside multi_cpu_stop() across %d\n", viol, windows)
+ printf(" rendezvous. This is the pre-fix behaviour the patch targets.\n")
+ printf(" Record these numbers, then re-run on a patched kernel WITHOUT\n")
+ printf(" --baseline and expect PASS (0 in-window flushes).\n")
+ } else {
+ printf("NOT REPRODUCED: %d flush(es) seen, but none inside a window.\n", outside + tail_flush)
+ printf(" The unpatched kernel should show in-window flushes, so the stress\n")
+ printf(" likely never coincided with MULTI_STOP_PREPARE. Widen the window\n")
+ printf(" and raise pressure: --hotplug --iters 200.\n")
+ printf(" Note the race needs an interrupt-context printk() inside a short\n")
+ printf(" window; a quiet device can miss it for many runs.\n")
+ }
+ } else if (viol > 0) {
+ printf("FAIL: %d legacy flush(es) inside the protected region.\n", viol)
+ printf(" Enable stack traces to see the escaping path:\n")
+ printf(" echo stacktrace > <tracefs>/events/kprobes/flush/trigger\n")
+ } else {
+ printf("PASS: no legacy console flush inside any protected region,\n")
+ printf(" across %d rendezvous, with %d flush(es) observed elsewhere.\n",
+ windows, outside + tail_flush)
+ }
+ printf("============================================================\n")
+}
+' "$SRC"
+
+exit 0
diff --git a/mcs-repro-run.sh b/mcs-repro-run.sh
new file mode 100644
index 0000000000000..c826e3c2eb0d6
--- /dev/null
+++ b/mcs-repro-run.sh
@@ -0,0 +1,265 @@
+#!/bin/sh
+# mcs-repro-run.sh - On-device runner: drive mcs_repro.ko (the in-window printk
+# trigger) while mcs-printk-probe.sh records, to reproduce the pre-fix bug
+# targeted by the [DNM] "printk: Defer legacy console flushes from
+# multi_cpu_stop()" patch.
+#
+# This is a SEPARATE file from the probe on purpose, and like the probe it
+# contains NO adb commands -- run it ON the target as root. Push both scripts
+# and the .ko to the device first (see the adb commands your host provides).
+#
+# What it does:
+# 1. starts mcs-printk-probe.sh --baseline in the background (it arms the
+# kprobes, records, then tears down and prints the verdict);
+# 2. waits until the probe reports it is armed and recording;
+# 3. insmod's mcs_repro.ko (its stop_machine() callback issues a normal
+# printk() from inside multi_cpu_stop() -> on an unpatched kernel that is a
+# legacy console flush in the protected window);
+# 4. keeps firing more rendezvous (/sys/kernel/mcs_repro/fire) until the
+# probe's recording window closes, so an in-window flush is guaranteed to
+# overlap regardless of exact timing;
+# 5. rmmod's the module and prints the probe's report.
+#
+# A "flushes while PROTECTED > 0" / REPRODUCED verdict is the bug. On a patched
+# kernel the same run should print PASS (0 in-window flushes).
+#
+# Usage (as root, on target):
+# ./mcs-repro-run.sh
+# ./mcs-repro-run.sh --iters 500 --backlog 400
+# ./mcs-repro-run.sh --dir /data/local/tmp --report /data/local/tmp/rep.txt
+# ./mcs-repro-run.sh --loglevel 0 # do not touch console loglevel
+# ./mcs-repro-run.sh --crash # SEVERE form: watchdog bark -> reset
+# ./mcs-repro-run.sh --crash --flood 10000
+#
+# By default the console loglevel is forced to 8 for the run (and restored
+# afterwards) so the module's normal-priority KERN_INFO in-window printk()s
+# actually reach the console and get flushed -- otherwise a low loglevel
+# filters them out and no in-window flush happens. Use --loglevel 0 to leave
+# the current setting untouched.
+#
+# --crash reproduces the SEVERE form of the bug instead of the measurable
+# invariant. It runs NO probe (no kprobes, no recording, no report): the module
+# reaches multi_cpu_stop() on its own via stop_machine(), and a large in-window
+# 'flood' of KERN_INFO printk()s drives the slow legacy UART synchronously while
+# every other CPU spins with IRQs disabled -- nothing pets the watchdog, so on
+# an unpatched kernel you get a soft-lockup/RCU-stall bark then a watchdog bite
+# and reset. This is destructive by design: the device is expected to reboot,
+# so no teardown runs. On a patched kernel the flush is offloaded and the box
+# survives. Expect NO shell prompt back if it works.
+set -u
+
+DIR=/data/local/tmp
+PROBE=
+KO=
+REPORT=
+MOD=mcs_repro
+ITERS=300 # probe trigger-loop length -> how long the recording stays open
+BACKLOG=200 # records the module pre-queues before each in-window printk
+KOITERS=5 # rendezvous the module fires per insmod / per sysfs 'fire'
+NO_BACKLOG=0 # pass through to the probe (--no-backlog)
+LOGLEVEL=8 # console loglevel to force while stressing (0 = leave as-is)
+CRASH=0 # --crash: skip the probe, drive a long in-window flood
+FLOOD=6000 # --crash: in-window printk lines per rendezvous
+
+while [ $# -gt 0 ]; do
+ case "$1" in
+ --dir) DIR=$2; shift 2 ;;
+ --probe) PROBE=$2; shift 2 ;;
+ --ko) KO=$2; shift 2 ;;
+ --report) REPORT=$2; shift 2 ;;
+ --iters) ITERS=$2; shift 2 ;;
+ --backlog) BACKLOG=$2; shift 2 ;;
+ --ko-iters) KOITERS=$2; shift 2 ;;
+ --no-backlog) NO_BACKLOG=1; shift ;;
+ --loglevel) LOGLEVEL=$2; shift 2 ;;
+ --crash) CRASH=1; shift ;;
+ --flood) FLOOD=$2; shift 2 ;;
+ -h|--help) sed -n '2,50p' "$0"; exit 0 ;;
+ *) echo "unknown option: $1" >&2; exit 2 ;;
+ esac
+done
+
+: "${PROBE:=$DIR/mcs-printk-probe.sh}"
+: "${KO:=$DIR/mcs_repro.ko}"
+: "${REPORT:=$DIR/mcs-repro-report.txt}"
+FIRE=/sys/kernel/$MOD/fire
+
+# ------------------------------------------------------------- preconditions --
+if [ "$(id -u 2>/dev/null || echo 0)" != 0 ]; then
+ echo "FATAL: must run as root (kprobes, insmod, /sys writes)." >&2
+ exit 1
+fi
+# --crash runs no probe at all, so the probe script need not even be present.
+if [ "$CRASH" = 0 ] && [ ! -r "$PROBE" ]; then
+ echo "FATAL: probe script not found/readable: $PROBE" >&2
+ echo " push mcs-printk-probe.sh to the device and/or pass --probe PATH." >&2
+ exit 1
+fi
+if [ ! -r "$KO" ]; then
+ echo "FATAL: module not found/readable: $KO" >&2
+ echo " push mcs_repro.ko to the device and/or pass --ko PATH." >&2
+ exit 1
+fi
+
+# A short sleep that tolerates shells/toybox without fractional sleep.
+nap() { sleep "$1" 2>/dev/null || sleep 1; }
+
+# The module's in-window printk()s are KERN_INFO (level 6). A message reaches
+# the console only when its level < console_loglevel, so unless the console
+# loglevel is raised above 6 those lines are filtered before the console layer
+# and NO synchronous flush -- hence no in-window stall -- ever happens, even
+# though the legacy_direct path is vulnerable. That is the "needed echo 8 >
+# /proc/sys/kernel/printk" trap. We must NOT raise the message level instead:
+# KERN_EMERG would push the context to NBCON_PRIO_EMERGENCY, whose branch in
+# printk_get_console_flush_type() has no !in_multi_cpu_stop() guard, so it would
+# flush in-window even on a patched kernel (false FAIL). Keep the printk normal
+# priority and raise console_loglevel here instead.
+PRINTK_SYSCTL=/proc/sys/kernel/printk
+SAVED_LOGLEVEL=
+set_loglevel() {
+ [ "$LOGLEVEL" = 0 ] && return 0
+ [ -w "$PRINTK_SYSCTL" ] || { echo "WARN: $PRINTK_SYSCTL not writable; leaving loglevel as-is." >&2; return 0; }
+ # Column 1 is the current console_loglevel; save the whole line to restore.
+ SAVED_LOGLEVEL=$(cat "$PRINTK_SYSCTL" 2>/dev/null)
+ echo "$LOGLEVEL" > "$PRINTK_SYSCTL" 2>/dev/null
+ echo "console loglevel: $(echo "$SAVED_LOGLEVEL" | awk '{print $1}') -> $LOGLEVEL (KERN_INFO must pass the filter to flush)"
+}
+restore_loglevel() {
+ [ -n "$SAVED_LOGLEVEL" ] || return 0
+ # Restore just the console_loglevel column; a plain int write sets that field.
+ echo "$SAVED_LOGLEVEL" | awk '{print $1}' > "$PRINTK_SYSCTL" 2>/dev/null
+ SAVED_LOGLEVEL=
+}
+
+cleanup() {
+ # Best-effort teardown; safe to call more than once.
+ rmmod "$MOD" 2>/dev/null
+ [ -n "${PROBE_PID:-}" ] && kill "$PROBE_PID" 2>/dev/null
+ restore_loglevel
+}
+trap 'cleanup' INT TERM
+
+# ------------------------------------------------------------- crash mode -----
+# The SEVERE reproduction. No probe, no kprobes, no recording: the module calls
+# stop_machine() directly, which is what puts mcs_repro_fn() inside
+# multi_cpu_stop() on the active participant CPU. The 'flood' loop then issues
+# FLOOD normal-priority printk()s from there. On an unpatched kernel each one
+# takes the legacy_direct path and synchronously pushes bytes out the slow UART
+# while every other CPU spins in the rendezvous with IRQs disabled, so nothing
+# can pet the watchdog for the whole duration -> bark, then bite and reset.
+#
+# Deliberately skips rmmod/restore on the way out: if this works the kernel is
+# gone before that could run anyway, and the loglevel lives in RAM so the reset
+# restores it for free. If the box is still alive after, something did not
+# reproduce -- that is reported, not silently swallowed.
+if [ "$CRASH" = 1 ]; then
+ echo "=================== CRASH MODE ===================="
+ echo "iters=1 backlog=0 loud=0 flood=$FLOOD, loglevel=$LOGLEVEL"
+ echo "Expect NO prompt back if this reproduces: bark -> bite -> reset."
+ echo "===================================================="
+
+ rmmod "$MOD" 2>/dev/null
+ set_loglevel
+
+ if ! insmod "$KO" iters=1 backlog=0 loud=0 flood="$FLOOD"; then
+ echo "FATAL: insmod failed; no crash attempted." >&2
+ echo " Check: dmesg | tail (vermagic mismatch shows here)." >&2
+ restore_loglevel
+ trap - INT TERM
+ exit 1
+ fi
+
+ # If we get here the module returned control without a reset: the
+ # in-window flood did not stall long enough (or the kernel is patched).
+ echo ""
+ echo "NOT REPRODUCED (severe form): device is still up after flood=$FLOOD."
+ echo " Either the kernel carries the fix, or the stall was too short to"
+ echo " trip the watchdog -- retry with a larger --flood."
+ rmmod "$MOD" 2>/dev/null
+ restore_loglevel
+ trap - INT TERM
+ exit 0
+fi
+
+# --------------------------------------------------------------- clean slate --
+rmmod "$MOD" 2>/dev/null
+"$PROBE" --cleanup >/dev/null 2>&1
+
+# Build the probe argument list.
+set -- --baseline --iters "$ITERS"
+[ "$NO_BACKLOG" = 1 ] && set -- "$@" --no-backlog
+
+echo "starting probe: $PROBE $*"
+echo " (report -> $REPORT)"
+
+# ------------------------------------------------------------ start recording --
+# Run the probe in the background; capture everything it prints (setup notes,
+# the /proc/consoles dump, and the final verdict) into the report file.
+"$PROBE" "$@" > "$REPORT" 2>&1 &
+PROBE_PID=$!
+
+# Wait until the probe has finished setup and armed the kprobes. It prints
+# "running <N> iterations ..." at that point; poll for it. Bail out early if the
+# probe died during setup (its report then holds the FATAL reason).
+armed=0
+tries=0
+while [ $tries -lt 200 ]; do
+ if grep -q "running .* iterations" "$REPORT" 2>/dev/null; then
+ armed=1
+ break
+ fi
+ kill -0 "$PROBE_PID" 2>/dev/null || break
+ nap 0.1
+ tries=$((tries + 1))
+done
+
+if [ "$armed" != 1 ]; then
+ echo "" >&2
+ echo "WARN: probe did not reach the recording stage; see report below." >&2
+ wait "$PROBE_PID" 2>/dev/null
+ echo "==================== probe report ====================" >&2
+ cat "$REPORT" >&2
+ echo "======================================================" >&2
+ exit 1
+fi
+
+echo "probe armed; loading $MOD (iters=$KOITERS backlog=$BACKLOG) ..."
+
+# Raise console loglevel so the module's KERN_INFO in-window lines actually
+# reach the console and get flushed. Restored in cleanup / at the end.
+set_loglevel
+
+# ------------------------------------------------------------- fire in-window --
+# insmod fires KOITERS rendezvous on load; recorded now that the probe is armed.
+if ! insmod "$KO" iters="$KOITERS" backlog="$BACKLOG"; then
+ echo "WARN: insmod failed. Unsigned modules allowed? Already loaded?" >&2
+ echo " Check: dmesg | tail (vermagic mismatch shows here)." >&2
+fi
+
+# Keep firing until the probe's recording window closes (probe process exits).
+# This guarantees an in-window printk overlaps the protected region even if the
+# on-load fire happened to fall between rendezvous.
+fires=0
+while kill -0 "$PROBE_PID" 2>/dev/null; do
+ if [ -w "$FIRE" ]; then
+ echo 1 > "$FIRE" 2>/dev/null && fires=$((fires + 1))
+ fi
+ nap 0.2
+done
+echo "fired $fires extra batch(es) while recording."
+
+# --------------------------------------------------------------- report -------
+rmmod "$MOD" 2>/dev/null
+wait "$PROBE_PID" 2>/dev/null
+restore_loglevel
+trap - INT TERM
+
+echo ""
+echo "==================== probe report ===================="
+cat "$REPORT"
+echo "======================================================"
+echo ""
+echo "Look for 'flushes while PROTECTED' and the verdict line:"
+echo " REPRODUCED -> in-window legacy flush seen (pre-fix bug present)."
+echo " PASS -> no in-window flush (patched kernel, or stress missed)."
+exit 0
--
Tried many approaches but the one that triggered the wdog bite reliably when idle is:
adb wait-for-device && \
adb root && \
adb shell mkdir -p /data/local/tmp && \
adb push mcs-repro-run.sh mcs-printk-probe.sh mcs_repro.ko /data/local/tmp/ && \
adb shell chmod +x /data/local/tmp/mcs-repro-run.sh /data/local/tmp/mcs-printk-probe.sh && \
adb shell "cd /data/local/tmp && ./mcs-repro-run.sh --crash --flood 3000"
Thank you,
Aditya
^ permalink raw reply [flat|nested] 4+ messages in thread