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(), 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 > >
