Re: [PATCH linux-next] RFC: torture: add pr_flush to flush the results to console

[Paul E. McKenney]

On Wed, Jun 15, 2022 at 06:52:20AM -0700, Paul E. McKenney wrote:
> 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@xxxxxxxxxx> wrote:
> > >
> > > On Wed, Jun 15, 2022 at 08:37:33AM +0800, zhouzhouyi@xxxxxxxxx wrote:
> > > > From: Zhouyi Zhou <zhouzhouyi@xxxxxxxxx>
> > > >
> > > > 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@xxxxxxxxx>
> > > > Signed-off-by: Zhouyi Zhou <zhouzhouyi@xxxxxxxxx>
> > > > Tested-by: Zhouyi Zhou <zhouzhouyi@xxxxxxxxx>
> > >
> > > 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@xxxxxxxxxxxxxxxxxxxxx/
> https://lore.kernel.org/all/YqdSw%2FfJvnkRbjvc@alley/

And Petr has posted a more official fix, which I have queued on -rcu
for testing at branch pmladek.2022.06.15a.

							Thanx, Paul

> > 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
> > > >