Login | Register For Free | Help
Search for: (Advanced)

Mailing List Archive: Linux: Kernel

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

 

 

First page Previous page 1 2 Next page Last page  View All Linux kernel RSS feed   Index | Next | Previous | View Threaded


rostedt at goodmis

Jun 13, 2012, 9:46 PM

Post #1 of 44 (917 views)
Permalink
[PATCH] printk: Add printk_flush() to force buffered text to console

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 '8191' (the max
number) as the "flush" facility. I also added the use of '<f>' that is
only used internally to printk to distinguish a flush has been
requested.

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:


But now it adds a timestamp where one shouldn't be. But this isn't as
annoying as not having something print out when the system locks up. We
can figure out how to fix that later.

[ 6.834073] Testing tracer function: [ 7.136194] PASSED

Well, it shows the length of the test, so it isn't that bad.

Signed-off-by: Steven Rostedt <rostedt [at] goodmis>

diff --git a/include/linux/printk.h b/include/linux/printk.h
index 1bec2f7..b3317bf3 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -111,6 +111,8 @@ asmlinkage int printk_emit(int facility, int level,
asmlinkage __printf(1, 2) __cold
int printk(const char *fmt, ...);

+void printk_flush(void);
+
/*
* Special printk facility for scheduler use only, _DO_NOT_USE_ !
*/
@@ -158,6 +160,10 @@ static inline bool printk_timed_ratelimit(unsigned long *caller_jiffies,
return false;
}

+static inline void printk_flush(void)
+{
+}
+
static inline void log_buf_kexec_setup(void)
{
}
@@ -190,6 +196,8 @@ extern void dump_stack(void) __cold;
printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
#define pr_cont(fmt, ...) \
printk(KERN_CONT fmt, ##__VA_ARGS__)
+#define pr_flush() \
+ printk_flush()

/* pr_devel() should produce zero code unless DEBUG is defined */
#ifdef DEBUG
diff --git a/kernel/printk.c b/kernel/printk.c
index 32462d2..dd27ac3 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -237,6 +237,9 @@ static char __log_buf[__LOG_BUF_LEN] __aligned(LOG_ALIGN);
static char *log_buf = __log_buf;
static u32 log_buf_len = __LOG_BUF_LEN;

+#define LOG_FLUSH 8191 /* 0xffff >> 3 */
+#define KERN_FLUSH "<f>"
+
/* cpu currently holding logbuf_lock */
static volatile unsigned int logbuf_cpu = UINT_MAX;

@@ -843,7 +846,8 @@ static size_t msg_print_text(const struct log *msg, bool syslog,
len += print_prefix(msg, syslog, buf + len);
memcpy(buf + len, text, text_len);
len += text_len;
- buf[len++] = '\n';
+ if (msg->level >> 3 != LOG_FLUSH)
+ buf[len++] = '\n';
} else {
/* SYSLOG_ACTION_* buffer size only calculation */
len += print_prefix(msg, syslog, NULL);
@@ -1275,6 +1279,7 @@ asmlinkage int vprintk_emit(int facility, int level,
int this_cpu;
bool newline = false;
bool prefix = false;
+ bool flush = false;
int printed_len = 0;

boot_delay_msec();
@@ -1339,18 +1344,29 @@ asmlinkage int vprintk_emit(int facility, int level,
case 'c': /* KERN_CONT */
text += 3;
text_len -= 3;
+ break;
+ case 'f': /* KERN_FLUSH - used internally */
+ flush = true;
}
}

- if (level == -1)
- level = default_message_loglevel;
+ if (!flush) {
+ if (level == -1)
+ level = default_message_loglevel;

- if (dict) {
- prefix = true;
- newline = true;
+ if (dict) {
+ prefix = true;
+ newline = true;
+ }
}

- if (!newline) {
+ if (flush) {
+ if (cont_len) {
+ log_store(LOG_FLUSH, cont_level, NULL, 0, cont_buf, cont_len);
+ cont_len = 0;
+ }
+
+ } else if (!newline) {
if (cont_len && (prefix || cont_task != current)) {
/*
* Flush earlier buffer, which is either from a
@@ -1483,6 +1499,24 @@ asmlinkage int printk(const char *fmt, ...)
}
EXPORT_SYMBOL(printk);

+/**
+ * printk_flush - flush out any buffered text
+ *
+ * printk() will buffer text and not write it out to the console
+ * if the text was missing a newline. If it is required to get text
+ * out to the console without a newline, use printk_flush() and it
+ * will do that. This is useful when running self tests, where you
+ * have a line that prints what is being tested, and then if it
+ * passed or failed after the test, and you want this all done on
+ * a single line. Without flushing, if the test crashes, you may
+ * never see what was being tested.
+ */
+void printk_flush(void)
+{
+ printk("<f>");
+}
+EXPORT_SYMBOL(printk_flush);
+
#else

#define LOG_LINE_MAX 0


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


gregkh at linuxfoundation

Jun 13, 2012, 9:59 PM

Post #2 of 44 (881 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, Jun 14, 2012 at 12:46:13AM -0400, Steven Rostedt 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.

You can't do a simple:
"Tracer function test starting"
"Tracer function test succeeded"
instead?

What happens if other parts of the system are doing printk() calls?
Wouldn't it make more sense just to pair them up like this instead of
flushing (as you then end up with the timestamp messing things up like
you showed.)

Also, this way you know how long your tests take, which might be nice to
know to figure out where boot time is going :)

thanks,

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


rostedt at goodmis

Jun 14, 2012, 4:01 AM

Post #3 of 44 (877 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Wed, 2012-06-13 at 21:59 -0700, Greg Kroah-Hartman wrote:
> On Thu, Jun 14, 2012 at 12:46:13AM -0400, Steven Rostedt 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.
>
> You can't do a simple:
> "Tracer function test starting"
> "Tracer function test succeeded"
> instead?

But I find that ugly ;-)


I know you can argue that the extra timestamp may be ugly too, but we
can work that out as well. I was just too tired to do so last night and
wanted to kick off the discussion before I got too tied up in other
things.

Currently we have something like this:

[ 6.834073] Testing tracer function: [ 7.136194] PASSED
[ 7.567062] Testing dynamic ftrace: PASSED
[ 8.053670] Testing dynamic ftrace ops #1: (1 0 1 1 0) (1 1 2 1 0) (2 1 3 1 18) (2 2 4 1 37) PASSED
[ 8.566062] Testing dynamic ftrace ops #2: (1 0 1 7 0) (1 1 2 38 0) (2 1 3 1 6) (2 2 4 36 36) PASSED
[ 8.596063] Testing tracer irqsoff: [ 9.014064] PASSED
[ 9.038062] Testing tracer wakeup: [ 9.681063] PASSED
[ 9.705066] Testing tracer wakeup_rt: [ 10.347064] PASSED
[ 10.371063] Testing tracer function_graph: [ 10.876064] PASSED

I didn't fix the dynamic ftrace ops #1 and #2 to flush, but that should
too, as each set of (1 0 1 1 0) etc, numbers are important, and is a
separate test. That could lock up the system as well and knowing where
it locked up is key to debugging.

To make this work with the current printk, I have to do:

Tracer function test started
Tracer function test succeeded
Tracer dynamic ftrace test started
Tracer dynamic ftrace test succeeded
Tracer dynamic ftrace ops #1 test started
(1 0 1 1 0)
(1 1 2 1 0)
(2 1 3 1 18)
(2 2 4 1 37)
Tracer dynamic ftrace ops #1 test succeeded
Tracer dynamic ftrace ops #2 test started
(1 0 1 7 0)
(1 1 2 38 0)
(2 1 3 1 6)
(2 2 4 36 36)
Tracer dynamic ftrace ops #2 succeeded
Tracer irqsoff test started
Tracer irqsoff test succeeded
Tracer wakeup test started
Tracer wakeup test succeeded
Tracer wakeup_rt test started
Tracer wakeup_rt test succeeded
Tracer function_graph test started
Tracer function_graph test succeeded


Yes, this would give us the functionality of today but more lines of
text on the output line. Then we have to worry about the trace event
tests:


[ 72.177731] Testing event rpc_bind_status: OK
[ 72.187100] Testing event rpc_connect_status: OK
[ 72.196501] Testing event rpc_task_begin: OK
[ 72.205504] Testing event rpc_task_run_action: OK
[ 72.214487] Testing event rpc_task_complete: OK
[ 72.223504] Testing event rpc_task_sleep: OK
[ 72.232500] Testing event rpc_task_wakeup: OK
[ 72.241504] Testing event kfree_skb: OK
[ 72.249486] Testing event consume_skb: OK
[ 72.257504] Testing event skb_copy_datagram_iovec: OK
[ 72.267500] Testing event net_dev_xmit: OK
[ 72.276486] Testing event net_dev_queue: OK
[ 72.285504] Testing event netif_receive_skb: OK
[ 72.294486] Testing event netif_rx: OK
[ 72.302504] Testing event napi_poll: OK
[ 72.310486] Testing event sock_rcvqueue_full: OK
[ 72.319504] Testing event sock_exceed_buf_limit: OK
[ 72.328486] Testing event udp_fail_queue_rcv_skb: OK
[ 72.337503] Testing event hda_send_cmd: OK
[ 72.346501] Testing event hda_get_response: OK
[ 72.355503] Testing event hda_bus_reset: OK
[ 72.364501] Testing event hda_power_down: OK
[ 72.373503] Testing event hda_power_up: OK
[ 72.382500] Testing event hda_unsol_event: OK
[ 72.391504] Testing event scsi_dispatch_cmd_start: OK
[ 72.401501] Testing event scsi_dispatch_cmd_error: OK
[ 72.411487] Testing event scsi_dispatch_cmd_done: OK
[ 72.420503] Testing event scsi_dispatch_cmd_timeout: OK
[ 72.430501] Testing event scsi_eh_wakeup: OK
[ 72.439505] Testing event i915_gem_object_create: OK
[ 72.448486] Testing event i915_gem_object_bind: OK
[ 72.457504] Testing event i915_gem_object_unbind: OK
[ 72.466487] Testing event i915_gem_object_change_domain: OK
[ 72.476504] Testing event i915_gem_object_pwrite: OK
[ 72.485486] Testing event i915_gem_object_pread: OK
[ 72.494504] Testing event i915_gem_object_fault: OK
[ 72.503485] Testing event i915_gem_object_clflush: OK
[ 72.513488] Testing event i915_gem_object_destroy: OK
[ 72.523488] Testing event i915_gem_evict: OK
[ 72.532479] Testing event i915_gem_evict_everything: OK
[ 72.542505] Testing event i915_gem_ring_dispatch: OK
[ 72.551486] Testing event i915_gem_ring_flush: OK
[ 72.560478] Testing event i915_gem_request_add: OK
[ 72.569506] Testing event i915_gem_request_complete: OK
[ 72.579501] Testing event i915_gem_request_retire: OK
[ 72.589485] Testing event i915_gem_request_wait_begin: OK
[ 72.599506] Testing event i915_gem_request_wait_end: OK
[ 72.609501] Testing event i915_ring_wait_begin: OK
[ 72.618504] Testing event i915_ring_wait_end: OK
[ 72.627488] Testing event i915_flip_request: OK
[...]

This does it for every event that is created. This case had 1556 events
tested.

The config had:

CONFIG_FTRACE_SELFTEST=y
CONFIG_FTRACE_STARTUP_TEST=y
# CONFIG_EVENT_TRACE_TEST_SYSCALLS is not set

If CONFIG_EVENT_TRACE_TEST_SYSCALLS is set, then it does the testing of
every system call entry and exit event.

>
> What happens if other parts of the system are doing printk() calls?
> Wouldn't it make more sense just to pair them up like this instead of
> flushing (as you then end up with the timestamp messing things up like
> you showed.)

On system boot up there's not much that gets interrupted. And yeah, I
don't like the timestamp in the middle. But that just means we need to
work to fix that too ;-)

>
> Also, this way you know how long your tests take, which might be nice to
> know to figure out where boot time is going :)

Hehe, if you have self tests enabled, you can bet the boot time is going
to them. I have no intention on speeding the tests up, if anything, I
want to add more to them, which would slow them down.

If you are concerned about boot up (and for production environments) you
do not enable these self tests. That wasn't their purpose. They were
created for developers to test their systems, just like lockdep and
kmemcheck are. You don't want those running on your production
environment either.

-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


gregkh at linuxfoundation

Jun 14, 2012, 8:41 AM

Post #4 of 44 (877 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, Jun 14, 2012 at 07:01:55AM -0400, Steven Rostedt wrote:
> On Wed, 2012-06-13 at 21:59 -0700, Greg Kroah-Hartman wrote:
> > On Thu, Jun 14, 2012 at 12:46:13AM -0400, Steven Rostedt 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.
> >
> > You can't do a simple:
> > "Tracer function test starting"
> > "Tracer function test succeeded"
> > instead?
>
> But I find that ugly ;-)

I find printk_flush() ugly :)

> I know you can argue that the extra timestamp may be ugly too, but we
> can work that out as well. I was just too tired to do so last night and
> wanted to kick off the discussion before I got too tied up in other
> things.
>
> Currently we have something like this:
>
> [ 6.834073] Testing tracer function: [ 7.136194] PASSED
> [ 7.567062] Testing dynamic ftrace: PASSED
> [ 8.053670] Testing dynamic ftrace ops #1: (1 0 1 1 0) (1 1 2 1 0) (2 1 3 1 18) (2 2 4 1 37) PASSED
> [ 8.566062] Testing dynamic ftrace ops #2: (1 0 1 7 0) (1 1 2 38 0) (2 1 3 1 6) (2 2 4 36 36) PASSED

That's ugly to me :)

> [ 8.596063] Testing tracer irqsoff: [ 9.014064] PASSED
> [ 9.038062] Testing tracer wakeup: [ 9.681063] PASSED
> [ 9.705066] Testing tracer wakeup_rt: [ 10.347064] PASSED
> [ 10.371063] Testing tracer function_graph: [ 10.876064] PASSED
>
> I didn't fix the dynamic ftrace ops #1 and #2 to flush, but that should
> too, as each set of (1 0 1 1 0) etc, numbers are important, and is a
> separate test. That could lock up the system as well and knowing where
> it locked up is key to debugging.
>
> To make this work with the current printk, I have to do:
>
> Tracer function test started
> Tracer function test succeeded
> Tracer dynamic ftrace test started
> Tracer dynamic ftrace test succeeded
> Tracer dynamic ftrace ops #1 test started
> (1 0 1 1 0)
> (1 1 2 1 0)
> (2 1 3 1 18)
> (2 2 4 1 37)

I suggest better prefixes here.

> Tracer dynamic ftrace ops #1 test succeeded
> Tracer dynamic ftrace ops #2 test started
> (1 0 1 7 0)
> (1 1 2 38 0)
> (2 1 3 1 6)
> (2 2 4 36 36)

And here.

> Tracer dynamic ftrace ops #2 succeeded
> Tracer irqsoff test started
> Tracer irqsoff test succeeded
> Tracer wakeup test started
> Tracer wakeup test succeeded
> Tracer wakeup_rt test started
> Tracer wakeup_rt test succeeded
> Tracer function_graph test started
> Tracer function_graph test succeeded
>
>
> Yes, this would give us the functionality of today but more lines of
> text on the output line. Then we have to worry about the trace event
> tests:

So what? You are doing development tests, it's ok to print out a lot of
messages, that is what you want to see, especially when something fails,
right?

> [ 72.177731] Testing event rpc_bind_status: OK
> [ 72.187100] Testing event rpc_connect_status: OK
> [ 72.196501] Testing event rpc_task_begin: OK
> [ 72.205504] Testing event rpc_task_run_action: OK
> [ 72.214487] Testing event rpc_task_complete: OK
> [ 72.223504] Testing event rpc_task_sleep: OK
> [ 72.232500] Testing event rpc_task_wakeup: OK
> [ 72.241504] Testing event kfree_skb: OK
> [ 72.249486] Testing event consume_skb: OK
> [ 72.257504] Testing event skb_copy_datagram_iovec: OK
> [ 72.267500] Testing event net_dev_xmit: OK
> [ 72.276486] Testing event net_dev_queue: OK
> [ 72.285504] Testing event netif_receive_skb: OK
> [ 72.294486] Testing event netif_rx: OK
> [ 72.302504] Testing event napi_poll: OK
> [ 72.310486] Testing event sock_rcvqueue_full: OK
> [ 72.319504] Testing event sock_exceed_buf_limit: OK
> [ 72.328486] Testing event udp_fail_queue_rcv_skb: OK
> [ 72.337503] Testing event hda_send_cmd: OK
> [ 72.346501] Testing event hda_get_response: OK
> [ 72.355503] Testing event hda_bus_reset: OK
> [ 72.364501] Testing event hda_power_down: OK
> [ 72.373503] Testing event hda_power_up: OK
> [ 72.382500] Testing event hda_unsol_event: OK
> [ 72.391504] Testing event scsi_dispatch_cmd_start: OK
> [ 72.401501] Testing event scsi_dispatch_cmd_error: OK
> [ 72.411487] Testing event scsi_dispatch_cmd_done: OK
> [ 72.420503] Testing event scsi_dispatch_cmd_timeout: OK
> [ 72.430501] Testing event scsi_eh_wakeup: OK
> [ 72.439505] Testing event i915_gem_object_create: OK
> [ 72.448486] Testing event i915_gem_object_bind: OK
> [ 72.457504] Testing event i915_gem_object_unbind: OK
> [ 72.466487] Testing event i915_gem_object_change_domain: OK
> [ 72.476504] Testing event i915_gem_object_pwrite: OK
> [ 72.485486] Testing event i915_gem_object_pread: OK
> [ 72.494504] Testing event i915_gem_object_fault: OK
> [ 72.503485] Testing event i915_gem_object_clflush: OK
> [ 72.513488] Testing event i915_gem_object_destroy: OK
> [ 72.523488] Testing event i915_gem_evict: OK
> [ 72.532479] Testing event i915_gem_evict_everything: OK
> [ 72.542505] Testing event i915_gem_ring_dispatch: OK
> [ 72.551486] Testing event i915_gem_ring_flush: OK
> [ 72.560478] Testing event i915_gem_request_add: OK
> [ 72.569506] Testing event i915_gem_request_complete: OK
> [ 72.579501] Testing event i915_gem_request_retire: OK
> [ 72.589485] Testing event i915_gem_request_wait_begin: OK
> [ 72.599506] Testing event i915_gem_request_wait_end: OK
> [ 72.609501] Testing event i915_ring_wait_begin: OK
> [ 72.618504] Testing event i915_ring_wait_end: OK
> [ 72.627488] Testing event i915_flip_request: OK
> [...]
>
> This does it for every event that is created. This case had 1556 events
> tested.

Great, lots of messages, be sure to increment your printk buffer size.
Or write saner tests :)

