Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Message-ID: <8682b08c-347b-5547-60e0-013dcf1f8c93@joelfernandes.org>
Date:   Thu, 20 Jul 2023 15:32:35 -0400
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Thunderbird/102.13.0
Subject: Re: [BUG] Re: Linux 6.4.4
Content-Language: en-US
To:     paulmck@kernel.org
Cc:     Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        linux-kernel@vger.kernel.org, akpm@linux-foundation.org,
        torvalds@linux-foundation.org, stable@vger.kernel.org, lwn@lwn.net,
        jslaby@suse.cz, rcu@vger.kernel.org
References: <2023071940-suspect-ominous-4a6a@gregkh>
 <20230720132714.GA3726096@google.com>
 <2b8fc10b-785e-48b9-9a38-5c1af81f9578@paulmck-laptop>
 <CAEXW_YQO7OCdkXm_SBcPhAm8V8vMaF_5DQq7PbG9PZb7RFgA_g@mail.gmail.com>
 <f18e165c-9196-4b41-a202-82cfd5ac7f8b@paulmck-laptop>
From:   Joel Fernandes <joel@joelfernandes.org>
In-Reply-To: <f18e165c-9196-4b41-a202-82cfd5ac7f8b@paulmck-laptop>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit
Precedence: bulk

On 7/20/23 15:04, Paul E. McKenney wrote:
 > On Thu, Jul 20, 2023 at 12:31:13PM -0400, Joel Fernandes wrote:
 >> Hi Paul,
 >>
 >> On Thu, Jul 20, 2023 at 11:55 AM Paul E. McKenney <paulmck@kernel.org> wrote:
 >>>
 >>> On Thu, Jul 20, 2023 at 01:27:14PM +0000, Joel Fernandes wrote:
[...]
 >>>>
 >>>> So likely RCU boosting is failing:
 >>>>
 >>>> The full TREE03 splat:
 >>>> [   54.243588] ------------[ cut here ]------------
 >>>> [   54.244547] rcu-torture: rcu_torture_boost started
[...]
 >>>> [   54.300499] RIP: 0010:rcu_torture_stats_print+0x5b2/0x620
[...]
 >>>> [ 2169.481783] rcu_torture_writer: rtort_pipe_count: 9
 >>>>
 >>>> However, if we are to believe the '9', it appears the object did made it
 >>>> quite some till the end of the pipe array but not until the free pool.
 >>>
 >>> This is from this if/for statement, correct?
 >>>
 >>>                  stutter_waited = stutter_wait("rcu_torture_writer");
 >>>                  if (stutter_waited &&
 >>>                      !atomic_read(&rcu_fwd_cb_nodelay) &&
 >>>                      !cur_ops->slow_gps &&
 >>>                      !torture_must_stop() &&
 >>>                      boot_ended)
 >>>                          for (i = 0; i < ARRAY_SIZE(rcu_tortures); i++)
 >>>                                  if (list_empty(&rcu_tortures[i].rtort_free) &&
 >>>                                      rcu_access_pointer(rcu_torture_current) !=
 >>>                                      &rcu_tortures[i]) {
 >>>                                          tracing_off();
 >>>                                          show_rcu_gp_kthreads();
 >>>                                          WARN(1, "%s: rtort_pipe_count:
 >>>                                          rcu_ftrace_dump(DUMP_ALL);
 >>>                                  }
 >>
 >> Yes, that's right.
 >>
 >>> If so, this happens when there was a stutter wait, but RCU grace
 >>> periods failed to clear out the backlog during the several seconds that
 >>> rcutorture was forced idle.  This might be related to the RCU priority
 >>> boosting failure, in which a preempted reader persisted across the
 >>> stutter interval.
 >>
 >> When RCU is operating normally, shouldn't the check
 >> "(list_empty(&rcu_tortures[i].rtort_free)" not run until the preempted
 >> reader unblocks and exits its RCU read-side critical section?
 >
 > Yes, but not just "until", but rather "long after".  If RCU is doing
 > grace periods correctly, an active reader on a given rcu_tortures[]
 > element will prevent .rtort_pipe_count from exceeding the value 2.

Ah ok, so the rtort_pipe_count being 9 is a sign RCU isn't making progress thus 
making it absent from the free list.

 >
 > The element will not be put on a list until .rtort_pipe_count is equal
 > to RCU_TORTURE_PIPE_LEN, which is 10.
 >
 > This warning usually appears when something is holding up the grace-period
 > kthread.  Historically, this has included deadlocks, missed timers,
 > and whatever else can prevent the grace-period kthread from running.

Makes sense.

 >> One thing that confuses me, in the case of
 >> "cur_ops->deferred_free(old_rp);" , the earlier do-while loop may exit
 >> before the async callbacks can finish. So what prevents the
 >> "(list_empty(&rcu_tortures[i].rtort_free)" check from happening before
 >> grace periods happen? Thanks for any clarification.
 >
 > We only enter this code if the stutter_wait() actually waited, and by
 > default this function will wait about five seconds.  Since the rcutorture
 > testing goes idle during this time period (or is supposed to!), if things
 > are working properly, knocking off ten grace periods during that time
 > should be pretty much a given.

Sure, makes sense. And this is not Lazy-RCU so 5 seconds should be plenty ;). I 
think I was subconsciously expecting an rcu_barrier() somewhere in the code 
before those checks, but that's not needed as you pointed that the stutter 
should be giving enough time for RCU to make progress.

So hmm, the count being 9 means that not enough RCU grace periods have passed 
for the rcu_torture object in question thus keeping it always allocated. The GP 
thread not getting CPU can do that indeed, or perhaps something else stalling 
RCU like a preempted reader, length preemption disabling on a CPU and so forth.. 
  I'll try to collect a trace when it happens.

thanks,

  - Joel