On Tue, Jan 03, 2023 at 06:24:23PM +0000, Joel Fernandes wrote: > On Tue, Jan 03, 2023 at 10:04:04AM -0800, Paul E. McKenney wrote: > > On Mon, Jan 02, 2023 at 08:43:10AM -0800, Davidlohr Bueso wrote: > > > On Sun, 01 Jan 2023, Joel Fernandes (Google) wrote: > > > > > > > During shutdown of rcutorture, the shutdown thread in > > > > rcu_torture_cleanup() calls torture_cleanup_begin() which sets fullstop > > > > to FULLSTOP_RMMOD. This is enough to cause the rcutorture threads for > > > > readers and fakewriters to breakout of their main while loop and start > > > > shutting down. > > > > > > > > Once out of their main loop, they then call torture_kthread_stopping() > > > > which in turn waits for kthread_stop() to be called, however > > > > rcu_torture_cleanup() has not even called kthread_stop() on those > > > > threads yet, it does that a bit later. However, before it gets a chance > > > > to do so, torture_kthread_stopping() calls > > > > schedule_timeout_interruptible(1) in a tight loop. Tracing confirmed > > > > this makes the timer softirq constantly execute timer callbacks, while > > > > never returning back to the softirq exit path and is essentially "locked > > > > up" because of that. If the softirq preempts the shutdown thread, > > > > kthread_stop() may never be called. > > > > > > > > This commit improves the situation dramatically, by increasing timeout > > > > passed to schedule_timeout_interruptible() 1/20th of a second. This > > > > causes the timer softirq to not lock up a CPU and everything works fine. > > > > Testing has shown 100 runs of TREE07 passing reliably, which was not the > > > > case before because of RCU stalls. > > > > > > > > Cc: Paul McKenney <paulmck@xxxxxxxxxx> > > > > Cc: Frederic Weisbecker <fweisbec@xxxxxxxxx> > > > > Cc: Zhouyi Zhou <zhouzhouyi@xxxxxxxxx> > > > > Cc: <stable@xxxxxxxxxxxxxxx> # 6.0.x > > > > Signed-off-by: Joel Fernandes (Google) <joel@xxxxxxxxxxxxxxxxx> > > > > > > Reviewed-by: Davidlohr Bueso <dave@xxxxxxxxxxxx> > > > > Queued for further review and testing, thank you all! > > > > One thing still puzzles me. Assuming HZ=1000 and given 16 CPUs, each > > timer hander must have consumed many tens of microseconds in order > > to keep the system busy, which seems a bit longer than it should be. > > Or am I underestimating the number of tasks involved? > > Here are the traces between successive calls to process_timeout() which is the timer callback handler: > > [ 1320.444210] <idle>-0 0dNs.. 314229620us : __run_timers: Calling timerfn 5: process_timeout > [ 1320.444215] <idle>-0 0dNs.. 314229620us : sched_waking: comm=rcu_torture_fak pid=145 prio=139 target_cpu=008 > [ 1320.463393] <idle>-0 7d.... 314229655us : sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_torture_wri next_pid=144 next_prio=120 > [ 1320.478870] rcu_tort-144 7d.... 314229658us : sched_switch: prev_comm=rcu_torture_wri prev_pid=144 prev_prio=120 prev_state=D ==> next_comm=swapper/7 next_pid=0 next_prio=120 > [ 1320.494324] <idle>-0 0dNs.. 314229738us : __run_timers: Calling timerfn 6: process_timeout > > It appears the time delta in the above occurrence is 118 micro seconds > between 2 timer callbacks. It does appear to be doing a cross-CPU wake up. > Maybe that adds to the long time? > > Here are the full logs with traces (in case it helps, search for "=D" for the > D-state sched_switch event before the "panic now" trace happens): > http://box.joelfernandes.org:9080/job/rcutorture_stable/job/linux-6.0.y/26/artifact/tools/testing/selftests/rcutorture/res/2022.12.31-23.04.42/TREE07.2/console.log 118 microseconds would do it! Still seems excessive to me, but what do I know? Thanx, Paul