> The config had:
>
> CONFIG_FTRACE_SELFTEST=y
> CONFIG_FTRACE_STARTUP_TEST=y
> # CONFIG_EVENT_TRACE_TEST_SYSCALLS is not set
>
> If CONFIG_EVENT_TRACE_TEST_SYSCALLS is set, then it does the testing of
> every system call entry and exit event.

Ok, but then again, that's your choice to do so, no "sane" person
normally enables that option...

> > What happens if other parts of the system are doing printk() calls?
> > Wouldn't it make more sense just to pair them up like this instead of
> > flushing (as you then end up with the timestamp messing things up like
> > you showed.)
>
> On system boot up there's not much that gets interrupted. And yeah, I
> don't like the timestamp in the middle. But that just means we need to
> work to fix that too ;-)

I think with a few minor changes as mentioned above, your messages will
look just fine, and you will know better how long things take, and what
exactly fails, which is what you want to know, right?

> > Also, this way you know how long your tests take, which might be nice to
> > know to figure out where boot time is going :)
>
> Hehe, if you have self tests enabled, you can bet the boot time is going
> to them. I have no intention on speeding the tests up, if anything, I
> want to add more to them, which would slow them down.
>
> If you are concerned about boot up (and for production environments) you
> do not enable these self tests. That wasn't their purpose. They were
> created for developers to test their systems, just like lockdep and
> kmemcheck are. You don't want those running on your production
> environment either.

