On Sat, Dec 31, 2022 at 04:18:40PM +0000, Joel Fernandes wrote: > On Sat, Dec 31, 2022 at 4:16 PM Joel Fernandes <joel@xxxxxxxxxxxxxxxxx> wrote: > > > > On Sat, Dec 31, 2022 at 4:07 PM Paul E. McKenney <paulmck@xxxxxxxxxx> wrote: > > > > > > On Sat, Dec 31, 2022 at 12:28:10AM -0500, Joel Fernandes wrote: > > > > On Fri, Dec 30, 2022 at 9:14 PM Paul E. McKenney <paulmck@xxxxxxxxxx> wrote: > > > > > > > > > > On Fri, Dec 30, 2022 at 08:42:24PM -0500, Joel Fernandes wrote: > > > > > > Hello, > > > > > > > > > > > > I have been firefighting a hang on 6.0.y stable kernels with > > > > > > rcutorture. It happens mostly consistently when TREE07 is shutting > > > > > > down. > > > > > > > > > > > > It appears that the RCU torture threads are attempted to stop but the > > > > > > shutdown thread, but are constantly awakened by a timer softirq > > > > > > handler in ksoftirqd context. When they wake up, they immediately goto > > > > > > sleep in uninterruptible state until the next time a timer handler > > > > > > wakes them up. It appears the timer softirq is long enough to cause > > > > > > RCU stalls and I see it calling 100s of timer function handlers > > > > > > (call_timer_fn). > > > > > > > > > > > > I am doing some more investigation with trace_printk(s): > > > > > > https://git.kernel.org/pub/scm/linux/kernel/git/jfern/linux.git/commit/?h=stable/trace-hang-6.0.y&id=b779b1e92c97f29333a282ee8f548da02f64de2b > > > > > > > > > > > > Regarding the timer handlers, I was wondering if it is possible that a > > > > > > large number of timer handlers constantly queued can cause RCU stalls > > > > > > due to the timer softirq taking a very long time. That certainly > > > > > > appears to be the case here. Shouldn't the timer softirq also do > > > > > > rcu_softirq_qs() similar to the ksoftirq loop, in case there are too > > > > > > many of them? > > > > > > > > > > That is certainly a good thing to try! > > > > > > > > I am trying something like this just for testing, let's see what happens ;-) > > > > > > > > @@ -1788,9 +1796,14 @@ static inline void __run_timers(struct timer_base *base) > > > > > > > > while (levels--) > > > > expire_timers(base, heads + levels); > > > > > > Might you need to put it inside the body of this "while" loop? > > > > I could but even doing the below did not help. Do you see any reason > > putting inside the loop helps? Let me know. > > > > > > + rcu_softirq_qs(); > > > > } > > > > > > > > I guess I am also wondering why the rcu reader does not stop queuing > > > > timers. It is doing schedule_timeout_interruptible() constantly even > > > > though the test is being stopped. > > > > > > As in it is doing schedule_timeout_interruptible() in a loop that does > > > not check torture_must_stop()? That would be bad unless there is some > > > reason the loop cannot just stop. But if the loop cannot just stop, > > > that leads me to believe that there is a bug elsewhere. After all, given > > > that the test is ending, why shouldn't all the loops be able to just stop? > > > > Sorry I meant uninterruptible sleep. So > > schedule_timeout_uninterruptible(). But I still cannot nail where in > > the torture test it is coming from. Now I put a trace_dump_stack() > > directly in the schedule loop() and I am hoping it will show: > > > > diff --git a/kernel/sched/core.c b/kernel/sched/core.c > > index c2bb0cd4225d5..d79bc3b91818a 100644 > > --- a/kernel/sched/core.c > > +++ b/kernel/sched/core.c > > @@ -6390,6 +6390,8 @@ pick_next_task(struct rq *rq, struct task_struct > > *prev, struct rq_flags *rf) > > * > > * WARNING: must be called with preemption disabled! > > */ > > +static int rcu_tort_ds; > > + > > static void __sched notrace __schedule(unsigned int sched_mode) > > { > > struct task_struct *prev, *next; > > @@ -6452,6 +6454,11 @@ static void __sched notrace __schedule(unsigned > > int sched_mode) > > if (prev->sched_contributes_to_load) > > rq->nr_uninterruptible++; > > + // Dump stack for uninterruptible every 10 stacks. > > + if (prev_state & TASK_UNINTERRUPTIBLE && ((rcu_tort_ds++ % 10) == 0)) { > > + trace_dump_stack(0); > > + } > > + > > /* > > Ok found the uninterruptible sleep, it is coming from here: > > [ 1359.592979] rcu_tort-160 15d.... 346177086us : <stack trace> > [ 1359.592979] => __ftrace_trace_stack > [ 1359.592979] => __schedule > [ 1359.592979] => schedule > [ 1359.592979] => schedule_timeout > [ 1359.592979] => torture_kthread_stopping > [ 1359.592979] => rcu_torture_reader > [ 1359.592979] => kthread > [ 1359.592979] => ret_from_fork > > Thoughts? That is door #3, or a variation on it. That rcu_torture_reader() task is waiting to be stopped in torture_kthread_stopping(). The next question is "why isn't rcu_torture_cleanup() making it to the 'if (reader_tasks)' code that stops the readers?" Getting a stack trace of the task executing rcu_torture_cleanup() would likely be helpful. Or just check for the console-log messages that it already emits. These look like "Stopping rcu_torture_writer task". Thanx, Paul
