Thank Paul and Petr for your efforts! On Thu, Jun 16, 2022 at 3:09 AM Paul E. McKenney <paulmck@xxxxxxxxxx> wrote: > > 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. I am very happy to see the official fix, and start test it on my Dell server by invoking ./tools/testing/selftests/rcutorture/bin/torture.sh It will take 12 hours for the above script to finish if the other guy who shares the server with me doesn't use it heavily ;-) Thanks Sincerely yours Zhouyi > > 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 > > > > >