Ok, then you just answered your own question there, make the messages a
bit "prettier" and all is fine, as no one will ever use this in
production, only for developers, and we can handle the little bit extra
printk noise, at the expense of providing accurate information.

thanks,

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


rostedt at goodmis

Jun 14, 2012, 10:07 AM

Post #5 of 44 (875 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, 2012-06-14 at 08:41 -0700, Greg Kroah-Hartman wrote:
>
> > But I find that ugly ;-)
>
> I find printk_flush() ugly :)
>

I guess beauty is really in the eye of the beholder.

> > I know you can argue that the extra timestamp may be ugly too, but we
> > can work that out as well. I was just too tired to do so last night and
> > wanted to kick off the discussion before I got too tied up in other
> > things.
> >
> > Currently we have something like this:
> >
> > [ 6.834073] Testing tracer function: [ 7.136194] PASSED
> > [ 7.567062] Testing dynamic ftrace: PASSED
> > [ 8.053670] Testing dynamic ftrace ops #1: (1 0 1 1 0) (1 1 2 1 0) (2 1 3 1 18) (2 2 4 1 37) PASSED
> > [ 8.566062] Testing dynamic ftrace ops #2: (1 0 1 7 0) (1 1 2 38 0) (2 1 3 1 6) (2 2 4 36 36) PASSED
>
> That's ugly to me :)

No no, that's pretty to you. Maybe meaningless, but pretty!

>
> > [ 8.596063] Testing tracer irqsoff: [ 9.014064] PASSED
> > [ 9.038062] Testing tracer wakeup: [ 9.681063] PASSED
> > [ 9.705066] Testing tracer wakeup_rt: [ 10.347064] PASSED
> > [ 10.371063] Testing tracer function_graph: [ 10.876064] PASSED
> >
> > I didn't fix the dynamic ftrace ops #1 and #2 to flush, but that should
> > too, as each set of (1 0 1 1 0) etc, numbers are important, and is a
> > separate test. That could lock up the system as well and knowing where
> > it locked up is key to debugging.
> >
> > To make this work with the current printk, I have to do:
> >
> > Tracer function test started
> > Tracer function test succeeded
> > Tracer dynamic ftrace test started
> > Tracer dynamic ftrace test succeeded
> > Tracer dynamic ftrace ops #1 test started
> > (1 0 1 1 0)
> > (1 1 2 1 0)
> > (2 1 3 1 18)
> > (2 2 4 1 37)
>
> I suggest better prefixes here.

And let people in on my secret (well, without having to read the
code) ;-)

>
> > Tracer dynamic ftrace ops #1 test succeeded
> > Tracer dynamic ftrace ops #2 test started
> > (1 0 1 7 0)
> > (1 1 2 38 0)
> > (2 1 3 1 6)
> > (2 2 4 36 36)
>
> And here.
>
> > Tracer dynamic ftrace ops #2 succeeded
> > Tracer irqsoff test started
> > Tracer irqsoff test succeeded
> > Tracer wakeup test started
> > Tracer wakeup test succeeded
> > Tracer wakeup_rt test started
> > Tracer wakeup_rt test succeeded
> > Tracer function_graph test started
> > Tracer function_graph test succeeded
> >
> >
> > Yes, this would give us the functionality of today but more lines of
> > text on the output line. Then we have to worry about the trace event
> > tests:
>
> So what? You are doing development tests, it's ok to print out a lot of
> messages, that is what you want to see, especially when something fails,
> right?

I actually would like to make these more compact. As all my test box
consoles go through serial ports, just booting through this takes more
time the the compile itself.

