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;
Date:   Wed, 15 Jun 2022 06:52:20 -0700
From:   "Paul E. McKenney" <paulmck@kernel.org>
To:     Zhouyi Zhou <zhouzhouyi@gmail.com>
Cc:     john.ogness@linutronix.de, pmladek@suse.com, dave@stgolabs.net,
        Josh Triplett <josh@joshtriplett.org>,
        linux-kernel <linux-kernel@vger.kernel.org>,
        rcu <rcu@vger.kernel.org>
Subject: Re: [PATCH linux-next] RFC: torture: add pr_flush to flush the
 results to console
Message-ID: <20220615135220.GI1790663@paulmck-ThinkPad-P17-Gen-1>
Reply-To: paulmck@kernel.org
References: <20220615003733.16447-1-zhouzhouyi@gmail.com>
 <20220615051521.GH1790663@paulmck-ThinkPad-P17-Gen-1>
 <CAABZP2wCos5xupRQ2LbJtaLVN1a7i0D5kwaVTq9DEov8C46Gkw@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <CAABZP2wCos5xupRQ2LbJtaLVN1a7i0D5kwaVTq9DEov8C46Gkw@mail.gmail.com>
Precedence: bulk

On Wed, Jun 15, 2022 at 08:36:54PM +0800, Zhouyi Zhou wrote:
> On Wed, Jun 15, 2022 at 1:15 PM Paul E. McKenney <paulmck@kernel.org> wrote:
> >
> > On Wed, Jun 15, 2022 at 08:37:33AM +0800, zhouzhouyi@gmail.com wrote:
> > > From: Zhouyi Zhou <zhouzhouyi@gmail.com>
> > >
> > > currently tools/testing/selftests/rcutorture/bin/torture.sh reports
> > > false positve because of kthread printing.
> > >
> > > Commit "printk: add functions to prefer direct printing" (2bb2b7b57f812)
> > > have added functions to prefer direct printing activated for the primary
> > > import messages.
> > >
> > > Meanwhile adding printk_prefer_direct_enter/exit to
> > > torture_cleanup_begin/end still can't eliminate the false positives
> > > for a hundred percent.
> > >
> > > This patch add pr_flush to torture_cleanup_end because the latter
> > > is sleepable.
> > >
> > > Reported-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
> > > Signed-off-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
> > > Tested-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
> >
> > Just the one Signed-off-by suffices.  ;-)
> Thank Paul for your guidance ;-)
> >
> > > ---
> > >  kernel/torture.c | 1 +
> > >  1 file changed, 1 insertion(+)
> > >
> > > diff --git a/kernel/torture.c b/kernel/torture.c
> > > index 789aeb0e1159..b51e42463a67 100644
> > > --- a/kernel/torture.c
> > > +++ b/kernel/torture.c
> > > @@ -878,6 +878,7 @@ void torture_cleanup_end(void)
> > >       mutex_lock(&fullstop_mutex);
> > >       torture_type = NULL;
> > >       mutex_unlock(&fullstop_mutex);
> > > +     pr_flush(1000, true);
> >
> > But in this case, the kernel keeps on running, correct?  So won't the
> > output appear over time?  All of printk()'s kthreads are still running
> > after all.
> I am doing research on linux-next following your guidance on my Dell
> PowerEdge R720 server:
> #git clone https://kernel.source.codeaurora.cn/pub/scm/linux/kernel/git/next/linux-next.git/
> #cd linux-next
> #./tools/testing/selftests/rcutorture/bin/torture.sh
> after about 14 hours, the test result show that there have been about
> 17 failures, I examine the corresponding console.log, and find the
> failures are caused by following reason:
> before the message output by
> rcu/lock/scf_torture_print_module_parms(cur_ops, "End of test:
> SUCCESS") has reached serial console, torture_shutdown invoked
> kernel_power_off(),

Ah, got it!  And good show tracking this down, by the way.

Does this workaround commit on -rcu do the trick for you?

704ae8dcda84 ("torture: Flush printk() buffers before powering off")

The printk() guys are looking at fixes within the printk() system
as well:

https://lore.kernel.org/all/87tu8pgcj0.fsf@jogness.linutronix.de/
https://lore.kernel.org/all/YqdSw%2FfJvnkRbjvc@alley/

> so the message "End of test: SUCCESS" has not chance of reaching
> console.log of host machine.
> 
> Then I add printk_prefer_direct_enter/exit to
> torture_cleanup_begin/end, again I invoke
> #./tools/testing/selftests/rcutorture/bin/torture.sh
> after about 14 hours, the test result show that there have been about
> 5 failures,
> 
> Then I add a debug statement after
> rcu/lock/scf_torture_print_module_parms(cur_ops, "End of test:
> SUCCESS") which sends the debug string ("hello world") to
> uart_console_write directly, again I invoke
> #./tools/testing/selftests/rcutorture/bin/torture.sh
> There is "hello world" in console.log but no "End of test" strings.
> 
> So I guess even with printk_prefer_direct_enter/exit to
> torture_cleanup_begin/end,  our main shutdown thread has failed in
> competition for console lock (printk.c):
> 2401 if (console_trylock_spinning())
> 2402     console_unlock();
> 
> Then I add pr_flush to torture_cleanup_end
> #./tools/testing/selftests/rcutorture/bin/torture.sh
> after 14 hours
> all 49 tests are success
> >
> > Or do you have a use case that requires that the output appear sooner
> > than it does?  If so, please let me know what that is.
> Thank Paul for your patience,
> ./tools/testing/selftests/rcutorture/bin/torture.sh is the only tool
> that I use.
> 
> I am very interested in this topic, and very glad to do further
> experiments under your guidance ;-)

Or are you already running with that commit or one of those patches?
They are working reliably for me (so far, anyway), but maybe more is
needed in some cases.

							Thanx, Paul

> Sincerely yours
> Thanks
> Zhouyi
> >
> >                                                         Thanx, Paul
> >
> > >  }
> > >  EXPORT_SYMBOL_GPL(torture_cleanup_end);
> > >
> > > --
> > > 2.25.1
> > >