Re: [PATCH v7 2/2] clocksource: add J-Core timer/clocksource driver
From: Rich Felker <dalias@libc.org>
Date: 2016-10-08 01:32:41
Also in:
linux-sh, lkml
On Fri, Sep 30, 2016 at 03:15:11PM +0200, Thomas Gleixner wrote:
On Tue, 27 Sep 2016, Rich Felker wrote:quoted
I've managed to get a trace with a stall. I'm not sure what the best way to share the full thing is, since it's large, but here are the potentially interesting parts.Upload it somewhere.quoted
The first is a big time gap with no events, from 82.446093 to 109.852709:quoted
<idle>-0 [001] d.h. 82.443398: irq_handler_entry: irq=16 name=jcore_pit <idle>-0 [001] d.h. 82.443573: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d.h. 82.443689: hrtimer_expire_entry: hrtimer=109f449c function=tick_sched_timer now=82356112320Tick timer expiresquoted
<idle>-0 [001] d.h. 82.443911: softirq_raise: vec=1 [action=TIMER] <idle>-0 [001] d.h. 82.444089: softirq_raise: vec=9 [action=RCU] <idle>-0 [001] d.h. 82.444306: softirq_raise: vec=7 [action=SCHED]Raises softirqsquoted
<idle>-0 [001] d.h. 82.444448: hrtimer_expire_exit: hrtimer=109f449c <idle>-0 [001] d.h. 82.444592: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=82360000000 softexpires=82360000000Rearms the next periodquoted
<idle>-0 [001] d.h. 82.444821: irq_handler_exit: irq=16 ret=handled <idle>-0 [001] ..s. 82.445034: softirq_entry: vec=1 [action=TIMER] <idle>-0 [001] ..s. 82.445222: softirq_exit: vec=1 [action=TIMER] <idle>-0 [001] ..s. 82.445341: softirq_entry: vec=7 [action=SCHED] <idle>-0 [001] ..s. 82.445745: softirq_exit: vec=7 [action=SCHED] <idle>-0 [001] ..s. 82.445880: softirq_entry: vec=9 [action=RCU] <idle>-0 [001] ..s. 82.446093: softirq_exit: vec=9 [action=RCU]Softirqs done and the machine vanishes into lala land .... And now after that gap we have a cancel/start on CPU 0quoted
<idle>-0 [000] dn.. 109.852709: hrtimer_cancel: hrtimer=109e949c <idle>-0 [000] dn.. 109.853043: hrtimer_start: hrtimer=109e949c function=tick_sched_timer expires=109770000000 softexpires=109770000000quoted
sh-388 [000] d.h. 109.855851: irq_handler_entry: irq=18 name=uartlite sh-388 [000] d.h. 109.856751: irq_handler_exit: irq=18 ret=handled sh-388 [000] d.h. 109.857264: irq_handler_entry: irq=18 name=uartlite sh-388 [000] d.h. 109.857458: irq_handler_exit: irq=18 ret=unhandled <idle>-0 [001] d.h. 109.857684: irq_handler_entry: irq=16 name=jcore_pit <idle>-0 [001] d.h. 109.857934: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d.h. 109.858087: hrtimer_expire_entry: hrtimer=109f449c function=tick_sched_timer now=109770452820And this expiry happens on CPU 1, but the expiry time looks like the one which got armed on CPU 0 above !?!?!quoted
<idle>-0 [001] d.h. 109.858639: softirq_raise: vec=1 [action=TIMER] <idle>-0 [001] d.h. 109.858839: softirq_raise: vec=9 [action=RCU] <idle>-0 [001] d.h. 109.859097: softirq_raise: vec=7 [action=SCHED] <idle>-0 [001] d.h. 109.859282: hrtimer_expire_exit: hrtimer=109f449c <idle>-0 [001] d.h. 109.859428: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=109780000000 softexpires=109780000000 <idle>-0 [001] d.h. 109.859637: irq_handler_exit: irq=16 ret=handled <idle>-0 [001] ..s. 109.859806: softirq_entry: vec=1 [action=TIMER] <idle>-0 [001] ..s. 109.859984: softirq_exit: vec=1 [action=TIMER] <idle>-0 [001] ..s. 109.860098: softirq_entry: vec=7 [action=SCHED] <idle>-0 [001] ..s. 109.860533: softirq_exit: vec=7 [action=SCHED] <idle>-0 [001] ..s. 109.860663: softirq_entry: vec=9 [action=RCU] <idle>-0 [001] .ns. 109.861424: softirq_exit: vec=9 [action=RCU] sh-388 [000] d.h. 109.861831: irq_handler_entry: irq=16 name=jcore_pit sh-388 [000] d.h. 109.862071: hrtimer_cancel: hrtimer=109e949c rcu_sched-7 [001] .... 109.862141: timer_init: timer=160a9eb0 sh-388 [000] d.h. 109.862233: hrtimer_expire_entry: hrtimer=109e949c function=tick_sched_timer now=109774586740And CPU0 has it's timer firing 4.5ms late .....quoted
rcu_sched-7 [001] d... 109.862317: timer_start: timer=160a9eb0 function=process_timeout expires=4294948275 [timeout=1] flags=0x00000001 However no stall message appeared on the console here, and I suspect it might have just been a gap in event recording because it doesn't look terribly suspicious. At first I thought (and discussed withWell. If there are gaps in the traces then decoding this is going to be a nightmare.quoted
Daniel off-list) that the hrtimer_cancel at the end of the long gap might have been spinning for the whole time, but this does not match the behavior of the stalls I'm observing waith tracing off; by hookingWhy would it spinning? There is no way that the callback of the tick timer runs when cancel is called. It's cpu local.....quoted
up LED output in the hrtimer_cancel code paths, I see rapid bursts of successful hrtimer_cancel (no repeated hrtimer_try_to_cancel looping) leading up to the rcu_sched stall message. That matches with what I'm seeing later in the event log, between 109s and 132s where the stall occurred: <idle>-0 [000] d.h. 109.946127: irq_handler_entry: irq=16 name=jcore_pit <idle>-0 [000] d.h. 109.946339: hrtimer_cancel: hrtimer=109e949c <idle>-0 [000] d.h. 109.946486: hrtimer_expire_entry: hrtimer=109e949c function=tick_sched_timer now=109858865160 <idle>-0 [000] d.h. 109.946714: softirq_raise: vec=1 [action=TIMER] <idle>-0 [000] d.h. 109.946918: softirq_raise: vec=9 [action=RCU] <idle>-0 [000] d.h. 109.947193: softirq_raise: vec=7 [action=SCHED] <idle>-0 [000] d.h. 109.947364: hrtimer_expire_exit: hrtimer=109e949c <idle>-0 [000] d.h. 109.947498: hrtimer_start: hrtimer=109e949c function=tick_sched_timer expires=109860000000 softexpires=109860000000 <idle>-0 [000] d.h. 109.947736: hrtimer_cancel: hrtimer=109e949c <idle>-0 [000] d.h. 109.947887: hrtimer_expire_entry: hrtimer=109e949c function=tick_sched_timer now=109860266000 <idle>-0 [000] d.h. 109.948394: softirq_raise: vec=1 [action=TIMER] <idle>-0 [000] d.h. 109.948600: softirq_raise: vec=9 [action=RCU] <idle>-0 [000] d.h. 109.948870: softirq_raise: vec=7 [action=SCHED] <idle>-0 [000] d.h. 109.949036: hrtimer_expire_exit: hrtimer=109e949c <idle>-0 [000] d.h. 109.949170: hrtimer_start: hrtimer=109e949c function=tick_sched_timer expires=109870000000 softexpires=109870000000 <idle>-0 [000] d.h. 109.949389: irq_handler_exit: irq=16 ret=handled <idle>-0 [000] ..s. 109.949585: softirq_entry: vec=1 [action=TIMER] <idle>-0 [000] ..s. 109.949785: softirq_exit: vec=1 [action=TIMER] <idle>-0 [000] ..s. 109.949902: softirq_entry: vec=7 [action=SCHED] <idle>-0 [000] ..s. 109.950347: softirq_exit: vec=7 [action=SCHED] <idle>-0 [000] ..s. 109.950472: softirq_entry: vec=9 [action=RCU] <idle>-0 [000] ..s. 109.951089: softirq_exit: vec=9 [action=RCU] <idle>-0 [001] dn.. 109.951213: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] dn.. 109.951476: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=109870000000 softexpires=109870000000 rcu_sched-7 [001] d... 109.952030: timer_cancel: timer=160a9eb0 rcu_sched-7 [001] .... 109.952478: timer_init: timer=160a9eb0 rcu_sched-7 [001] d... 109.952633: timer_start: timer=160a9eb0 function=process_timeout expires=4294948284 [timeout=1] flags=0x00000001So that should kick rcu_sched-7 in 10ms, latest 20ms from now and CPU1 goes into a NOHZ idle sleep.quoted
<idle>-0 [001] d... 109.953436: tick_stop: success=1 dependency=NONE <idle>-0 [001] d... 109.953617: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d... 109.953818: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=109880000000 softexpires=109880000000which is (using the 0.087621us delta between the trace clock and clock MONO) at: 109.880 + 0.087621 = 109.968 Which is about correct as we expect the RCU timer to fire at: 109.952633 + 0.01 = 109.963633 or latest at 109.952633 + 0.02 = 109.983633 There is another caveat. That nohz stuff can queue the rcu timer on CPU0, which it did not because:quoted
rcu_sched-7 [001] d... 109.952633: timer_start: timer=160a9eb0 function=process_timeout expires=4294948284 [timeout=1] flags=0x00000001The CPU nr encoded in flags is: 1 Now we cancel and restart the timer w/o seing the interrupt expiring it. And that expiry should have happened at 109.968000 !?!quoted
<idle>-0 [001] d... 109.968225: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d... 109.968526: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=109890000000 softexpires=109890000000So this advances the next tick even further out. And CPU 0 sets the timer to the exact smae value:quoted
<idle>-0 [000] d.h. 109.969104: hrtimer_start: hrtimer=109e949c function=tick_sched_timer expires=109890000000 softexpires=109890000000quoted
<idle>-0 [000] d.h. 109.977690: irq_handler_entry: irq=16 name=jcore_pit <idle>-0 [000] d.h. 109.977911: hrtimer_cancel: hrtimer=109e949c <idle>-0 [000] d.h. 109.978053: hrtimer_expire_entry: hrtimer=109e949c function=tick_sched_timer now=109890434160Which expires here. And CPU1 instead of getting an interrupt and expiring the timer does the cancel/restart to the next jiffie again:quoted
<idle>-0 [001] d... 109.978206: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d... 109.978495: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=109900000000 softexpires=109900000000And this repeats;quoted
<idle>-0 [000] d.h. 109.987726: irq_handler_entry: irq=16 name=jcore_pit <idle>-0 [000] d.h. 109.987954: hrtimer_cancel: hrtimer=109e949c <idle>-0 [000] d.h. 109.988095: hrtimer_expire_entry: hrtimer=109e949c function=tick_sched_timer now=109900474620quoted
<idle>-0 [001] d... 109.988243: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d... 109.988537: hrtimer_start: hrtimer=109f449c fun9cThere is something badly wrong here.quoted
<idle>-0 [000] ..s. 110.019443: softirq_entry: vec=1 [action=TIMER] <idle>-0 [000] ..s. 110.019617: softirq_exit: vec=1 [action=TIMER] <idle>-0 [000] ..s. 110.019730: softirq_entry: vec=7 [action=SCHED] <idle>-0 [000] ..s. 110.020174: softirq_exit: vec=7 [action=SCHED] <idle>-0 [000] d.h. 110.027674: irq_handler_entry: irq=16 name=jcore_pit The rcu_sched process does not run again after the tick_stop until 132s, and only a few RCU softirqs happen (all shown above). During this time, cpu1 has no interrupt activity and nothing in the trace except the above hrtimer_cancel/hrtimer_start pairs (not sure how they're happening without any interrupts).If you drop out of the arch idle into the core idle loop then you might end up with this. You want to add a few trace points or trace_printks() to the involved functions. tick_nohz_restart() tick_nohz_stop_sched_tick() tick_nohz_restart_sched_tick() and the idle code should be a good starting point.quoted
This pattern repeats until almost 131s, where cpu1 goes into a frenzy of hrtimer_cancel/start:It's not a frenzy. It's the same pattern as above. It arms the timer to the next tick, but that timer never ever fires. And it does that every tick .... Please put a tracepoint into your set_next_event() callback as well. SO this changes here:
Here is a full log with added printk's of a stall: http://sprunge.us/PgOZ The relevant excerpt where the stall begins is: rcu_sched-7 [000] d... 150.828744: timer_start: timer=1636feac function=process_timeout expires=4294952380 [timeout=1] flags=0x00000000 rcu_sched-7 [000] d... 150.828892: rcu_utilization: Start context switch rcu_sched-7 [000] d... 150.828988: rcu_grace_period: rcu_sched 51 cpuqs rcu_sched-7 [000] d... 150.829080: rcu_utilization: End context switch rcu_sched-7 [000] d... 150.829230: sched_stat_runtime: comm=rcu_sched pid=7 runtime=2813820 [ns] vruntime=10018192393 [ns] rcu_sched-7 [000] d... 150.829496: sched_switch: prev_comm=rcu_sched prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120 <idle>-0 [000] d... 150.829698: __tick_nohz_idle_enter: can stop idle tick <idle>-0 [000] d... 150.829774: __tick_nohz_idle_enter: entering stop_sched_tick <idle>-0 [000] d... 150.830001: tick_stop: success=1 dependency=NONE <idle>-0 [000] d... 150.830127: hrtimer_cancel: hrtimer=109e949c <idle>-0 [000] d... 150.830380: jcore_pit_set_next_event: pit 109eccb0 0 set delta 82124660 en=4410000 cntr=75 throt=82124660 <idle>-0 [000] d... 150.830498: hrtimer_start: hrtimer=109e949c function=tick_sched_timer expires=150840000000 softexpires=150840000000 <idle>-0 [000] d... 150.830720: jcore_pit_set_next_event: pit 109eccb0 0 set delta 539823 en=4410000 cntr=34 throt=539823 <idle>-0 [000] d... 150.830822: __tick_nohz_idle_enter: returning from stop_sched_tick <idle>-0 [000] d... 150.830940: rcu_dyntick: Start 140000000000000 0 <idle>-0 [000] d... 150.831072: rcu_dyntick: End 0 1 <idle>-0 [000] d... 150.831165: cpu_idle: state=0 cpu_id=0 <idle>-0 [000] d... 150.831269: rcu_dyntick: Start 1 0 <idle>-0 [000] .... 150.831368: cpu_startup_entry: enabled irqs, spinning <idle>-0 [001] d... 150.831491: rcu_dyntick: End 0 1 <idle>-0 [001] d.h. 150.831704: irq_handler_entry: irq=16 name=jcore_pit <idle>-0 [001] d.h. 150.831855: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d.h. 150.831965: hrtimer_expire_entry: hrtimer=109f449c function=tick_sched_timer now=150830402668 <idle>-0 [001] d.h. 150.832075: tick_sched_do_timer: update jiffies via tick <idle>-0 [001] d.h. 150.832217: tick_do_update_jiffies64: finished do_timer(1) <idle>-0 [001] d.h. 150.832335: tick_do_update_jiffies64: finished updating jiffies <idle>-0 [001] d.h. 150.832462: softirq_raise: vec=1 [action=TIMER] <idle>-0 [001] d.h. 150.832566: rcu_utilization: Start scheduler-tick <idle>-0 [001] d.h. 150.832719: softirq_raise: vec=9 [action=RCU] <idle>-0 [001] d.h. 150.832811: rcu_utilization: End scheduler-tick <idle>-0 [001] d.h. 150.833012: softirq_raise: vec=7 [action=SCHED] <idle>-0 [001] d.h. 150.833146: hrtimer_expire_exit: hrtimer=109f449c <idle>-0 [001] d.h. 150.833244: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=150840000000 softexpires=150840000000 <idle>-0 [001] d.h. 150.833481: jcore_pit_set_next_event: pit 109f7cb0 1 set delta 402319 en=4410000 cntr=54 throt=402319 <idle>-0 [001] d.h. 150.833583: irq_handler_exit: irq=16 ret=handled <idle>-0 [001] ..s. 150.833735: softirq_entry: vec=1 [action=TIMER] <idle>-0 [001] ..s. 150.833869: softirq_exit: vec=1 [action=TIMER] <idle>-0 [001] ..s. 150.833959: softirq_entry: vec=7 [action=SCHED] <idle>-0 [001] ..s. 150.834298: softirq_exit: vec=7 [action=SCHED] <idle>-0 [001] ..s. 150.834398: softirq_entry: vec=9 [action=RCU] <idle>-0 [001] ..s. 150.834494: rcu_utilization: Start RCU core <idle>-0 [001] d.s. 150.834628: rcu_future_grace_period: rcu_sched 51 50 52 0 0 1 Startleaf <idle>-0 [001] d.s. 150.834738: rcu_future_grace_period: rcu_sched 51 50 52 0 0 1 Startedleaf <idle>-0 [001] d.s. 150.834839: rcu_grace_period: rcu_sched 50 AccWaitCB <idle>-0 [001] d.s. 150.834931: rcu_grace_period: rcu_sched 51 cpustart <idle>-0 [001] ..s. 150.835062: rcu_utilization: End RCU core <idle>-0 [001] ..s. 150.835156: softirq_exit: vec=9 [action=RCU] <idle>-0 [001] d... 150.835304: __tick_nohz_idle_enter: entering stop_sched_tick <idle>-0 [001] d... 150.835399: __tick_nohz_idle_enter: returning from stop_sched_tick <idle>-0 [001] d... 150.835497: rcu_dyntick: Start 1 0 <idle>-0 [001] d... 150.841525: rcu_dyntick: End 0 1 <idle>-0 [000] d... 150.841530: rcu_dyntick: End 0 1 <idle>-0 [000] d.s. 150.841724: tick_irq_enter: update jiffies via irq <idle>-0 [001] d.h. 150.841829: irq_handler_entry: irq=16 name=jcore_pit <idle>-0 [000] d.s. 150.841918: tick_do_update_jiffies64: finished do_timer(1) <idle>-0 [001] d.h. 150.842054: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d.h. 150.842218: hrtimer_expire_entry: hrtimer=109f449c function=tick_sched_timer now=150840579940 <idle>-0 [000] d.s. 150.842348: tick_do_update_jiffies64: finished updating jiffies <idle>-0 [001] d.h. 150.842382: tick_sched_do_timer: update jiffies via tick <idle>-0 [001] d.h. 150.842576: softirq_raise: vec=1 [action=TIMER] <idle>-0 [000] d... 150.842603: __tick_nohz_idle_enter: can stop idle tick <idle>-0 [000] d... 150.842700: __tick_nohz_idle_enter: entering stop_sched_tick <idle>-0 [001] d.h. 150.842718: rcu_utilization: Start scheduler-tick <idle>-0 [001] d.h. 150.842869: rcu_grace_period: rcu_sched 51 cpuqs <idle>-0 [000] d... 150.842937: tick_nohz_restart: restart <idle>-0 [001] d.h. 150.843051: softirq_raise: vec=9 [action=RCU] <idle>-0 [000] d... 150.843115: hrtimer_cancel: hrtimer=109e949c <idle>-0 [001] d.h. 150.843179: rcu_utilization: End scheduler-tick <idle>-0 [000] d... 150.843455: jcore_pit_set_next_event: pit 109eccb0 0 set delta 81472695 en=4410000 cntr=74 throt=81472695 <idle>-0 [001] d.h. 150.843467: softirq_raise: vec=7 [action=SCHED] <idle>-0 [001] d.h. 150.843651: hrtimer_expire_exit: hrtimer=109f449c <idle>-0 [000] d... 150.843698: hrtimer_start: hrtimer=109e949c function=tick_sched_timer expires=150850000000 softexpires=150850000000 <idle>-0 [001] d.h. 150.843789: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=150850000000 softexpires=150850000000 <idle>-0 [000] d... 150.844005: jcore_pit_set_next_event: pit 109eccb0 0 set delta 377377 en=4410000 cntr=42 throt=377377 <idle>-0 [001] d.h. 150.844115: jcore_pit_set_next_event: pit 109f7cb0 1 set delta 372809 en=4410000 cntr=66 throt=372809 <idle>-0 [000] d... 150.844132: tick_nohz_restart: return from restart <idle>-0 [000] d... 150.844240: __tick_nohz_idle_enter: returning from stop_sched_tick <idle>-0 [001] d.h. 150.844260: irq_handler_exit: irq=16 ret=handled <idle>-0 [000] d... 150.844377: rcu_dyntick: Start 1 0 <idle>-0 [001] ..s. 150.844473: softirq_entry: vec=1 [action=TIMER] <idle>-0 [001] ..s. 150.844612: softirq_exit: vec=1 [action=TIMER] <idle>-0 [001] ..s. 150.844701: softirq_entry: vec=7 [action=SCHED] <idle>-0 [001] ..s. 150.845036: softirq_exit: vec=7 [action=SCHED] <idle>-0 [001] ..s. 150.845136: softirq_entry: vec=9 [action=RCU] <idle>-0 [001] ..s. 150.845231: rcu_utilization: Start RCU core <idle>-0 [001] d.s. 150.845413: rcu_future_grace_period: rcu_sched 51 50 52 0 0 1 Startleaf <idle>-0 [001] d.s. 150.845518: rcu_future_grace_period: rcu_sched 51 50 52 0 0 1 Prestartleaf <idle>-0 [001] d.s. 150.845619: rcu_grace_period: rcu_sched 51 AccWaitCB <idle>-0 [001] d.s. 150.845723: rcu_quiescent_state_report: rcu_sched 51 2>1 0 0 1 0 <idle>-0 [001] ..s. 150.845857: rcu_utilization: End RCU core <idle>-0 [001] ..s. 150.845949: softirq_exit: vec=9 [action=RCU] <idle>-0 [001] d... 150.846098: __tick_nohz_idle_enter: entering stop_sched_tick <idle>-0 [001] d... 150.846192: __tick_nohz_idle_enter: returning from stop_sched_tick <idle>-0 [001] d... 150.846289: rcu_dyntick: Start 1 0 <idle>-0 [000] d... 150.851519: rcu_dyntick: End 0 1 <idle>-0 [001] d... 150.851522: rcu_dyntick: End 0 1 <idle>-0 [000] d.s. 150.851709: tick_irq_enter: update jiffies via irq <idle>-0 [001] d.h. 150.851824: irq_handler_entry: irq=16 name=jcore_pit <idle>-0 [000] d.s. 150.851900: tick_do_update_jiffies64: finished do_timer(1) <idle>-0 [001] d.h. 150.852047: hrtimer_cancel: hrtimer=109f449c <idle>-0 [001] d.h. 150.852213: hrtimer_expire_entry: hrtimer=109f449c function=tick_sched_timer now=150850574115 <idle>-0 [000] d.s. 150.852307: tick_do_update_jiffies64: finished updating jiffies <idle>-0 [001] d.h. 150.852375: tick_sched_do_timer: update jiffies via tick <idle>-0 [000] d... 150.852566: __tick_nohz_idle_enter: can stop idle tick <idle>-0 [001] d.h. 150.852578: softirq_raise: vec=1 [action=TIMER] <idle>-0 [000] d... 150.852660: __tick_nohz_idle_enter: entering stop_sched_tick <idle>-0 [001] d.h. 150.852723: rcu_utilization: Start scheduler-tick <idle>-0 [000] d... 150.852907: tick_nohz_restart: restart <idle>-0 [001] d.h. 150.852934: rcu_utilization: End scheduler-tick <idle>-0 [000] d... 150.853076: hrtimer_cancel: hrtimer=109e949c <idle>-0 [001] d.h. 150.853229: softirq_raise: vec=7 [action=SCHED] <idle>-0 [001] d.h. 150.853412: hrtimer_expire_exit: hrtimer=109f449c <idle>-0 [000] d... 150.853412: jcore_pit_set_next_event: pit 109eccb0 0 set delta 80974397 en=4410000 cntr=34 throt=80974397 <idle>-0 [001] d.h. 150.853549: hrtimer_start: hrtimer=109f449c function=tick_sched_timer expires=150860000000 softexpires=150860000000 <idle>-0 [000] d... 150.853645: hrtimer_start: hrtimer=109e949c function=tick_sched_timer expires=150860000000 softexpires=150860000000 <idle>-0 [001] d.h. 150.853879: jcore_pit_set_next_event: pit 109f7cb0 1 set delta 384360 en=4410000 cntr=66 throt=384360 <idle>-0 [000] d... 150.853941: jcore_pit_set_next_event: pit 109eccb0 0 set delta 380089 en=4410000 cntr=42 throt=380089 <idle>-0 [001] d.h. 150.854024: irq_handler_exit: irq=16 ret=handled <idle>-0 [000] d... 150.854082: tick_nohz_restart: return from restart <idle>-0 [000] d... 150.854186: __tick_nohz_idle_enter: returning from stop_sched_tick <idle>-0 [001] ..s. 150.854235: softirq_entry: vec=1 [action=TIMER] <idle>-0 [000] d... 150.854325: rcu_dyntick: Start 1 0 <idle>-0 [001] ..s. 150.854426: softirq_exit: vec=1 [action=TIMER] <idle>-0 [001] ..s. 150.854520: softirq_entry: vec=7 [action=SCHED] <idle>-0 [001] ..s. 150.854861: softirq_exit: vec=7 [action=SCHED] <idle>-0 [001] d... 150.855017: __tick_nohz_idle_enter: entering stop_sched_tick <idle>-0 [001] d... 150.855111: __tick_nohz_idle_enter: returning from stop_sched_tick <idle>-0 [001] d... 150.855208: rcu_dyntick: Start 1 0 <idle>-0 [000] d... 150.861516: rcu_dyntick: End 0 1 <idle>-0 [001] d... 150.861523: rcu_dyntick: End 0 1 <idle>-0 [000] d.s. 150.861703: tick_irq_enter: update jiffies via irq If I'm not mistaken, the bug is in tick_nohz_restart. According to the comment, it forwards the timer to take place one jiffy in the future, whereas one of its callers, tick_nohz_stop_sched_tick, expects it to "prod the hardware into firing an interrupt". That's not going to happen right away (as needed to get proper timing), and not going to happen at all if the idle loop keeps breaking out and forwarding the timer over and over again. Before commit 0ff53d09642204c648424def0caa9117e7a3caaf ("tick: sched: Force tick interrupt and get rid of softirq magic"), a timer softirq was always raised, which seems to have made it impossible to get into this situation. Adding back the raise_softirq_irqoff(TIMER_SOFTIRQ) seems to make the problem go away -- with that change, my "rcu_sched is stalled in swait" LED only lights briefly. But it's clearly not the right fix; the interrupt load with this change is comparable to periodic-tick. FWIW I also spent a good deal of time exploring the possibility of a hardware problem, but couldn't find any. The timer interrupt is firing when it's programmed to; the kernel is just repeatedly reprogramming it to fire in the future. Rich