>
> > [ 72.177731] Testing event rpc_bind_status: OK
> > [ 72.187100] Testing event rpc_connect_status: OK
> > [ 72.196501] Testing event rpc_task_begin: OK
> > [ 72.205504] Testing event rpc_task_run_action: OK
> > [ 72.214487] Testing event rpc_task_complete: OK
> > [ 72.223504] Testing event rpc_task_sleep: OK
> > [ 72.232500] Testing event rpc_task_wakeup: OK
> > [ 72.241504] Testing event kfree_skb: OK
> > [ 72.249486] Testing event consume_skb: OK
> > [ 72.257504] Testing event skb_copy_datagram_iovec: OK
> > [ 72.267500] Testing event net_dev_xmit: OK
> > [ 72.276486] Testing event net_dev_queue: OK
> > [ 72.285504] Testing event netif_receive_skb: OK
> > [ 72.294486] Testing event netif_rx: OK
> > [ 72.302504] Testing event napi_poll: OK
> > [ 72.310486] Testing event sock_rcvqueue_full: OK
> > [ 72.319504] Testing event sock_exceed_buf_limit: OK
> > [ 72.328486] Testing event udp_fail_queue_rcv_skb: OK
> > [ 72.337503] Testing event hda_send_cmd: OK
> > [ 72.346501] Testing event hda_get_response: OK
> > [ 72.355503] Testing event hda_bus_reset: OK
> > [ 72.364501] Testing event hda_power_down: OK
> > [ 72.373503] Testing event hda_power_up: OK
> > [ 72.382500] Testing event hda_unsol_event: OK
> > [ 72.391504] Testing event scsi_dispatch_cmd_start: OK
> > [ 72.401501] Testing event scsi_dispatch_cmd_error: OK
> > [ 72.411487] Testing event scsi_dispatch_cmd_done: OK
> > [ 72.420503] Testing event scsi_dispatch_cmd_timeout: OK
> > [ 72.430501] Testing event scsi_eh_wakeup: OK
> > [ 72.439505] Testing event i915_gem_object_create: OK
> > [ 72.448486] Testing event i915_gem_object_bind: OK
> > [ 72.457504] Testing event i915_gem_object_unbind: OK
> > [ 72.466487] Testing event i915_gem_object_change_domain: OK
> > [ 72.476504] Testing event i915_gem_object_pwrite: OK
> > [ 72.485486] Testing event i915_gem_object_pread: OK
> > [ 72.494504] Testing event i915_gem_object_fault: OK
> > [ 72.503485] Testing event i915_gem_object_clflush: OK
> > [ 72.513488] Testing event i915_gem_object_destroy: OK
> > [ 72.523488] Testing event i915_gem_evict: OK
> > [ 72.532479] Testing event i915_gem_evict_everything: OK
> > [ 72.542505] Testing event i915_gem_ring_dispatch: OK
> > [ 72.551486] Testing event i915_gem_ring_flush: OK
> > [ 72.560478] Testing event i915_gem_request_add: OK
> > [ 72.569506] Testing event i915_gem_request_complete: OK
> > [ 72.579501] Testing event i915_gem_request_retire: OK
> > [ 72.589485] Testing event i915_gem_request_wait_begin: OK
> > [ 72.599506] Testing event i915_gem_request_wait_end: OK
> > [ 72.609501] Testing event i915_ring_wait_begin: OK
> > [ 72.618504] Testing event i915_ring_wait_end: OK
> > [ 72.627488] Testing event i915_flip_request: OK
> > [...]
> >
> > This does it for every event that is created. This case had 1556 events
> > tested.
>
> Great, lots of messages, be sure to increment your printk buffer size.
> Or write saner tests :)

No reason for extended buffer size, this is all recorded on serial
console.

>
> > The config had:
> >
> > CONFIG_FTRACE_SELFTEST=y
> > CONFIG_FTRACE_STARTUP_TEST=y
> > # CONFIG_EVENT_TRACE_TEST_SYSCALLS is not set
> >
> > If CONFIG_EVENT_TRACE_TEST_SYSCALLS is set, then it does the testing of
> > every system call entry and exit event.
>
> Ok, but then again, that's your choice to do so, no "sane" person
> normally enables that option...

No "sane" person would enable any of the above options. They are for
testing purposes only. This of course assumes that kernel developers are
not "sane".


>
> > > What happens if other parts of the system are doing printk() calls?
> > > Wouldn't it make more sense just to pair them up like this instead of
> > > flushing (as you then end up with the timestamp messing things up like
> > > you showed.)
> >
> > On system boot up there's not much that gets interrupted. And yeah, I
> > don't like the timestamp in the middle. But that just means we need to
> > work to fix that too ;-)
>
> I think with a few minor changes as mentioned above, your messages will
> look just fine, and you will know better how long things take,

I've never really worried about how long, as the output of the message
itself takes up more time than most of those tests.

> and what
> exactly fails, which is what you want to know, right?

Well, it did that before the updated printk() code.

>
> > > Also, this way you know how long your tests take, which might be nice to
> > > know to figure out where boot time is going :)
> >
> > Hehe, if you have self tests enabled, you can bet the boot time is going
> > to them. I have no intention on speeding the tests up, if anything, I
> > want to add more to them, which would slow them down.
> >
> > If you are concerned about boot up (and for production environments) you
> > do not enable these self tests. That wasn't their purpose. They were
> > created for developers to test their systems, just like lockdep and
> > kmemcheck are. You don't want those running on your production
> > environment either.
>
> Ok, then you just answered your own question there, make the messages a
> bit "prettier" and all is fine, as no one will ever use this in
> production, only for developers, and we can handle the little bit extra
> printk noise, at the expense of providing accurate information.

That accurate information is there with the original printk(), but is
broken with the new method.

Currently, I have a patch to force printk() to become early_printk()
that I'll be using for the time being. Until it bothers me enough (read,
user reports are messed up), will this get fixed.

-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


fengguang.wu at intel

Jun 14, 2012, 9:22 PM

Post #6 of 44 (869 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

> I actually would like to make these more compact. As all my test box
> consoles go through serial ports, just booting through this takes more
> time the the compile itself.

The tests took 23 seconds boot time on one kernel:

[ 0.152934] Testing tracer nop: PASSED
...1577 lines total...
[ 23.206550] Testing kprobe tracing: OK

And 135 seconds in another bloated kernel:

[ 115.396441] Testing event 9p_client_req: OK
...2545 lines total...
[ 240.268783] Testing kprobe tracing: OK

I'd appreciate if the boot time can be reduced. Because I'm doing
kernel boot tests for *every single* commits.

It may look insane amount of work, but it's still manageable: with 10
kvm instances each take 1 minute to boot test a kernel, I can boot
test 60*24*10=14400 kernels in one day. That's a rather big number.
That allows me to run more cpu/vm/io stress tests for each kernel :-)

Thanks,
Fengguang
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


gregkh at linuxfoundation

Jun 14, 2012, 9:30 PM

Post #7 of 44 (871 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Fri, Jun 15, 2012 at 12:22:33PM +0800, Fengguang Wu wrote:
> > I actually would like to make these more compact. As all my test box
> > consoles go through serial ports, just booting through this takes more
> > time the the compile itself.
>
> The tests took 23 seconds boot time on one kernel:
>
> [ 0.152934] Testing tracer nop: PASSED
> ...1577 lines total...
> [ 23.206550] Testing kprobe tracing: OK
>
> And 135 seconds in another bloated kernel:
>
> [ 115.396441] Testing event 9p_client_req: OK
> ...2545 lines total...
> [ 240.268783] Testing kprobe tracing: OK
>
> I'd appreciate if the boot time can be reduced. Because I'm doing
> kernel boot tests for *every single* commits.
>
> It may look insane amount of work, but it's still manageable: with 10
> kvm instances each take 1 minute to boot test a kernel, I can boot
> test 60*24*10=14400 kernels in one day. That's a rather big number.
> That allows me to run more cpu/vm/io stress tests for each kernel :-)

Do you really want to enable those tests for your test kernels? Can
they fail if we mess up other parts of the kernel, or do they only test
the tracing portions?

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


