Re: [PATCH sched/core] sched/rt: Fix RT_PUSH_IPI soft lockup loop

[Tejun Heo <tj@kernel.org>]

Hello,

Capturing this on the actual production hosts is awkward. It requires
a fleet with a particular management operation in flight, and while
the aggregate occurrence rate is reliable, which specific machine
hits it isn't predictable, so I haven't been able to catch one with
tracing on.

Production context: hosts serve live network traffic and storage IO.
CPU util before lockup is moderate (~30-40% steady state), but the
moment-to-moment softirq work is bursty - traffic patterns, IO
completions, plus the PSI poll triggers that source the migratable
psimon. Once softirq processing falls behind on a CPU, work piles
up. With the prio-bail-without-clearing-overload path, the IPI
storm forms on top and amplifies the slowdown.

So, here's a capture from a synthetic reproducer that I think
models the dynamic and reaches the same end state.

Test box, 192 CPUs, kernel without the fix:

- Per-target hrtimer (HRTIMER_MODE_REL_PINNED_HARD) fires every
  750us. Each fire schedules one tasklet round-robin from a pool
  of 20k distinct tasklets. Each tasklet body is a 500us cpu_relax
  loop, standing in for "process one item of softirq work".

- Storm driver: 190 SCHED_FIFO-50 nanosleep loops on non-target
  CPUs drive tell_cpu_to_push from balance_rt. Two synthetic
  psimon-shaped kthreads (FIFO 1) bound to the targets to pin
  them into rto_mask.

Baseline (no storm helpers): ~85% softirq util, no lockup, runs
indefinitely. The reproducer's baseline is higher than production -
my guess is we need to scrape up against capacity to grow a backlog
with the fixed-shape workload here, while production gets the same
effect from bursty arrivals during brief slowdowns.

With the storm: walker IPI overhead stretches each tasklet body
from 500us to ~1.1ms. Service rate drops below arrival, backlog
grows ~430/s. After ~46s, one tasklet_action_common snapshot has
~20k tasklets which it processes serially in BH-disabled softirq
context. That's ~22s uninterruptible, watchdog fires.

Six soft-lockups in a 120s run:

  [61125.38] BUG: soft lockup - CPU#95 stuck for 22s! [kworker/95:0]
  [61145.38] BUG: soft lockup - CPU#47 stuck for 45s! [migration/47]
  [61173.38] BUG: soft lockup - CPU#47 stuck for 71s! [migration/47]
  [61197.38] BUG: soft lockup - CPU#95 stuck for 22s! [migration/95]
  [61209.38] BUG: soft lockup - CPU#47 stuck for 21s! [kworker/47:1]
  [61225.38] BUG: soft lockup - CPU#95 stuck for 48s! [migration/95]

Stack at fire:

  rt_storm_wedge_fn+0x22/0xe0
  tasklet_action_common+0x100/0x2b0
  handle_softirqs+0xbe/0x280
  __irq_exit_rcu+0x47/0x100
  sysvec_apic_timer_interrupt+0x3a/0x80     <- watchdog hrtimer
  asm_sysvec_apic_timer_interrupt+0x16/0x20
  RIP: 0033:0x...     <- user task (rt_storm_hog)

Trace captured with your event list plus IPI:

  -e sched_switch -e sched_waking -e irq -e workqueue -e ipi
  -e irq_vectors:call_function_single_entry/exit
  -e irq_vectors:irq_work_entry/exit
  -e irq_vectors:reschedule_entry/exit
  -e irq_vectors:local_timer_entry/exit

Sliced to a 17s window around the first RCU stall + first
soft-lockup, filtered to CPUs 47 and 95, gzipped text (~11MB):

  https://drive.google.com/file/d/11AN6dyvOWiZLVNEEuVtQieRyAxJYbCbt/view?usp=sharing

Thanks.

--
tejun