lkml.org 
[lkml]   [2022]   [Jun]   [15]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
From
Date
SubjectRe: [PATCH linux-next] RFC: torture: add pr_flush to flush the results to console
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(),
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 ;-)

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

\
 
 \ /
  Last update: 2022-06-15 14:38    [W:0.275 / U:0.132 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site