fengguang.wu at intel

Jun 14, 2012, 9:37 PM

Post #8 of 44 (871 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, Jun 14, 2012 at 09:30:17PM -0700, Greg Kroah-Hartman wrote:
> On Fri, Jun 15, 2012 at 12:22:33PM +0800, Fengguang Wu wrote:
> > > I actually would like to make these more compact. As all my test box
> > > consoles go through serial ports, just booting through this takes more
> > > time the the compile itself.
> >
> > The tests took 23 seconds boot time on one kernel:
> >
> > [ 0.152934] Testing tracer nop: PASSED
> > ...1577 lines total...
> > [ 23.206550] Testing kprobe tracing: OK
> >
> > And 135 seconds in another bloated kernel:
> >
> > [ 115.396441] Testing event 9p_client_req: OK
> > ...2545 lines total...
> > [ 240.268783] Testing kprobe tracing: OK
> >
> > I'd appreciate if the boot time can be reduced. Because I'm doing
> > kernel boot tests for *every single* commits.
> >
> > It may look insane amount of work, but it's still manageable: with 10
> > kvm instances each take 1 minute to boot test a kernel, I can boot
> > test 60*24*10=14400 kernels in one day. That's a rather big number.
> > That allows me to run more cpu/vm/io stress tests for each kernel :-)
>
> Do you really want to enable those tests for your test kernels? Can
> they fail if we mess up other parts of the kernel, or do they only test
> the tracing portions?

Good question. If the tests are only relevant to the tracing system,
it's better to enable them only when testing the tracing commits. Just
like I won't run ext4 tests for an XFS commit.

Thanks,
Fengguang
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


mingo at kernel

Jun 15, 2012, 5:04 AM

Post #9 of 44 (868 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

* Greg Kroah-Hartman <gregkh [at] linuxfoundation> wrote:

> On Fri, Jun 15, 2012 at 12:22:33PM +0800, Fengguang Wu wrote:
> > > I actually would like to make these more compact. As all my test box
> > > consoles go through serial ports, just booting through this takes more
> > > time the the compile itself.
> >
> > The tests took 23 seconds boot time on one kernel:
> >
> > [ 0.152934] Testing tracer nop: PASSED
> > ...1577 lines total...
> > [ 23.206550] Testing kprobe tracing: OK
> >
> > And 135 seconds in another bloated kernel:
> >
> > [ 115.396441] Testing event 9p_client_req: OK
> > ...2545 lines total...
> > [ 240.268783] Testing kprobe tracing: OK
> >
> > I'd appreciate if the boot time can be reduced. Because I'm doing
> > kernel boot tests for *every single* commits.
> >
> > It may look insane amount of work, but it's still manageable: with 10
> > kvm instances each take 1 minute to boot test a kernel, I can boot
> > test 60*24*10=14400 kernels in one day. That's a rather big number.
> > That allows me to run more cpu/vm/io stress tests for each kernel :-)
>
> Do you really want to enable those tests for your test
> kernels? Can they fail if we mess up other parts of the
> kernel, or do they only test the tracing portions?

These printk's are useful, are used for a specific (albeit
limited) purpose and were and continue to be useful in that
role.

The changes Steve bisected to broke this use of printk(). Please
apply Steve's fix, fix it yourself or revert the changes that
regressed printk().

Thanks,

Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


gregkh at linuxfoundation

Jun 15, 2012, 4:13 PM

Post #10 of 44 (867 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Fri, Jun 15, 2012 at 02:04:30PM +0200, Ingo Molnar wrote:
>
> * Greg Kroah-Hartman <gregkh [at] linuxfoundation> wrote:
>
> > On Fri, Jun 15, 2012 at 12:22:33PM +0800, Fengguang Wu wrote:
> > > > I actually would like to make these more compact. As all my test box
> > > > consoles go through serial ports, just booting through this takes more
> > > > time the the compile itself.
> > >
> > > The tests took 23 seconds boot time on one kernel:
> > >
> > > [ 0.152934] Testing tracer nop: PASSED
> > > ...1577 lines total...
> > > [ 23.206550] Testing kprobe tracing: OK
> > >
> > > And 135 seconds in another bloated kernel:
> > >
> > > [ 115.396441] Testing event 9p_client_req: OK
> > > ...2545 lines total...
> > > [ 240.268783] Testing kprobe tracing: OK
> > >
> > > I'd appreciate if the boot time can be reduced. Because I'm doing
> > > kernel boot tests for *every single* commits.
> > >
> > > It may look insane amount of work, but it's still manageable: with 10
> > > kvm instances each take 1 minute to boot test a kernel, I can boot
> > > test 60*24*10=14400 kernels in one day. That's a rather big number.
> > > That allows me to run more cpu/vm/io stress tests for each kernel :-)
> >
> > Do you really want to enable those tests for your test
> > kernels? Can they fail if we mess up other parts of the
> > kernel, or do they only test the tracing portions?
>
> These printk's are useful, are used for a specific (albeit
> limited) purpose and were and continue to be useful in that
> role.
>
> The changes Steve bisected to broke this use of printk().

And note, fixed others :)

> Please apply Steve's fix, fix it yourself or revert the changes that
> regressed printk().

I thought Steve's patch was just a RFC thing, is it really something
that everyone wants to see applied?

thanks,

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


rostedt at goodmis

Jun 15, 2012, 4:53 PM

Post #11 of 44 (870 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Fri, 2012-06-15 at 16:13 -0700, Greg Kroah-Hartman wrote:

> > Please apply Steve's fix, fix it yourself or revert the changes that
> > regressed printk().
>
> I thought Steve's patch was just a RFC thing, is it really something
> that everyone wants to see applied?

It was, and still is, an RFC. I'd like to fix the double printing of the
time stamps as well.

It was really a compromise, as the new printk() is a serious
functionality change. Even though I mostly use trace_printk(), there are
still times that I like to use printk in some hot spots. For example I
sometimes to do:

printk("a");
some_code();
printk("b");
more_code();
printk("c");
continued_code();
[etc]


And watch a stream of 'abcabcabc...' and see where finally something
causes the machine to triple fault and reboot.

Because the bug would cause a triple fault, there would be no time to
recover data from trace_printk(). But as the code is quite hot, my use
of printk is to be as small as possible and with no new lines.

But now this method is gone. Not to mention, digging through the complex
maze of the new printk, I realize that it's not optimize for speed at
all. But printing to the serial console makes it not that big of a deal.

I have patches that just force printk() to be early_printk(), and in
fact, we have in the -rt patch this:

http://git.kernel.org/?p=linux/kernel/git/rt/linux-stable-rt.git;a=blobdiff;f=kernel/printk.c;h=5a172f9e5027b7416a82e54dfc29afbda71296ee;hp=c4426061e228c252e226feb67193d80cdba3af5b;hb=865407ef06e61c97cdd9091082ed8038c801f535;hpb=c09d1c02743a7d2df13574d93dea9f21ccf02560

I had my own patch that did pretty much the same thing, and I was very
happy to see that Ingo had the same mind set.

Actually, I think that patch really should go mainline, and give others
some of the luxury that us -rt folks enjoy.

But back to this patch. I was irritated that we blamed the wrong code
because the printk functionality changed. And instead of writing some
drastic changes that would be controversial, I suggested a
'printk_flush()' that would work similar to a fflush(). Yeah, buffering
is good and lets lines fit together, but there's times where getting the
partial line out to the screen is more important that keeping it
together.

If other printks were interleaved and it didn't crash, we wouldn't care
(or even notice). But if it did crash, I'll even argue seeing the
interleaved printks would provide a hint to why it crashed.

-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


mingo at kernel

Jun 15, 2012, 11:59 PM

Post #12 of 44 (865 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

* Greg Kroah-Hartman <gregkh [at] linuxfoundation> wrote:

