Re: [PATCH] printk: Add printk_flush() to force buffered text to console

[Ingo Molnar <mingo@kernel.org>]

* Steven Rostedt <rostedt@goodmis.org> wrote:

> Fengguang Wu had a config that caused the system to lockup. It reported:
> 
> [    6.086395] type=2000 audit(1339501575.085:1): initialized
> [    6.116356] Kprobe smoke test started
> [    6.125915] Kprobe smoke test passed successfully
> [    6.127478] rcu-torture:--- Start of test: nreaders=2 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0
> +fqs_holdoff=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0
> 
> and then froze. So naturally, the suspected bug was with rcu-torture.
> Fengguang did a git bisect and discovered that the crash came with a
> function trace update. He also noticed that if he reverted that update,
> the system got farther and showed:
> 
> [    1.611901] Testing tracer function: PASSED
> 
> His time was wasted by the fact that the function tracing self test
> first prints:
> 
>   "Testing tracer function: "
> 
> then runs the test, and if it succeeds, it prints "PASSED", giving us
> the nice output you see above.
> 
> But with the new printk() changes, text without a newline gets buffered
> and does not print out to the console at the location of the printk.
> This caused the "Testing tracer function: " not to print out and because
> the test caused the kernel to lock up, we are clueless to the fact that
> the problem was with the function tracer test and not the rcu_torture
> test. As it made sense that the rcu_torture test could lock up the
> system, many kernel developer hours were wasted chasing the wrong wild
> goose.
> 
> If the "Testing tracer function: " had printed out in the first place,
> we would have caught the correct wild goose and saved precious kernel
> developer's time.
> 
> Thus a need for the following utility. That is to add a 'printk_flush()'
> that acts like a fflush() in userspace to flush out the buffers used by
> the printing facility so we don't have unexpected hunts for nature
> roaming fowl.
> 
> I hooked onto the 'facility' infrastructure and used '0x1ffc' (the max
> number) as a way to communicate printk() commands to the msg_print_text()
> which is performed at a later time (console_unlock()).
> 
> I tested this out, (adding pr_flush() after my printk) and now the
> lockup shows:
> 
> [    9.018231] Kprobe smoke test passed successfully
> [    9.023084] rcu-torture:--- Start of test: nreaders=4 nfakewriters=4 stat_interval=0 verbose=0 test_no_idle_hz=0 shuffle_interval=3 stutter=5 irqreader=1 fqs_duration=0 fqs_hold
> off=0 fqs_stutter=3 test_boost=1/0 test_boost_interval=7 test_boost_duration=4 shutdown_secs=0 onoff_interval=0 onoff_holdoff=0
> [    9.066065] Testing tracer function:
> 
> To prevent the flush to cause the next printk to have a timestamp that
> would produce the following:
> 
> [    6.834073] Testing tracer function: [    7.136194] PASSED
> 
> I made the KERN_CONT ("<c>") use the facility as well to pass info to
> not print the timestamp. This fixes the abve issue to print:
> 
> [    1.291025] Testing tracer function: PASSED
> 
> Link: http://lkml.kernel.org/r/1339649173.13377.191.camel@gandalf.stny.rr.com
> 
> Cc: Linus Torvalds <torvalds@linux-foundation.org>
> Cc: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
> Cc: "kay.sievers" <kay.sievers@vrfy.org>
> Cc: "Paul E. McKenney" <paulmck@us.ibm.com>
> Cc: Fengguang Wu <fengguang.wu@intel.com>
> Cc: Ingo Molnar <mingo@elte.hu>
> Cc: Andrew Morton <akpm@linux-foundation.org>
> Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
> ---
>  include/linux/printk.h |    8 ++++
>  kernel/printk.c        |  104 ++++++++++++++++++++++++++++++++++++++++++-----
>  2 files changed, 101 insertions(+), 11 deletions(-)

Maybe also add the actual usage sites, to demonstrate how it's 
going to be used?

Thanks,

	Ingo