mirror of https://lore.kernel.org/lkml/
 help / color / mirror / Atom feed
* [PATCH v2] stop_machine: Defer legacy console flushes while a CPU runs a stopper callback
@ 2026-09-10  3:53 Aditya Chillara
  2026-09-10  8:43 ` John Ogness
  2026-09-10 16:16 ` Bradley Morgan
  0 siblings, 2 replies; 4+ messages in thread
From: Aditya Chillara @ 2026-09-10  3:53 UTC (permalink / raw)
  To: Petr Mladek, Steven Rostedt, John Ogness, Sergey Senozhatsky
  Cc: linux-kernel, Aditya Chillara

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. 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.

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.

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

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.
---
Changes in v2:
- Use printk_deferred_enter/exit() to defer legacy console flushes instead
  of in_cpu_stop().
- Link to v1: https://patch.msgid.link/20260827-defer-legacy-console-write-on-multi_cpu_stop-v1-0-3b9f6bb4679f@oss.qualcomm.com
---
 kernel/stop_machine.c | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/kernel/stop_machine.c b/kernel/stop_machine.c
index d085ba1f4b44..31f7af41249f 100644
--- a/kernel/stop_machine.c
+++ b/kernel/stop_machine.c
@@ -507,7 +507,9 @@ static void cpu_stopper_thread(unsigned int cpu)
 		stopper->caller = work->caller;
 		stopper->fn = fn;
 		preempt_count_inc();
+		printk_deferred_enter();
 		ret = fn(arg);
+		printk_deferred_exit();
 		if (done) {
 			if (ret)
 				done->ret = ret;

---
base-commit: 77ae27fd98f3b548797c9f22c10ab5cf1c4ada53
change-id: 20260824-defer-legacy-console-write-on-multi_cpu_stop-d3ef6f6b150b

Best regards,
--  
Aditya Chillara <aditya.chillara@oss.qualcomm.com>


^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [PATCH v2] stop_machine: Defer legacy console flushes while a CPU runs a stopper callback
  2026-09-10  3:53 [PATCH v2] stop_machine: Defer legacy console flushes while a CPU runs a stopper callback Aditya Chillara
@ 2026-09-10  8:43 ` John Ogness
  2026-09-10 16:16 ` Bradley Morgan
  1 sibling, 0 replies; 4+ messages in thread
From: John Ogness @ 2026-09-10  8:43 UTC (permalink / raw)
  To: Aditya Chillara, Petr Mladek, Steven Rostedt, Sergey Senozhatsky
  Cc: linux-kernel, Aditya Chillara

On 2026-09-10, 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. 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.
>
> Signed-off-by: Aditya Chillara <aditya.chillara@oss.qualcomm.com>

Reviewed-by: John Ogness <john.ogness@linutronix.de>

> 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.

Note that with the new nbcon consoles, this will still happen if the CPU
is in an emergency state (WARN/panic), but that is the intended
behavior.

John

^ permalink raw reply	[flat|nested] 4+ messages in thread

* Re: [PATCH v2] stop_machine: Defer legacy console flushes while a CPU runs a stopper callback
  2026-09-10  3:53 [PATCH v2] stop_machine: Defer legacy console flushes while a CPU runs a stopper callback Aditya Chillara
  2026-09-10  8:43 ` John Ogness
@ 2026-09-10 16:16 ` Bradley Morgan
  2026-09-11 11:02   ` Aditya Chillara
  1 sibling, 1 reply; 4+ messages in thread
From: Bradley Morgan @ 2026-09-10 16:16 UTC (permalink / raw)
  To: aditya.chillara; +Cc: john.ogness, linux-kernel, pmladek, rostedt, senozhatsky

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?

>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?"

>
>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)


>---
>Changes in v2:
>- Use printk_deferred_enter/exit() to defer legacy console flushes instead
>  of in_cpu_stop().
>- Link to v1: https://patch.msgid.link/20260827-defer-legacy-console-write-on-multi_cpu_stop-v1-0-3b9f6bb4679f@oss.qualcomm.com
>---
> kernel/stop_machine.c | 2 ++
> 1 file changed, 2 insertions(+)
>
>diff --git a/kernel/stop_machine.c b/kernel/stop_machine.c
>index d085ba1f4b44..31f7af41249f 100644
>--- a/kernel/stop_machine.c
>+++ b/kernel/stop_machine.c
>@@ -507,7 +507,9 @@ static void cpu_stopper_thread(unsigned int cpu)
> 		stopper->caller = work->caller;
> 		stopper->fn = fn;
> 		preempt_count_inc();
>+		printk_deferred_enter();
> 		ret = fn(arg);
>+		printk_deferred_exit();

Clean! :)

> 		if (done) {
> 			if (ret)
> 				done->ret = ret;
>
>---
>base-commit: 77ae27fd98f3b548797c9f22c10ab5cf1c4ada53
>change-id: 20260824-defer-legacy-console-write-on-multi_cpu_stop-d3ef6f6b150b
>
>Best regards,
>--  
>Aditya Chillara <aditya.chillara@oss.qualcomm.com>
>
>
>

--- Thanks!
https://lore.kernel.org/all/EE579805-42F2-4C58-B752-F28779EEB717@grrlz.net/

^ permalink raw reply	[flat|nested] 4+ messages in thread

* 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

end of thread, other threads:[~2026-09-11 11:02 UTC | newest]

Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2026-09-10  3:53 [PATCH v2] stop_machine: Defer legacy console flushes while a CPU runs a stopper callback Aditya Chillara
2026-09-10  8:43 ` John Ogness
2026-09-10 16:16 ` Bradley Morgan
2026-09-11 11:02   ` Aditya Chillara

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox

all inboxes | Powered by JetHome®