> On Fri, Jun 15, 2012 at 02:04:30PM +0200, Ingo Molnar wrote:
> >
> > * Greg Kroah-Hartman <gregkh [at] linuxfoundation> wrote:
> >
> > > On Fri, Jun 15, 2012 at 12:22:33PM +0800, Fengguang Wu wrote:
> > > > > I actually would like to make these more compact. As all my test box
> > > > > consoles go through serial ports, just booting through this takes more
> > > > > time the the compile itself.
> > > >
> > > > The tests took 23 seconds boot time on one kernel:
> > > >
> > > > [ 0.152934] Testing tracer nop: PASSED
> > > > ...1577 lines total...
> > > > [ 23.206550] Testing kprobe tracing: OK
> > > >
> > > > And 135 seconds in another bloated kernel:
> > > >
> > > > [ 115.396441] Testing event 9p_client_req: OK
> > > > ...2545 lines total...
> > > > [ 240.268783] Testing kprobe tracing: OK
> > > >
> > > > I'd appreciate if the boot time can be reduced. Because I'm doing
> > > > kernel boot tests for *every single* commits.
> > > >
> > > > It may look insane amount of work, but it's still manageable: with 10
> > > > kvm instances each take 1 minute to boot test a kernel, I can boot
> > > > test 60*24*10=14400 kernels in one day. That's a rather big number.
> > > > That allows me to run more cpu/vm/io stress tests for each kernel :-)
> > >
> > > Do you really want to enable those tests for your test
> > > kernels? Can they fail if we mess up other parts of the
> > > kernel, or do they only test the tracing portions?
> >
> > These printk's are useful, are used for a specific (albeit
> > limited) purpose and were and continue to be useful in that
> > role.
> >
> > The changes Steve bisected to broke this use of printk().
>
> And note, fixed others :)

Sorry, the "we fix some bugs and introduce others" stance is not
a valid response to a regression. Either fix *all* regressions
or revert the original change. Simple and robust policy, isn't
it?

> > Please apply Steve's fix, fix it yourself or revert the
> > changes that regressed printk().
>
> I thought Steve's patch was just a RFC thing, is it really
> something that everyone wants to see applied?

You mean the adding of an API to flush buffered output when
that's the desired outcome? Why the heck should we *not* want
that? Either I'm the weird one or you are being difficult ;-)

Thanks,

Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


joe at perches

Jun 16, 2012, 5:51 AM

Post #13 of 44 (865 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Sat, 2012-06-16 at 08:59 +0200, Ingo Molnar wrote:
> * Greg Kroah-Hartman <gregkh [at] linuxfoundation> wrote:
> > On Fri, Jun 15, 2012 at 02:04:30PM +0200, Ingo Molnar wrote:
> > > These printk's are useful, are used for a specific (albeit
> > > limited) purpose and were and continue to be useful in that
> > > role.
> > >
> > > The changes Steve bisected to broke this use of printk().
> >
> > And note, fixed others :)
>
> Sorry, the "we fix some bugs and introduce others" stance is not
> a valid response to a regression. Either fix *all* regressions
> or revert the original change. Simple and robust policy, isn't
> it?
>
> > > Please apply Steve's fix, fix it yourself or revert the
> > > changes that regressed printk().
> >
> > I thought Steve's patch was just a RFC thing, is it really
> > something that everyone wants to see applied?
>
> You mean the adding of an API to flush buffered output when
> that's the desired outcome? Why the heck should we *not* want
> that? Either I'm the weird one or you are being difficult ;-)

The API might be better as a global flag
not a per-site flush.

Maybe printk_is_buffered(true/false)



--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


gregkh at linuxfoundation

Jun 16, 2012, 8:38 AM

Post #14 of 44 (867 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Sat, Jun 16, 2012 at 05:51:27AM -0700, Joe Perches wrote:
> On Sat, 2012-06-16 at 08:59 +0200, Ingo Molnar wrote:
> > * Greg Kroah-Hartman <gregkh [at] linuxfoundation> wrote:
> > > On Fri, Jun 15, 2012 at 02:04:30PM +0200, Ingo Molnar wrote:
> > > > These printk's are useful, are used for a specific (albeit
> > > > limited) purpose and were and continue to be useful in that
> > > > role.
> > > >
> > > > The changes Steve bisected to broke this use of printk().
> > >
> > > And note, fixed others :)
> >
> > Sorry, the "we fix some bugs and introduce others" stance is not
> > a valid response to a regression. Either fix *all* regressions
> > or revert the original change. Simple and robust policy, isn't
> > it?
> >
> > > > Please apply Steve's fix, fix it yourself or revert the
> > > > changes that regressed printk().
> > >
> > > I thought Steve's patch was just a RFC thing, is it really
> > > something that everyone wants to see applied?
> >
> > You mean the adding of an API to flush buffered output when
> > that's the desired outcome? Why the heck should we *not* want
> > that? Either I'm the weird one or you are being difficult ;-)
>
> The API might be better as a global flag
> not a per-site flush.
>
> Maybe printk_is_buffered(true/false)

Hm, that sounds a bit better, and I thin it would solve the timestamp
problem that the proposed patch has, right? We would then just
timestamp on a new line, as we should "know" when that happens?

Steven, do you like this idea better?

thanks,

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


gregkh at linuxfoundation

Jun 16, 2012, 8:40 AM

Post #15 of 44 (866 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Sat, Jun 16, 2012 at 08:59:03AM +0200, Ingo Molnar wrote:
>
> * Greg Kroah-Hartman <gregkh [at] linuxfoundation> wrote:
>
> > On Fri, Jun 15, 2012 at 02:04:30PM +0200, Ingo Molnar wrote:
> > >
> > > * Greg Kroah-Hartman <gregkh [at] linuxfoundation> wrote:
> > >
> > > > On Fri, Jun 15, 2012 at 12:22:33PM +0800, Fengguang Wu wrote:
> > > > > > I actually would like to make these more compact. As all my test box
> > > > > > consoles go through serial ports, just booting through this takes more
> > > > > > time the the compile itself.
> > > > >
> > > > > The tests took 23 seconds boot time on one kernel:
> > > > >
> > > > > [ 0.152934] Testing tracer nop: PASSED
> > > > > ...1577 lines total...
> > > > > [ 23.206550] Testing kprobe tracing: OK
> > > > >
> > > > > And 135 seconds in another bloated kernel:
> > > > >
> > > > > [ 115.396441] Testing event 9p_client_req: OK
> > > > > ...2545 lines total...
> > > > > [ 240.268783] Testing kprobe tracing: OK
> > > > >
> > > > > I'd appreciate if the boot time can be reduced. Because I'm doing
> > > > > kernel boot tests for *every single* commits.
> > > > >
> > > > > It may look insane amount of work, but it's still manageable: with 10
> > > > > kvm instances each take 1 minute to boot test a kernel, I can boot
> > > > > test 60*24*10=14400 kernels in one day. That's a rather big number.
> > > > > That allows me to run more cpu/vm/io stress tests for each kernel :-)
> > > >
> > > > Do you really want to enable those tests for your test
> > > > kernels? Can they fail if we mess up other parts of the
> > > > kernel, or do they only test the tracing portions?
> > >
> > > These printk's are useful, are used for a specific (albeit
> > > limited) purpose and were and continue to be useful in that
> > > role.
> > >
> > > The changes Steve bisected to broke this use of printk().
> >
> > And note, fixed others :)
>
> Sorry, the "we fix some bugs and introduce others" stance is not
> a valid response to a regression. Either fix *all* regressions
> or revert the original change. Simple and robust policy, isn't
> it?

You are right, to a point :)

> > > Please apply Steve's fix, fix it yourself or revert the
> > > changes that regressed printk().
> >
> > I thought Steve's patch was just a RFC thing, is it really
> > something that everyone wants to see applied?
>
> You mean the adding of an API to flush buffered output when
> that's the desired outcome? Why the heck should we *not* want
> that? Either I'm the weird one or you are being difficult ;-)

Sorry, no, I was referring to the fact that he said he didn't really
like it because of the timestamp garbage in the line.

thanks,

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


gregkh at linuxfoundation

Jun 18, 2012, 4:03 PM

