lkml.org 
[lkml]   [2012]   [Jun]   [22]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH] printk: Add printk_flush() to force buffered text to console

* 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


\
 
 \ /
  Last update: 2012-06-22 10:41    [W:0.180 / U:0.268 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site