From: "Paul E. McKenney" <paulmck@kernel.org>
To: Joel Fernandes <joel@joelfernandes.org>
Cc: Frederic Weisbecker <frederic@kernel.org>, rcu@vger.kernel.org
Subject: Re: [BUG] Random intermittent boost failures (Was Re: [BUG] TREE04..)
Date: Mon, 11 Sep 2023 01:16:21 -0700 [thread overview]
Message-ID: <1f12ffe6-4cb0-4364-8c4c-3393ca5368c2@paulmck-laptop> (raw)
In-Reply-To: <20230911022725.GA2542634@google.com>
On Mon, Sep 11, 2023 at 02:27:25AM +0000, Joel Fernandes wrote:
> On Sun, Sep 10, 2023 at 07:37:13PM -0400, Joel Fernandes wrote:
> > On Sun, Sep 10, 2023 at 5:16 PM Paul E. McKenney <paulmck@kernel.org> wrote:
> > >
> > > On Sun, Sep 10, 2023 at 08:14:45PM +0000, Joel Fernandes wrote:
> > [...]
> > > > > I have been running into another intermittent one as well which
> > > > > is the boost failure and that happens once in 10-15 runs or so.
> > > > >
> > > > > I was thinking of running the following configuration on an automated
> > > > > regular basis to at least provide a better clue on the lucky run that
> > > > > catches an issue. But then the issue is it would change timing enough
> > > > > to maybe hide bugs. I could also make it submit logs automatically to
> > > > > the list on such occurrences, but one step at a time and all that. I
> > > > > do need to add (hopefully less noisy) tick/timer related trace events.
> > > > >
> > > > > # Define the bootargs array
> > > > > bootargs=(
> > > > > "ftrace_dump_on_oops"
> > > > > "panic_on_warn=1"
> > > > > "sysctl.kernel.panic_on_rcu_stall=1"
> > > > > "sysctl.kernel.max_rcu_stall_to_panic=1"
> > > > > "trace_buf_size=10K"
> > > > > "traceoff_on_warning=1"
> > > > > "panic_print=0x1f" # To dump held locks, mem and other info.
> > > > > )
> > > > > # Define the trace events array passed to bootargs.
> > > > > trace_events=(
> > > > > "sched:sched_switch"
> > > > > "sched:sched_waking"
> > > > > "rcu:rcu_callback"
> > > > > "rcu:rcu_fqs"
> > > > > "rcu:rcu_quiescent_state_report"
> > > > > "rcu:rcu_grace_period"
> > > > > )
> > > >
> > > > So some insight on this boost failure. Just before the boost failures are
> > > > reported, I see the migration thread interferring with the rcu_preempt thread
> > > > (aka GP kthread). See trace below. Of note is that the rcu_preempt thread is
> > > > runnable while context switching, which means its execution is interferred.
> > > > The rcu_preempt thread is at RT prio 2 as can be seen.
> > > >
> > > > So some open-ended questions: what exactly does the migration thread want,
> > > > this is something related to CPU hotplug? And if the migration thread had to
> > > > run, why did the rcu_preempt thread not get pushed to another CPU by the
> > > > scheduler? We have 16 vCPUs for this test.
> > >
> > > Maybe we need a cpus_read_lock() before doing a given boost-test interval
> > > and a cpus_read_unlock() after finishing one? But much depends on
> > > exactly what is starting those migration threads.
> >
> > But in the field, a real RT task can preempt a reader without doing
> > cpus_read_lock() and may run into a similar boost issue?
The sysctl_sched_rt_runtime should prevent a livelock in most
configurations. Here, rcutorture explicitly disables this.
> > > Then again, TREE03 is pretty aggressive about doing CPU hotplug.
> >
> > Ok. I put a trace_printk() in the stopper thread to see what the
> > ->fn() is. I'm doing another run to see what falls out.
>
> I think I am getting somewhere, It looks like the migration thread tries to
> push the task out due to __balance_push_cpu_stop. Clearly it fails because
> the rcu_preempt task is still on CPU 3. And the whole thing is live locked
> retrying the same.
>
> I am not sure if the migration thread is trying to migrate rcu_preempt
> because the CPU is going down or because a higher priority RT task is
> running.
>
> rcu_pree-13 3d..4. 2936723336us : sched_waking: comm=migration/3 pid=34 prio=0 target_cpu=003
> rcu_pree-13 3d..2. 2936723338us : sched_switch: prev_comm=rcu_preempt prev_pid=13 prev_prio=97 prev_state=R ==> next_comm=migration/3 next_pid=34 next_prio=0
> migratio-34 3..... 2936723341us : cpu_stopper_thread: cpu_stop: caller=balance_push+0xc9/0x150 fn=__balance_push_cpu_stop+0x0/0x1c0 on cpu 3
> migratio-34 3d..2. 2936723345us : sched_switch: prev_comm=migration/3 prev_pid=34 prev_prio=0 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
> <idle>-0 3d..2. 2936723676us : sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=13 next_prio=97
> rcu_pree-13 3d..4. 2936723678us : sched_waking: comm=migration/3 pid=34 prio=0 target_cpu=003
> rcu_pree-13 3d..2. 2936723680us : sched_switch: prev_comm=rcu_preempt prev_pid=13 prev_prio=97 prev_state=R ==> next_comm=migration/3 next_pid=34 next_prio=0
> migratio-34 3..... 2936723683us : cpu_stopper_thread: cpu_stop: caller=balance_push+0xc9/0x150 fn=__balance_push_cpu_stop+0x0/0x1c0 on cpu 3
>
> I am digging deeper to see why the rcu_preempt thread cannot be pushed out
> and then I'll also look at why is it being pushed out in the first place.
>
> At least I have a strong repro now running 5 instances of TREE03 in parallel
> for several hours.
Very good! Then why not boot with rcutorture.onoff_interval=0 and see if
the problem still occurs? If yes, then there is definitely some reason
other than CPU hotplug that makes this happen.
Thanx, Paul
next prev parent reply other threads:[~2023-09-11 8:16 UTC|newest]
Thread overview: 23+ messages / expand[flat|nested] mbox.gz Atom feed top
2023-09-10 20:14 [BUG] Random intermittent boost failures (Was Re: [BUG] TREE04..) Joel Fernandes
2023-09-10 21:16 ` Paul E. McKenney
2023-09-10 23:37 ` Joel Fernandes
2023-09-11 2:27 ` Joel Fernandes
2023-09-11 8:16 ` Paul E. McKenney [this message]
2023-09-11 13:17 ` Joel Fernandes
2023-09-11 13:49 ` Paul E. McKenney
2023-09-11 16:18 ` Joel Fernandes
2023-09-13 20:30 ` Joel Fernandes
2023-09-14 11:11 ` Paul E. McKenney
2023-09-14 13:13 ` Joel Fernandes
2023-09-14 15:23 ` Paul E. McKenney
2023-09-14 18:56 ` Joel Fernandes
2023-09-14 21:53 ` Joel Fernandes
2023-09-15 0:13 ` Joel Fernandes
2023-09-15 11:33 ` Joel Fernandes
2023-09-15 14:53 ` Paul E. McKenney
2023-09-15 16:37 ` Joel Fernandes
2023-09-15 16:57 ` Paul E. McKenney
2023-09-15 21:14 ` Joel Fernandes
2023-09-18 6:05 ` Paul E. McKenney
2023-09-15 14:48 ` Paul E. McKenney
2023-09-15 14:45 ` Paul E. McKenney
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=1f12ffe6-4cb0-4364-8c4c-3393ca5368c2@paulmck-laptop \
--to=paulmck@kernel.org \
--cc=frederic@kernel.org \
--cc=joel@joelfernandes.org \
--cc=rcu@vger.kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.