Post #16 of 44 (859 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Fri, Jun 15, 2012 at 07:53:35PM -0400, Steven Rostedt wrote:
> On Fri, 2012-06-15 at 16:13 -0700, Greg Kroah-Hartman wrote:
>
> > > Please apply Steve's fix, fix it yourself or revert the changes that
> > > regressed printk().
> >
> > I thought Steve's patch was just a RFC thing, is it really something
> > that everyone wants to see applied?
>
> It was, and still is, an RFC. I'd like to fix the double printing of the
> time stamps as well.
>
> It was really a compromise, as the new printk() is a serious
> functionality change. Even though I mostly use trace_printk(), there are
> still times that I like to use printk in some hot spots. For example I
> sometimes to do:
>
> printk("a");
> some_code();
> printk("b");
> more_code();
> printk("c");
> continued_code();
> [etc]
>
>
> And watch a stream of 'abcabcabc...' and see where finally something
> causes the machine to triple fault and reboot.

Yeah, that's not good, but note that because of this change, other
things that were failing are now working properly, we really can't have
one without the other here :(

> Because the bug would cause a triple fault, there would be no time to
> recover data from trace_printk(). But as the code is quite hot, my use
> of printk is to be as small as possible and with no new lines.
>
> But now this method is gone. Not to mention, digging through the complex
> maze of the new printk, I realize that it's not optimize for speed at
> all. But printing to the serial console makes it not that big of a deal.
>
> I have patches that just force printk() to be early_printk(), and in
> fact, we have in the -rt patch this:
>
> http://git.kernel.org/?p=linux/kernel/git/rt/linux-stable-rt.git;a=blobdiff;f=kernel/printk.c;h=5a172f9e5027b7416a82e54dfc29afbda71296ee;hp=c4426061e228c252e226feb67193d80cdba3af5b;hb=865407ef06e61c97cdd9091082ed8038c801f535;hpb=c09d1c02743a7d2df13574d93dea9f21ccf02560
>
> I had my own patch that did pretty much the same thing, and I was very
> happy to see that Ingo had the same mind set.
>
> Actually, I think that patch really should go mainline, and give others
> some of the luxury that us -rt folks enjoy.

That would be good.

> But back to this patch. I was irritated that we blamed the wrong code
> because the printk functionality changed. And instead of writing some
> drastic changes that would be controversial, I suggested a
> 'printk_flush()' that would work similar to a fflush(). Yeah, buffering
> is good and lets lines fit together, but there's times where getting the
> partial line out to the screen is more important that keeping it
> together.

I agree, it's frustrating to go down the wrong path, sorry about that.

> If other printks were interleaved and it didn't crash, we wouldn't care
> (or even notice). But if it did crash, I'll even argue seeing the
> interleaved printks would provide a hint to why it crashed.

Ok, so what do you want to do here? Fix up your RFC patch to not have
the printk stamps? Or something like the above rt patch?

thanks,

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


rostedt at goodmis

Jun 18, 2012, 6:28 PM

Post #17 of 44 (853 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Mon, 2012-06-18 at 16:03 -0700, Greg Kroah-Hartman wrote:

> > Actually, I think that patch really should go mainline, and give others
> > some of the luxury that us -rt folks enjoy.
>
> That would be good.

Maybe I'll package that up if Ingo has no objections.


> > If other printks were interleaved and it didn't crash, we wouldn't care
> > (or even notice). But if it did crash, I'll even argue seeing the
> > interleaved printks would provide a hint to why it crashed.
>
> Ok, so what do you want to do here? Fix up your RFC patch to not have
> the printk stamps? Or something like the above rt patch?
>

I'm fine with adding a printk_flush() or even as Joe suggested, making a
pr_flush(), or printk(KERN_FLUSH "..." that will just do it. Maybe make
that default with a switch.

As to get rid of the time stamp issue, that may take a bit, as the code
goes through layers where this information needs to be passed down. I
ran 'trace-cmd record -p function_graph -g printk' to see how the flow
works, mounted an NFS filesystem (to force a printk) and this is what I
got:

printk() {
vprintk_emit() {
_raw_spin_lock();
log_store();
console_trylock() {
down_trylock() {
_raw_spin_lock_irqsave();
_raw_spin_unlock_irqrestore();
}
}
console_unlock() {
_raw_spin_lock_irqsave();
log_from_idx();
msg_print_text() {
print_prefix();
print_prefix();
}
log_next();
serial8250_console_write() {

What's missing (as are all lib/ functions are from function tracing) is
the first call to vscnprintf() to get the string and all its args
together.

Then the '\n' is checked as well as the '<X>' notations. The prefix is
set for everything but '<c>' which makes sense, as you don't want to add
a prefix to a KERN_CONT line. But this 'prefix' variable just changes
the logic, it doesn't really prevent the prefix from appearing as we
will see.

Now things are a bit different if there's a newline or not. In this
trace, the newline was there, but first lets look at what happens when
there's no newline.

It checks this static variable called 'cont_len' which is set if we
buffered the last line. cont_task is set to the task it buffered too. If
cont_len is set but cont_task does not equal the current task, we call
this log_store() thingy. Which is the next thing that would have
happened if we did have a newline.

Now if cont_len is zero, it updates the current cont_level and
cont_task. Now it copies the printk into the cont_buf, which too is
static.

Finally, console_trylock() followed by console_unlock() which is done
regardless if there was a newline or not.

The console_unlock() is where the magic happens. Remember that
log_store() thingy, that's what is going to be printed. But remember, it
only was called if we had a newline, or we had buffered data and the
current task is different. But the current printk line is still located
in that cont_buf variable which happens to be static for vprintk_emit()
and not available elsewhere.

Once data is sent to the log_store() it always prints this prefix. This
is why my printk_flush() caused the next (<c>) line to have a timestamp
too. Because when that got flushed out, it got a timestamp on it, as all
data that goes to the console gets a timestamp. The only reason it
doesn't in the current method, is that it buffers it locally in the
cont_buf[] array, before it sends it out to the console. When it does
send it out to the console, it sends the entire buffer.

I forgot to mention what happens when the line has a newline, and
there's content in cont_buf[]. If the cont_task is the same as current,
it appends the cont_buf to the new data that is about to be printed, and
then sends that out to the log_store() which will get a timestamp at the
beginning of the line before the buffered data.

Oh, and one more thing. The vprintk_emit() strips the newline from the
text even if it had one. The msg_print_text() called by console_unlock()
and a bunch of syslog callers, adds the '\n' back. This is to all text
going out. My patch added a msg flag to say "don't do that!" We also
need a flag to skip adding the timestamp, but that looks even more
complex, as the timestamp is added by print_prefix() also called by
msg_print_text() (three callers) and there's no comments to what the
frick it's doing or why. We need a way to stop that from happening.


-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


mingo at kernel

Jun 20, 2012, 5:25 AM

Post #18 of 44 (855 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

* Steven Rostedt <rostedt [at] goodmis> wrote:

> On Mon, 2012-06-18 at 16:03 -0700, Greg Kroah-Hartman wrote:
>
> > > Actually, I think that patch really should go mainline, and give others
> > > some of the luxury that us -rt folks enjoy.
> >
> > That would be good.
>
> Maybe I'll package that up if Ingo has no objections.

No objection, but I see it as an independent improvement.

Please also make printk() more useful out of box and fix the
flushing bug ...

So mind re-sending the latest version of your printk flushing
fix? I'll apply it for v3.5-rc if other trees won't pick it up.

Thanks,

Ingo
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


gregkh at linuxfoundation

Jun 21, 2012, 10:13 AM

Post #19 of 44 (849 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Wed, Jun 20, 2012 at 02:25:49PM +0200, Ingo Molnar wrote:
>
> * Steven Rostedt <rostedt [at] goodmis> wrote:
>
> > On Mon, 2012-06-18 at 16:03 -0700, Greg Kroah-Hartman wrote:
> >
> > > > Actually, I think that patch really should go mainline, and give others
> > > > some of the luxury that us -rt folks enjoy.
> > >
> > > That would be good.
> >
> > Maybe I'll package that up if Ingo has no objections.
>
> No objection, but I see it as an independent improvement.
>
> Please also make printk() more useful out of box and fix the
> flushing bug ...
>
> So mind re-sending the latest version of your printk flushing
> fix? I'll apply it for v3.5-rc if other trees won't pick it up.

I'll be glad to pick it up, just make it work properly :)

thanks,

greg k-h
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


rostedt at goodmis

Jun 21, 2012, 10:41 AM

Post #20 of 44 (849 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, 2012-06-21 at 10:13 -0700, Greg Kroah-Hartman wrote:

> > So mind re-sending the latest version of your printk flushing
> > fix? I'll apply it for v3.5-rc if other trees won't pick it up.
>
> I'll be glad to pick it up, just make it work properly :)

I'm playing around with making a KERN_FLUSH "<f>". Think that's a better
approach?

-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


joe at perches

Jun 21, 2012, 11:17 AM

Post #21 of 44 (846 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, 2012-06-21 at 13:41 -0400, Steven Rostedt wrote:
> On Thu, 2012-06-21 at 10:13 -0700, Greg Kroah-Hartman wrote:
>
> > > So mind re-sending the latest version of your printk flushing
> > > fix? I'll apply it for v3.5-rc if other trees won't pick it up.
> >
> > I'll be glad to pick it up, just make it work properly :)
>
> I'm playing around with making a KERN_FLUSH "<f>". Think that's a better
> approach?

I don't think that's better. I think it's worse
because it intermixes the idea of a kernel message
logging level with a specific functionality to
emit any fragmentary message immediately.

I think a global setting via a some functions like:

(printk private variable)
bool printk_buffered = true;

bool printk_set_buffering(bool enable)
{
bool old_state = printk_buffered;
printk_buffered = enable;

return old_state;
}

and maybe:

bool printk_get_buffering(void)
{
return printk_buffered;
}

would be better because the non-buffered use should
really be pretty isolated to last_breath type output
and to pretty isolated cases like your long running
tests.

A separate printk_flush() function if really necessary
but sprinking a bunch of printk_flush() calls seems
wasteful.


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


joe at perches

Jun 21, 2012, 11:22 AM

Post #22 of 44 (846 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, 2012-06-21 at 11:17 -0700, Joe Perches wrote:
> bool printk_set_buffering(bool enable)
> {
> bool old_state = printk_buffered;
> printk_buffered = enable;

I suppose that should really be a counter
with an atomic inc/dec.


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


rostedt at goodmis

Jun 21, 2012, 11:29 AM

Post #23 of 44 (851 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, 2012-06-21 at 11:17 -0700, Joe Perches wrote:
> On Thu, 2012-06-21 at 13:41 -0400, Steven Rostedt wrote:
> > On Thu, 2012-06-21 at 10:13 -0700, Greg Kroah-Hartman wrote:
> >
> > > > So mind re-sending the latest version of your printk flushing
> > > > fix? I'll apply it for v3.5-rc if other trees won't pick it up.
> > >
> > > I'll be glad to pick it up, just make it work properly :)
> >
> > I'm playing around with making a KERN_FLUSH "<f>". Think that's a better
> > approach?
>
> I don't think that's better. I think it's worse
> because it intermixes the idea of a kernel message
> logging level with a specific functionality to
> emit any fragmentary message immediately.

Are you using a 50 char width terminal?

>
> I think a global setting via a some functions like:
>
> (printk private variable)
> bool printk_buffered = true;
>
> bool printk_set_buffering(bool enable)
> {
> bool old_state = printk_buffered;
> printk_buffered = enable;
>
> return old_state;
> }
>
> and maybe:
>
> bool printk_get_buffering(void)
> {
> return printk_buffered;
> }
>
> would be better because the non-buffered use should
> really be pretty isolated to last_breath type output
> and to pretty isolated cases like your long running
> tests.
>
> A separate printk_flush() function if really necessary
> but sprinking a bunch of printk_flush() calls seems
> wasteful.

A global buffering disable may cause other things that are printed to be
screwed up. Something that actually expects to be buffered. Which is why
I'm leaning to the log level version. As it keeps it contained to the
actual printk that does not want buffering.

Or perhaps have printk_flush() become a new printk. That is,
printk_flush("this does not buffer").

-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


joe at perches

Jun 21, 2012, 11:39 AM

Post #24 of 44 (847 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, 2012-06-21 at 14:29 -0400, Steven Rostedt wrote:
> On Thu, 2012-06-21 at 11:17 -0700, Joe Perches wrote:
> > On Thu, 2012-06-21 at 13:41 -0400, Steven Rostedt wrote:
[]
> > > I'm playing around with making a KERN_FLUSH "<f>". Think that's a better
> > > approach?
> >
> > I don't think that's better. I think it's worse
> > because it intermixes the idea of a kernel message
> > logging level with a specific functionality to
> > emit any fragmentary message immediately.
>
> Are you using a 50 char width terminal?

Nope. Just an old habit.

> >
> > I think a global setting via a some functions like:
> >
> > (printk private variable)
> > bool printk_buffered = true;
> >
> > bool printk_set_buffering(bool enable)
> > {
> > bool old_state = printk_buffered;
> > printk_buffered = enable;
> >
> > return old_state;
> > }
> >
> > and maybe:
> >
> > bool printk_get_buffering(void)
> > {
> > return printk_buffered;
> > }
> >
> > would be better because the non-buffered use should
> > really be pretty isolated to last_breath type output
> > and to pretty isolated cases like your long running
> > tests.
> >
> > A separate printk_flush() function if really necessary
> > but sprinkling a bunch of printk_flush() calls seems
> > wasteful.
>
> A global buffering disable may cause other things that are printed to be
> screwed up.

After Kay's deferral patch (an actual improvement), lots
of output could have been changed. Turning off buffering
would simply revert to pre 3.5 behavior. I don't think
that's a significant issue.

> Something that actually expects to be buffered.

There is nothing today that _expects_ buffering or is
guaranteed non-buffered.

The locations that benefit from non-buffering are few
and isolated.

> Or perhaps have printk_flush() become a new printk. That is,
> printk_flush("this does not buffer").

Yuck.

Then there'd be all the likely variants for
prefix [pr|dev|netdev]_<level>[_once|_ratelimited] postfix
too.


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/


rostedt at goodmis

Jun 21, 2012, 11:49 AM

Post #25 of 44 (847 views)
Permalink
Re: [PATCH] printk: Add printk_flush() to force buffered text to console [In reply to]

On Thu, 2012-06-21 at 11:39 -0700, Joe Perches wrote:

> > A global buffering disable may cause other things that are printed to be
> > screwed up.
>
> After Kay's deferral patch (an actual improvement), lots
> of output could have been changed. Turning off buffering
> would simply revert to pre 3.5 behavior. I don't think
> that's a significant issue.

But prints that actually require buffering disabled (like the one I'm
using) does so because it may be testing something that may crash the
system. On SMP, that crash could cause garbled output. Yes, it is pre
3.5 behavior, but why have garbled output on the crash when Kay went
through all that effort to have it work.


>
> > Something that actually expects to be buffered.
>
> There is nothing today that _expects_ buffering or is
> guaranteed non-buffered.

I'm not saying there is. But if the new buffering system is here, then
there may be something that will _expect_ buffering to be enabled.

>
> The locations that benefit from non-buffering are few
> and isolated.

Which means we can use individual flushing.

>
> > Or perhaps have printk_flush() become a new printk. That is,
> > printk_flush("this does not buffer").
>
> Yuck.
>
> Then there'd be all the likely variants for
> prefix [pr|dev|netdev]_<level>[_once|_ratelimited] postfix
> too.

Actually, I'm starting to lean back to my original patch, and stick a
pr_flush() in there. As it basically just acts like a barrier. "Make
sure the output I printed actually gets out to the console before I
continue".

-- Steve


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo [at] vger
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

First page Previous page 1 2 Next page Last page  View All Linux kernel RSS feed   Index | Next | Previous | View Threaded
 
 


Interested in having your list archived? Contact Gossamer Threads
 
  Web Applications & Managed Hosting Powered by Gossamer Threads Inc.