* Weird character in kernel message @ 2014-09-14 5:09 Markus Trippelsdorf 2014-09-14 5:54 ` Markus Trippelsdorf 0 siblings, 1 reply; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-14 5:09 UTC (permalink / raw) To: linux-kernel Just noticed this today: Sep 14 06:51:57 x4 kernel: [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec in hex: 20 01 34 43 45 3A 20 Must be a recent regression. -- Markus ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: Weird character in kernel message 2014-09-14 5:09 Weird character in kernel message Markus Trippelsdorf @ 2014-09-14 5:54 ` Markus Trippelsdorf 2014-09-14 9:13 ` Geert Uytterhoeven 0 siblings, 1 reply; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-14 5:54 UTC (permalink / raw) To: linux-kernel; +Cc: Jan Kara, Steven Rostedt On 2014.09.14 at 07:09 +0200, Markus Trippelsdorf wrote: > Just noticed this today: > > Sep 14 06:51:57 x4 kernel: [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > in hex: > 20 01 34 43 45 3A 20 > > Must be a recent regression. It looks like a combination of commit 504d58745c9ca and commit 458df9fd4815b causes the issue. 458df9fd4815b changed the loglevel of printk_deferred to a hardcoded KERN_WARNING. And 504d58745c9ca changed the printk in kernel/time/clockevents.c to printk_deferred. But now the KERN_WARNING loglevel of printk_deferred in kernel/time/clockevents.c is redundant and responsible for the weird 01 34 character combination (KERN_SOH "4"). -- Markus ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: Weird character in kernel message 2014-09-14 5:54 ` Markus Trippelsdorf @ 2014-09-14 9:13 ` Geert Uytterhoeven 2014-09-15 16:37 ` Markus Trippelsdorf 0 siblings, 1 reply; 33+ messages in thread From: Geert Uytterhoeven @ 2014-09-14 9:13 UTC (permalink / raw) To: Markus Trippelsdorf; +Cc: linux-kernel, Jan Kara, Steven Rostedt On Sun, Sep 14, 2014 at 7:54 AM, Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > On 2014.09.14 at 07:09 +0200, Markus Trippelsdorf wrote: >> Just noticed this today: >> >> Sep 14 06:51:57 x4 kernel: [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec >> >> in hex: >> 20 01 34 43 45 3A 20 >> >> Must be a recent regression. > > It looks like a combination of commit 504d58745c9ca and commit > 458df9fd4815b causes the issue. > 458df9fd4815b changed the loglevel of printk_deferred to a hardcoded > KERN_WARNING. And 504d58745c9ca changed the printk in > kernel/time/clockevents.c to printk_deferred. > But now the KERN_WARNING loglevel of printk_deferred in > kernel/time/clockevents.c is redundant and responsible for the weird > 01 34 character combination (KERN_SOH "4"). vprintk_emit() has: if (in_sched) text_len = scnprintf(text, sizeof(textbuf), KERN_WARNING "[sched_delayed] "); text_len += vscnprintf(text + text_len, sizeof(textbuf) - text_len, fmt, args); Hence if in_sched, "[sched_delayed] " is inserted before the printed message. As most printed messages have a KERN_* prefix, this prefix now ends up in the middle of the message, causing the issue. A simple solution is to print a newline after the "[sched_delayed]", but this will break the line. Better, but more complicated, would be to remove the KERN_* prefix (if it exists) from the next message if in_sched is set. Gr{oetje,eeting}s, Geert -- Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org In personal conversations with technical people, I call myself a hacker. But when I'm talking to journalists I just say "programmer" or something like that. -- Linus Torvalds ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: Weird character in kernel message 2014-09-14 9:13 ` Geert Uytterhoeven @ 2014-09-15 16:37 ` Markus Trippelsdorf 2014-09-16 10:55 ` Jan Kara 0 siblings, 1 reply; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-15 16:37 UTC (permalink / raw) To: Geert Uytterhoeven; +Cc: linux-kernel, Jan Kara, Steven Rostedt, Andrew Morton On 2014.09.14 at 11:13 +0200, Geert Uytterhoeven wrote: > On Sun, Sep 14, 2014 at 7:54 AM, Markus Trippelsdorf > <markus@trippelsdorf.de> wrote: > > On 2014.09.14 at 07:09 +0200, Markus Trippelsdorf wrote: > >> Just noticed this today: > >> > >> Sep 14 06:51:57 x4 kernel: [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > >> > >> in hex: > >> 20 01 34 43 45 3A 20 > >> > >> Must be a recent regression. > > > > It looks like a combination of commit 504d58745c9ca and commit > > 458df9fd4815b causes the issue. > > 458df9fd4815b changed the loglevel of printk_deferred to a hardcoded > > KERN_WARNING. And 504d58745c9ca changed the printk in > > kernel/time/clockevents.c to printk_deferred. > > But now the KERN_WARNING loglevel of printk_deferred in > > kernel/time/clockevents.c is redundant and responsible for the weird > > 01 34 character combination (KERN_SOH "4"). > > vprintk_emit() has: > > if (in_sched) > text_len = scnprintf(text, sizeof(textbuf), > KERN_WARNING "[sched_delayed] "); > > text_len += vscnprintf(text + text_len, > sizeof(textbuf) - text_len, fmt, args); > > Hence if in_sched, "[sched_delayed] " is inserted before the printed > message. As most printed messages have a KERN_* prefix, this > prefix now ends up in the middle of the message, causing the issue. > > A simple solution is to print a newline after the "[sched_delayed]", but > this will break the line. > > Better, but more complicated, would be to remove the KERN_* prefix > (if it exists) from the next message if in_sched is set. Or just get rid of the "[sched_delayed] " thing. Does it really convey useful information to the user? diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 1ce770687ea8..b13c8650a751 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1680,12 +1680,8 @@ asmlinkage int vprintk_emit(int facility, int level, * The printf needs to come first; we need the syslog * prefix which might be passed-in as a parameter. */ - if (in_sched) - text_len = scnprintf(text, sizeof(textbuf), - KERN_WARNING "[sched_delayed] "); - text_len += vscnprintf(text + text_len, - sizeof(textbuf) - text_len, fmt, args); + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); /* mark and strip a trailing newline */ if (text_len && text[text_len-1] == '\n') { -- Markus ^ permalink raw reply related [flat|nested] 33+ messages in thread
* Re: Weird character in kernel message 2014-09-15 16:37 ` Markus Trippelsdorf @ 2014-09-16 10:55 ` Jan Kara 2014-09-16 14:42 ` [PATCH] printk: git rid of [sched_delayed] message for printk_deferred Markus Trippelsdorf 0 siblings, 1 reply; 33+ messages in thread From: Jan Kara @ 2014-09-16 10:55 UTC (permalink / raw) To: Markus Trippelsdorf Cc: Geert Uytterhoeven, linux-kernel, Jan Kara, Steven Rostedt, Andrew Morton On Mon 15-09-14 18:37:40, Markus Trippelsdorf wrote: > On 2014.09.14 at 11:13 +0200, Geert Uytterhoeven wrote: > > On Sun, Sep 14, 2014 at 7:54 AM, Markus Trippelsdorf > > <markus@trippelsdorf.de> wrote: > > > On 2014.09.14 at 07:09 +0200, Markus Trippelsdorf wrote: > > >> Just noticed this today: > > >> > > >> Sep 14 06:51:57 x4 kernel: [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > >> > > >> in hex: > > >> 20 01 34 43 45 3A 20 > > >> > > >> Must be a recent regression. > > > > > > It looks like a combination of commit 504d58745c9ca and commit > > > 458df9fd4815b causes the issue. > > > 458df9fd4815b changed the loglevel of printk_deferred to a hardcoded > > > KERN_WARNING. And 504d58745c9ca changed the printk in > > > kernel/time/clockevents.c to printk_deferred. > > > But now the KERN_WARNING loglevel of printk_deferred in > > > kernel/time/clockevents.c is redundant and responsible for the weird > > > 01 34 character combination (KERN_SOH "4"). > > > > vprintk_emit() has: > > > > if (in_sched) > > text_len = scnprintf(text, sizeof(textbuf), > > KERN_WARNING "[sched_delayed] "); > > > > text_len += vscnprintf(text + text_len, > > sizeof(textbuf) - text_len, fmt, args); > > > > Hence if in_sched, "[sched_delayed] " is inserted before the printed > > message. As most printed messages have a KERN_* prefix, this > > prefix now ends up in the middle of the message, causing the issue. > > > > A simple solution is to print a newline after the "[sched_delayed]", but > > this will break the line. > > > > Better, but more complicated, would be to remove the KERN_* prefix > > (if it exists) from the next message if in_sched is set. > > Or just get rid of the "[sched_delayed] " thing. Does it really convey > useful information to the user? Yeah, you're right the prefix isn't that useful IMHO. So feel free to add: Acked-by: Jan Kara <jack@suse.cz> Honza > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 1ce770687ea8..b13c8650a751 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -1680,12 +1680,8 @@ asmlinkage int vprintk_emit(int facility, int level, > * The printf needs to come first; we need the syslog > * prefix which might be passed-in as a parameter. > */ > - if (in_sched) > - text_len = scnprintf(text, sizeof(textbuf), > - KERN_WARNING "[sched_delayed] "); > > - text_len += vscnprintf(text + text_len, > - sizeof(textbuf) - text_len, fmt, args); > + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); > > /* mark and strip a trailing newline */ > if (text_len && text[text_len-1] == '\n') { > > -- > Markus -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 33+ messages in thread
* [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 10:55 ` Jan Kara @ 2014-09-16 14:42 ` Markus Trippelsdorf 2014-09-16 15:13 ` Steven Rostedt 0 siblings, 1 reply; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-16 14:42 UTC (permalink / raw) To: Jan Kara; +Cc: Geert Uytterhoeven, linux-kernel, Steven Rostedt, Andrew Morton commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts the string "[sched_delayed] " before the actual message. However it doesn't take into account the KERN_* prefix of the message, that now ends up in the middle of the output: [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec Fix this by just getting rid of the "[sched_delayed] " scnprintf(). Acked-by: Jan Kara <jack@suse.cz> Signed-off-by: Markus Trippelsdorf <markus@trippelsdorf.de> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 1ce770687ea8..f85994b58934 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1680,12 +1680,7 @@ asmlinkage int vprintk_emit(int facility, int level, * The printf needs to come first; we need the syslog * prefix which might be passed-in as a parameter. */ - if (in_sched) - text_len = scnprintf(text, sizeof(textbuf), - KERN_WARNING "[sched_delayed] "); - - text_len += vscnprintf(text + text_len, - sizeof(textbuf) - text_len, fmt, args); + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); /* mark and strip a trailing newline */ if (text_len && text[text_len-1] == '\n') { -- Markus ^ permalink raw reply related [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 14:42 ` [PATCH] printk: git rid of [sched_delayed] message for printk_deferred Markus Trippelsdorf @ 2014-09-16 15:13 ` Steven Rostedt 2014-09-16 15:20 ` Markus Trippelsdorf 2014-09-16 20:35 ` Jan Kara 0 siblings, 2 replies; 33+ messages in thread From: Steven Rostedt @ 2014-09-16 15:13 UTC (permalink / raw) To: Markus Trippelsdorf Cc: Jan Kara, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On Tue, 16 Sep 2014 16:42:52 +0200 Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts > the string "[sched_delayed] " before the actual message. > However it doesn't take into account the KERN_* prefix of the message, > that now ends up in the middle of the output: > > [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > Fix this by just getting rid of the "[sched_delayed] " scnprintf(). I prefer the "[sched_delayed]" output. It lets us know that the output did not come out immediately, which is important sometimes during debugging. Otherwise it can confuse people, as printk is suppose to be a blocking write. Can we instead fix the bug instead of nuking the output? That is, move the KERN_* prefix before the "[sched_delayed]" message? I don't think it would be that hard. If you want, I'll write that patch (probably take me 20 minutes at most), but I'm just coming back from medical leave so I prefer not to. -- Steve > > Acked-by: Jan Kara <jack@suse.cz> > Signed-off-by: Markus Trippelsdorf <markus@trippelsdorf.de> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 1ce770687ea8..f85994b58934 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -1680,12 +1680,7 @@ asmlinkage int vprintk_emit(int facility, int level, > * The printf needs to come first; we need the syslog > * prefix which might be passed-in as a parameter. > */ > - if (in_sched) > - text_len = scnprintf(text, sizeof(textbuf), > - KERN_WARNING "[sched_delayed] "); > - > - text_len += vscnprintf(text + text_len, > - sizeof(textbuf) - text_len, fmt, args); > + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); > > /* mark and strip a trailing newline */ > if (text_len && text[text_len-1] == '\n') { ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 15:13 ` Steven Rostedt @ 2014-09-16 15:20 ` Markus Trippelsdorf 2014-09-16 19:14 ` Steven Rostedt 2014-09-16 20:35 ` Jan Kara 1 sibling, 1 reply; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-16 15:20 UTC (permalink / raw) To: Steven Rostedt Cc: Jan Kara, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On 2014.09.16 at 11:13 -0400, Steven Rostedt wrote: > On Tue, 16 Sep 2014 16:42:52 +0200 > Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > > > commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts > > the string "[sched_delayed] " before the actual message. > > However it doesn't take into account the KERN_* prefix of the message, > > that now ends up in the middle of the output: > > > > [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > > > Fix this by just getting rid of the "[sched_delayed] " scnprintf(). > > I prefer the "[sched_delayed]" output. It lets us know that the output > did not come out immediately, which is important sometimes during > debugging. Otherwise it can confuse people, as printk is suppose to be > a blocking write. > > Can we instead fix the bug instead of nuking the output? That is, move > the KERN_* prefix before the "[sched_delayed]" message? I don't think > it would be that hard. If you want, I'll write that patch (probably > take me 20 minutes at most), but I'm just coming back from medical > leave so I prefer not to. I'll leave it to you. This is just a cosmetic issue, so there's no need to fix this immediately. -- Markus ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 15:20 ` Markus Trippelsdorf @ 2014-09-16 19:14 ` Steven Rostedt 2014-09-16 19:17 ` Markus Trippelsdorf 0 siblings, 1 reply; 33+ messages in thread From: Steven Rostedt @ 2014-09-16 19:14 UTC (permalink / raw) To: Markus Trippelsdorf Cc: Jan Kara, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On Tue, 16 Sep 2014 17:20:46 +0200 Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > On 2014.09.16 at 11:13 -0400, Steven Rostedt wrote > I'll leave it to you. This is just a cosmetic issue, so there's no need > to fix this immediately. > Actually the fix is much simpler (I had to wait for the drugs to wear off before I noticed this ;-): >From 2a88421634bf7a5238b18d829c64f8fd59f12aab Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Red Hat)" <rostedt@goodmis.org> Date: Tue, 16 Sep 2014 15:08:24 -0400 Subject: [PATCH] timer: Remove redundant log level from printk_deferred() call printk_deferred() is only used in critical sections that is unsafe to call printk() directly, and these prints are for warnings only. They do not take a printk loglevel (KERN_*) in their formats. A KERN_WARNING is assumed and applied by the call itself. Cc: Jan Kara <jack@suse.cz> Cc: Thomas Gleixner <tglx@linutronix.de> Cc: stable@vger.kernel.org # 3.16+ Fixes: 504d58745c9c "timer: Fix lock inversion between hrtimer_bases.lock and scheduler locks" Signed-off-by: Steven Rostedt <rostedt@goodmis.org> --- kernel/time/clockevents.c | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/kernel/time/clockevents.c b/kernel/time/clockevents.c index 9c94c19f1305..0a7516e59610 100644 --- a/kernel/time/clockevents.c +++ b/kernel/time/clockevents.c @@ -146,8 +146,7 @@ static int clockevents_increase_min_delta(struct clock_event_device *dev) { /* Nothing to do if we already reached the limit */ if (dev->min_delta_ns >= MIN_DELTA_LIMIT) { - printk_deferred(KERN_WARNING - "CE: Reprogramming failure. Giving up\n"); + printk_deferred("CE: Reprogramming failure. Giving up\n"); dev->next_event.tv64 = KTIME_MAX; return -ETIME; } @@ -160,8 +159,7 @@ static int clockevents_increase_min_delta(struct clock_event_device *dev) if (dev->min_delta_ns > MIN_DELTA_LIMIT) dev->min_delta_ns = MIN_DELTA_LIMIT; - printk_deferred(KERN_WARNING - "CE: %s increased min_delta_ns to %llu nsec\n", + printk_deferred("CE: %s increased min_delta_ns to %llu nsec\n", dev->name ? dev->name : "?", (unsigned long long) dev->min_delta_ns); return 0; -- 1.8.1.4 ^ permalink raw reply related [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 19:14 ` Steven Rostedt @ 2014-09-16 19:17 ` Markus Trippelsdorf 2014-09-16 20:26 ` Steven Rostedt 0 siblings, 1 reply; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-16 19:17 UTC (permalink / raw) To: Steven Rostedt Cc: Jan Kara, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On 2014.09.16 at 15:14 -0400, Steven Rostedt wrote: > On Tue, 16 Sep 2014 17:20:46 +0200 > Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > > > On 2014.09.16 at 11:13 -0400, Steven Rostedt wrote > > I'll leave it to you. This is just a cosmetic issue, so there's no need > > to fix this immediately. > > > > Actually the fix is much simpler (I had to wait for the drugs to wear > off before I noticed this ;-): Well, the list is not complete: linux % git grep printk_deferred ... kernel/time/clockevents.c: printk_deferred(KERN_WARNING kernel/time/clockevents.c: printk_deferred(KERN_WARNING kernel/time/ntp.c: printk_deferred(KERN_ERR kernel/time/ntp.c: printk_deferred(KERN_WARNING kernel/time/ntp.c: printk_deferred(KERN_WARNING kernel/time/ntp.c: printk_deferred(KERN_ERR "hardpps: PPSJITTER: bad pulse\n"); kernel/time/timekeeping.c: printk_deferred(KERN_WARNING -- Markus ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 19:17 ` Markus Trippelsdorf @ 2014-09-16 20:26 ` Steven Rostedt 0 siblings, 0 replies; 33+ messages in thread From: Steven Rostedt @ 2014-09-16 20:26 UTC (permalink / raw) To: Markus Trippelsdorf Cc: Jan Kara, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On Tue, 16 Sep 2014 21:17:40 +0200 Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > On 2014.09.16 at 15:14 -0400, Steven Rostedt wrote: > > On Tue, 16 Sep 2014 17:20:46 +0200 > > Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > > > > > On 2014.09.16 at 11:13 -0400, Steven Rostedt wrote > > > I'll leave it to you. This is just a cosmetic issue, so there's no need > > > to fix this immediately. > > > > > > > Actually the fix is much simpler (I had to wait for the drugs to wear > > off before I noticed this ;-): > > Well, the list is not complete: Thanks! I'll update it. -- Steve > > linux % git grep printk_deferred > ... > kernel/time/clockevents.c: printk_deferred(KERN_WARNING > kernel/time/clockevents.c: printk_deferred(KERN_WARNING > kernel/time/ntp.c: printk_deferred(KERN_ERR > kernel/time/ntp.c: printk_deferred(KERN_WARNING > kernel/time/ntp.c: printk_deferred(KERN_WARNING > kernel/time/ntp.c: printk_deferred(KERN_ERR "hardpps: PPSJITTER: bad pulse\n"); > kernel/time/timekeeping.c: printk_deferred(KERN_WARNING > ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 15:13 ` Steven Rostedt 2014-09-16 15:20 ` Markus Trippelsdorf @ 2014-09-16 20:35 ` Jan Kara 2014-09-16 21:07 ` Steven Rostedt 1 sibling, 1 reply; 33+ messages in thread From: Jan Kara @ 2014-09-16 20:35 UTC (permalink / raw) To: Steven Rostedt Cc: Markus Trippelsdorf, Jan Kara, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On Tue 16-09-14 11:13:31, Steven Rostedt wrote: > On Tue, 16 Sep 2014 16:42:52 +0200 > Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > > > commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts > > the string "[sched_delayed] " before the actual message. > > However it doesn't take into account the KERN_* prefix of the message, > > that now ends up in the middle of the output: > > > > [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > > > Fix this by just getting rid of the "[sched_delayed] " scnprintf(). > > I prefer the "[sched_delayed]" output. It lets us know that the output > did not come out immediately, which is important sometimes during > debugging. Otherwise it can confuse people, as printk is suppose to be > a blocking write. This is a common misconception about printk. It isn't a blocking write for ten years or more. If there happens to be someone else printing to console, the difference between printk() and printk_deferred() is marginal - it used to be bigger when scheduler had its own buffer but these days message is inserted in the kernel ring buffer immediately. That's why I don't think the prefix is useful anymore. > Can we instead fix the bug instead of nuking the output? That is, move > the KERN_* prefix before the "[sched_delayed]" message? I don't think > it would be that hard. If you want, I'll write that patch (probably > take me 20 minutes at most), but I'm just coming back from medical > leave so I prefer not to. Glad to see you back! I'm not opposed to moving the prefix but it doesn't seem worth the effort... Honza > > Acked-by: Jan Kara <jack@suse.cz> > > Signed-off-by: Markus Trippelsdorf <markus@trippelsdorf.de> > > > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > > index 1ce770687ea8..f85994b58934 100644 > > --- a/kernel/printk/printk.c > > +++ b/kernel/printk/printk.c > > @@ -1680,12 +1680,7 @@ asmlinkage int vprintk_emit(int facility, int level, > > * The printf needs to come first; we need the syslog > > * prefix which might be passed-in as a parameter. > > */ > > - if (in_sched) > > - text_len = scnprintf(text, sizeof(textbuf), > > - KERN_WARNING "[sched_delayed] "); > > - > > - text_len += vscnprintf(text + text_len, > > - sizeof(textbuf) - text_len, fmt, args); > > + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); > > > > /* mark and strip a trailing newline */ > > if (text_len && text[text_len-1] == '\n') { > -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 20:35 ` Jan Kara @ 2014-09-16 21:07 ` Steven Rostedt 2014-09-16 21:22 ` Jan Kara 0 siblings, 1 reply; 33+ messages in thread From: Steven Rostedt @ 2014-09-16 21:07 UTC (permalink / raw) To: Jan Kara Cc: Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On Tue, 16 Sep 2014 22:35:10 +0200 Jan Kara <jack@suse.cz> wrote: > On Tue 16-09-14 11:13:31, Steven Rostedt wrote: > > On Tue, 16 Sep 2014 16:42:52 +0200 > > Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > > > > > commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts > > > the string "[sched_delayed] " before the actual message. > > > However it doesn't take into account the KERN_* prefix of the message, > > > that now ends up in the middle of the output: > > > > > > [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > > > > > Fix this by just getting rid of the "[sched_delayed] " scnprintf(). > > > > I prefer the "[sched_delayed]" output. It lets us know that the output > > did not come out immediately, which is important sometimes during > > debugging. Otherwise it can confuse people, as printk is suppose to be > > a blocking write. > This is a common misconception about printk. It isn't a blocking write > for ten years or more. If there happens to be someone else printing to > console, the difference between printk() and printk_deferred() is > marginal - it used to be bigger when scheduler had its own buffer but these > days message is inserted in the kernel ring buffer immediately. That's why > I don't think the prefix is useful anymore. For the most part it's a blocking write. Yeah, if another CPU is writing, it wont be a blocking write, but it usually is, I know I depend on it (when I'm debugging, I usually don't have contention between CPUs). The important part is that they are done in order. A delayed print, wont be in order with other printks. That is still a crucial difference. > > > Can we instead fix the bug instead of nuking the output? That is, move > > the KERN_* prefix before the "[sched_delayed]" message? I don't think > > it would be that hard. If you want, I'll write that patch (probably > > take me 20 minutes at most), but I'm just coming back from medical > > leave so I prefer not to. > Glad to see you back! I'm not opposed to moving the prefix but it doesn't > seem worth the effort... I don't know. Since all the printk_deferred() are KERN_WARNING anyway, we can at least clean them up, and remove the extra loglevel. -- Steve ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 21:07 ` Steven Rostedt @ 2014-09-16 21:22 ` Jan Kara 2014-09-16 21:33 ` Steven Rostedt 0 siblings, 1 reply; 33+ messages in thread From: Jan Kara @ 2014-09-16 21:22 UTC (permalink / raw) To: Steven Rostedt Cc: Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On Tue 16-09-14 17:07:09, Steven Rostedt wrote: > On Tue, 16 Sep 2014 22:35:10 +0200 > Jan Kara <jack@suse.cz> wrote: > > > On Tue 16-09-14 11:13:31, Steven Rostedt wrote: > > > On Tue, 16 Sep 2014 16:42:52 +0200 > > > Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > > > > > > > commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts > > > > the string "[sched_delayed] " before the actual message. > > > > However it doesn't take into account the KERN_* prefix of the message, > > > > that now ends up in the middle of the output: > > > > > > > > [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > > > > > > > Fix this by just getting rid of the "[sched_delayed] " scnprintf(). > > > > > > I prefer the "[sched_delayed]" output. It lets us know that the output > > > did not come out immediately, which is important sometimes during > > > debugging. Otherwise it can confuse people, as printk is suppose to be > > > a blocking write. > > This is a common misconception about printk. It isn't a blocking write > > for ten years or more. If there happens to be someone else printing to > > console, the difference between printk() and printk_deferred() is > > marginal - it used to be bigger when scheduler had its own buffer but these > > days message is inserted in the kernel ring buffer immediately. That's why > > I don't think the prefix is useful anymore. > > For the most part it's a blocking write. Yeah, if another CPU is > writing, it wont be a blocking write, but it usually is, I know I > depend on it (when I'm debugging, I usually don't have contention > between CPUs). The important part is that they are done in order. A > delayed print, wont be in order with other printks. That is still a > crucial difference. printk_deffered() will be in order with other printks after your commit 458df9fd4815b47809875d57f42e16401674b621. Just printing to console itself will be delayed to the next timer interrupt. Or am I missing something? Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 21:22 ` Jan Kara @ 2014-09-16 21:33 ` Steven Rostedt 2014-09-17 14:18 ` Peter Zijlstra 0 siblings, 1 reply; 33+ messages in thread From: Steven Rostedt @ 2014-09-16 21:33 UTC (permalink / raw) To: Jan Kara Cc: Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton, Peter Zijlstra On Tue, 16 Sep 2014 23:22:50 +0200 Jan Kara <jack@suse.cz> wrote: > > For the most part it's a blocking write. Yeah, if another CPU is > > writing, it wont be a blocking write, but it usually is, I know I > > depend on it (when I'm debugging, I usually don't have contention > > between CPUs). The important part is that they are done in order. A > > delayed print, wont be in order with other printks. That is still a > > crucial difference. > printk_deffered() will be in order with other printks after your commit > 458df9fd4815b47809875d57f42e16401674b621. Just printing to console itself > will be delayed to the next timer interrupt. Or am I missing something? Hehe, you're right. I blame the meds for forgetting this. Yeah, my update will put the data in order. Thus I guess I agree with your assessment. We probably don't need the "sched_delayed" anymore. OK, you convinced me, but I still like to hear Peter's view on this before we commit it. For Markus's patch: Acked-by: Steven Rostedt <rostedt@goodmis.org> -- Steve ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-16 21:33 ` Steven Rostedt @ 2014-09-17 14:18 ` Peter Zijlstra 2014-09-17 14:22 ` Steven Rostedt 0 siblings, 1 reply; 33+ messages in thread From: Peter Zijlstra @ 2014-09-17 14:18 UTC (permalink / raw) To: Steven Rostedt Cc: Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Tue, Sep 16, 2014 at 05:33:28PM -0400, Steven Rostedt wrote: > > printk_deffered() will be in order with other printks after your commit > > 458df9fd4815b47809875d57f42e16401674b621. Just printing to console itself > > will be delayed to the next timer interrupt. Or am I missing something? > > Hehe, you're right. I blame the meds for forgetting this. > > Yeah, my update will put the data in order. Thus I guess I agree with > your assessment. We probably don't need the "sched_delayed" anymore. > > OK, you convinced me, but I still like to hear Peter's view on this > before we commit it. By not calling console_unlock() the messages will be 'delayed', as in, we'll not call console->write() and we'll not see them, etc.. So some form of [delayed] or whatnot seems to remain appropriate. I agree that the 'sched_' part has lived far beyond its relevance. ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-17 14:18 ` Peter Zijlstra @ 2014-09-17 14:22 ` Steven Rostedt 2014-09-17 22:36 ` Peter Zijlstra 0 siblings, 1 reply; 33+ messages in thread From: Steven Rostedt @ 2014-09-17 14:22 UTC (permalink / raw) To: Peter Zijlstra Cc: Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Wed, 17 Sep 2014 16:18:16 +0200 Peter Zijlstra <peterz@infradead.org> wrote: > On Tue, Sep 16, 2014 at 05:33:28PM -0400, Steven Rostedt wrote: > > > > printk_deffered() will be in order with other printks after your commit > > > 458df9fd4815b47809875d57f42e16401674b621. Just printing to console itself > > > will be delayed to the next timer interrupt. Or am I missing something? > > > > Hehe, you're right. I blame the meds for forgetting this. > > > > Yeah, my update will put the data in order. Thus I guess I agree with > > your assessment. We probably don't need the "sched_delayed" anymore. > > > > OK, you convinced me, but I still like to hear Peter's view on this > > before we commit it. > > By not calling console_unlock() the messages will be 'delayed', as in, > we'll not call console->write() and we'll not see them, etc.. > > So some form of [delayed] or whatnot seems to remain appropriate. > > I agree that the 'sched_' part has lived far beyond its relevance. But then we should add '[delayed]' if a CPU calls printk() while another CPU is printing, as printk() wont block in that case either, and the output will happen some later time. -- Steve ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-17 14:22 ` Steven Rostedt @ 2014-09-17 22:36 ` Peter Zijlstra 2014-09-18 0:31 ` Steven Rostedt 0 siblings, 1 reply; 33+ messages in thread From: Peter Zijlstra @ 2014-09-17 22:36 UTC (permalink / raw) To: Steven Rostedt Cc: Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Wed, Sep 17, 2014 at 10:22:55AM -0400, Steven Rostedt wrote: > On Wed, 17 Sep 2014 16:18:16 +0200 > Peter Zijlstra <peterz@infradead.org> wrote: > > By not calling console_unlock() the messages will be 'delayed', as in, > > we'll not call console->write() and we'll not see them, etc.. > > > > So some form of [delayed] or whatnot seems to remain appropriate. > > > > I agree that the 'sched_' part has lived far beyond its relevance. > > But then we should add '[delayed]' if a CPU calls printk() while > another CPU is printing, as printk() wont block in that case either, > and the output will happen some later time. You're over thinking this. You cannot (and we don't want to) know if it indeed got delayed, therefore it got delayed. ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-17 22:36 ` Peter Zijlstra @ 2014-09-18 0:31 ` Steven Rostedt 2014-09-18 17:34 ` Peter Zijlstra 0 siblings, 1 reply; 33+ messages in thread From: Steven Rostedt @ 2014-09-18 0:31 UTC (permalink / raw) To: Peter Zijlstra Cc: Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Thu, 18 Sep 2014 00:36:33 +0200 Peter Zijlstra <peterz@infradead.org> wrote: > On Wed, Sep 17, 2014 at 10:22:55AM -0400, Steven Rostedt wrote: > > On Wed, 17 Sep 2014 16:18:16 +0200 > > Peter Zijlstra <peterz@infradead.org> wrote: > > > > By not calling console_unlock() the messages will be 'delayed', as in, > > > we'll not call console->write() and we'll not see them, etc.. > > > > > > So some form of [delayed] or whatnot seems to remain appropriate. > > > > > > I agree that the 'sched_' part has lived far beyond its relevance. > > > > But then we should add '[delayed]' if a CPU calls printk() while > > another CPU is printing, as printk() wont block in that case either, > > and the output will happen some later time. > > You're over thinking this. You cannot (and we don't want to) know if it > indeed got delayed, therefore it got delayed. I totally didn't get what you wrote. We don't want to know if it got delayed, then the patch to remove that print seems correct. But how did it get delayed if we don't know if it got delayed and don't want to know? Are my meds still that strong??? -- Steve ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-18 0:31 ` Steven Rostedt @ 2014-09-18 17:34 ` Peter Zijlstra 2014-09-20 5:12 ` Jan Kara 0 siblings, 1 reply; 33+ messages in thread From: Peter Zijlstra @ 2014-09-18 17:34 UTC (permalink / raw) To: Steven Rostedt Cc: Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Wed, Sep 17, 2014 at 08:31:35PM -0400, Steven Rostedt wrote: > I totally didn't get what you wrote. :-) > We don't want to know if it got delayed, then the patch to remove that > print seems correct. Why would you not want to know that? Also was that the actual argument? Lemme go check the earlier emails -- I cannot find that argument in the first few emails. > But how did it get delayed if we don't know if it got delayed and > don't want to know? If you cannot prove something didn't happen it must have happened :-) > Are my meds still that strong??? Either that or I'm just incoherent, I get that while traveling. ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-18 17:34 ` Peter Zijlstra @ 2014-09-20 5:12 ` Jan Kara 2014-09-20 15:32 ` Steven Rostedt 2014-09-20 15:47 ` Peter Zijlstra 0 siblings, 2 replies; 33+ messages in thread From: Jan Kara @ 2014-09-20 5:12 UTC (permalink / raw) To: Peter Zijlstra Cc: Steven Rostedt, Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Thu 18-09-14 19:34:14, Peter Zijlstra wrote: > On Wed, Sep 17, 2014 at 08:31:35PM -0400, Steven Rostedt wrote: > > I totally didn't get what you wrote. > > :-) > > > We don't want to know if it got delayed, then the patch to remove that > > print seems correct. > > Why would you not want to know that? Also was that the actual argument? > Lemme go check the earlier emails -- I cannot find that argument in the > first few emails. Well, so what gets delayed is printing from kernel buffer to console. So this is the same as when you do printk() when console lock is taken by someone else. So it seems a bit strange to prepend [delayed] in some cases and not in others. Another question is what the [delayed] prefix would be useful for? If the message eventually gets printed to console I don't see why you would care it was printed few ms after it entered the kernel buffer (after all the time stamp before the line will be the time when it entered the kernel buffer). And if the kernel crashes in such a way that the message doesn't get printed, then bad luck but prefix in the kernel log buffer isn't going to make that any better :) This all feels like bikeshedding, I don't deeply care what gets done but I wanted to point out I don't really see a use for [delayed]... Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-20 5:12 ` Jan Kara @ 2014-09-20 15:32 ` Steven Rostedt 2014-09-20 16:34 ` Markus Trippelsdorf 2014-09-20 15:47 ` Peter Zijlstra 1 sibling, 1 reply; 33+ messages in thread From: Steven Rostedt @ 2014-09-20 15:32 UTC (permalink / raw) To: Jan Kara Cc: Peter Zijlstra, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Sat, 20 Sep 2014 07:12:24 +0200 Jan Kara <jack@suse.cz> wrote: > On Thu 18-09-14 19:34:14, Peter Zijlstra wrote: > > On Wed, Sep 17, 2014 at 08:31:35PM -0400, Steven Rostedt wrote: > > > I totally didn't get what you wrote. > > > > :-) > > > > > We don't want to know if it got delayed, then the patch to remove that > > > print seems correct. > > > > Why would you not want to know that? Also was that the actual argument? > > Lemme go check the earlier emails -- I cannot find that argument in the > > first few emails. > Well, so what gets delayed is printing from kernel buffer to console. > So this is the same as when you do printk() when console lock is taken by > someone else. So it seems a bit strange to prepend [delayed] in some cases > and not in others. > > Another question is what the [delayed] prefix would be useful for? If the > message eventually gets printed to console I don't see why you would care > it was printed few ms after it entered the kernel buffer (after all the > time stamp before the line will be the time when it entered the kernel > buffer). And if the kernel crashes in such a way that the message doesn't > get printed, then bad luck but prefix in the kernel log buffer isn't going > to make that any better :) > > This all feels like bikeshedding, I don't deeply care what gets done but I > wanted to point out I don't really see a use for [delayed]... > I pretty much agree with this assessment. I don't really care if there's a "[delayed]" message or not. I now agree that it isn't really that useful. Now what I do care about is that there's a bug with the current code, and the non bikeshed argument is how to fix this bug. The bug is that there's users of printk_deferred() that use KERN_WARN in the format. This ends up showing "[delayed]<whacky-characters> message". The fix needs to remove those whacky characters. There's three ways to fix this bug. 1) change printk() to check for whacky characters before adding "[delayed]" and either move them before it or remove them all together. 2) change all users of printk_deferred() to not add the KERN_WARN. 3) just get rid of adding the "[delayed]" message and make printk() itself a bit cleaner. I'm leaning towards #3 as I don't see the usefulness of that "[delayed]" message if there's other cases that can also delay printk. Remember, the code has been changed since the delayed message was added to make sure that the printk_deferred() message gets into the printk message in sequence of other printk's happening. The original way (when the "delayed" message was added) used its own buffer and would write to the log buffer at a later time, where the printk_deferred() could actually come out of sequence with other printk()s, and the "[delayed]" message would be useful for that case. But it's not useful anymore. #1 of above will just makes printk more complex, and being such a critical function which is already complex enough, I would like to not do so. #2 can fix the issue for now, until someone else adds a printk_deferred() with another KERN_WARN. Worse yet, someone may add one of the other KERN_* log levels and it will be ignored. Getting beyond the bikeshedding, there's a real bug that should be fixed. We just need to figure out what's the best way to do so. -- Steve ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-20 15:32 ` Steven Rostedt @ 2014-09-20 16:34 ` Markus Trippelsdorf 0 siblings, 0 replies; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-20 16:34 UTC (permalink / raw) To: Steven Rostedt Cc: Jan Kara, Peter Zijlstra, Geert Uytterhoeven, linux-kernel, Andrew Morton On 2014.09.20 at 11:32 -0400, Steven Rostedt wrote: > On Sat, 20 Sep 2014 07:12:24 +0200 > Jan Kara <jack@suse.cz> wrote: > > > On Thu 18-09-14 19:34:14, Peter Zijlstra wrote: > > > On Wed, Sep 17, 2014 at 08:31:35PM -0400, Steven Rostedt wrote: > > > > I totally didn't get what you wrote. > > > > > > :-) > > > > > > > We don't want to know if it got delayed, then the patch to remove that > > > > print seems correct. > > > > > > Why would you not want to know that? Also was that the actual argument? > > > Lemme go check the earlier emails -- I cannot find that argument in the > > > first few emails. > > Well, so what gets delayed is printing from kernel buffer to console. > > So this is the same as when you do printk() when console lock is taken by > > someone else. So it seems a bit strange to prepend [delayed] in some cases > > and not in others. > > > > Another question is what the [delayed] prefix would be useful for? If the > > message eventually gets printed to console I don't see why you would care > > it was printed few ms after it entered the kernel buffer (after all the > > time stamp before the line will be the time when it entered the kernel > > buffer). And if the kernel crashes in such a way that the message doesn't > > get printed, then bad luck but prefix in the kernel log buffer isn't going > > to make that any better :) > > > > This all feels like bikeshedding, I don't deeply care what gets done but I > > wanted to point out I don't really see a use for [delayed]... > > > > I pretty much agree with this assessment. I don't really care if > there's a "[delayed]" message or not. I now agree that it isn't really > that useful. Now what I do care about is that there's a bug with the > current code, and the non bikeshed argument is how to fix this bug. > > The bug is that there's users of printk_deferred() that use KERN_WARN > in the format. This ends up showing "[delayed]<whacky-characters> > message". The fix needs to remove those whacky characters. > > There's three ways to fix this bug. > > 1) change printk() to check for whacky characters before adding > "[delayed]" and either move them before it or remove them all together. > > 2) change all users of printk_deferred() to not add the KERN_WARN. > > 3) just get rid of adding the "[delayed]" message and make printk() > itself a bit cleaner. > > I'm leaning towards #3 as I don't see the usefulness of that > "[delayed]" message if there's other cases that can also delay printk. > Remember, the code has been changed since the delayed message was added > to make sure that the printk_deferred() message gets into the printk > message in sequence of other printk's happening. The original way (when > the "delayed" message was added) used its own buffer and would write to > the log buffer at a later time, where the printk_deferred() could > actually come out of sequence with other printk()s, and the "[delayed]" > message would be useful for that case. But it's not useful anymore. > > #1 of above will just makes printk more complex, and being such a > critical function which is already complex enough, I would like to not > do so. > > #2 can fix the issue for now, until someone else adds a > printk_deferred() with another KERN_WARN. Worse yet, someone may add > one of the other KERN_* log levels and it will be ignored. There are already two "printk_deferred(KERN_ERR" in kernel/time/ntp.c, that get currently transformed to KERN_WARN. > Getting beyond the bikeshedding, there's a real bug that should be > fixed. We just need to figure out what's the best way to do so. I agree that 3) is the best solution. Feel free to just add the description of why it now makes sense to the patch. -- Markus ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-20 5:12 ` Jan Kara 2014-09-20 15:32 ` Steven Rostedt @ 2014-09-20 15:47 ` Peter Zijlstra 2014-09-20 16:10 ` Joe Perches 2014-09-24 11:01 ` Jan Kara 1 sibling, 2 replies; 33+ messages in thread From: Peter Zijlstra @ 2014-09-20 15:47 UTC (permalink / raw) To: Jan Kara Cc: Steven Rostedt, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Sat, Sep 20, 2014 at 07:12:24AM +0200, Jan Kara wrote: > On Thu 18-09-14 19:34:14, Peter Zijlstra wrote: > > On Wed, Sep 17, 2014 at 08:31:35PM -0400, Steven Rostedt wrote: > > > I totally didn't get what you wrote. > > > > :-) > > > > > We don't want to know if it got delayed, then the patch to remove that > > > print seems correct. > > > > Why would you not want to know that? Also was that the actual argument? > > Lemme go check the earlier emails -- I cannot find that argument in the > > first few emails. > Well, so what gets delayed is printing from kernel buffer to console. > So this is the same as when you do printk() when console lock is taken by > someone else. So it seems a bit strange to prepend [delayed] in some cases > and not in others. The difference is that when someone else has the console lock, he guarantees it gets out. Whereas with the delayed thing it can take a virtual forever to get out. > Another question is what the [delayed] prefix would be useful for? If the > message eventually gets printed to console I don't see why you would care > it was printed few ms after it entered the kernel buffer (after all the > time stamp before the line will be the time when it entered the kernel > buffer). And if the kernel crashes in such a way that the message doesn't > get printed, then bad luck but prefix in the kernel log buffer isn't going > to make that any better :) > > This all feels like bikeshedding, I don't deeply care what gets done but I > wanted to point out I don't really see a use for [delayed]... Sure, I was just pointing out that those arguments had not been made. I think you're right, if you see the msg it obviously made it out. If you don't see it, you don't know either way. But a patch removing it _must_ make those arguments, it did not. On a whole, printk() is entirely useless for debugging these days, its far too fragile/unreliable to be taken seriously so I really don't care on that point either. ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-20 15:47 ` Peter Zijlstra @ 2014-09-20 16:10 ` Joe Perches 2014-09-20 16:30 ` Steven Rostedt 2014-09-20 18:01 ` Peter Zijlstra 2014-09-24 11:01 ` Jan Kara 1 sibling, 2 replies; 33+ messages in thread From: Joe Perches @ 2014-09-20 16:10 UTC (permalink / raw) To: Peter Zijlstra Cc: Jan Kara, Steven Rostedt, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Sat, 2014-09-20 at 17:47 +0200, Peter Zijlstra wrote: > On a whole, printk() is entirely useless for debugging these days, its > far too fragile/unreliable to be taken seriously so I really don't care > on that point either. That's unfortunate. Care to enumerate the issues that you believe make printk too fragile/unreliable for debugging? ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-20 16:10 ` Joe Perches @ 2014-09-20 16:30 ` Steven Rostedt 2014-09-20 18:08 ` Peter Zijlstra 2014-09-20 18:01 ` Peter Zijlstra 1 sibling, 1 reply; 33+ messages in thread From: Steven Rostedt @ 2014-09-20 16:30 UTC (permalink / raw) To: Joe Perches Cc: Peter Zijlstra, Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Sat, 20 Sep 2014 09:10:47 -0700 Joe Perches <joe@perches.com> wrote: > On Sat, 2014-09-20 at 17:47 +0200, Peter Zijlstra wrote: > > On a whole, printk() is entirely useless for debugging these days, its > > far too fragile/unreliable to be taken seriously so I really don't care > > on that point either. > > That's unfortunate. > > Care to enumerate the issues that you believe make > printk too fragile/unreliable for debugging? I seldom use printk these days. It's far too limited in its uses. For one, most things worth debugging happen thousands of times a second, and printk will just slow things down to a crawl if it is used. Another, is that it can not be used in most critical sections (NMI handlers and anything that deals with the scheduler). Also, as it no longer blocks when another CPU is doing a printk, a bug can happen which crashes the system and the output of that bug will never get printed due to the delayed output from another CPU having the console lock. -- Steve ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-20 16:30 ` Steven Rostedt @ 2014-09-20 18:08 ` Peter Zijlstra 0 siblings, 0 replies; 33+ messages in thread From: Peter Zijlstra @ 2014-09-20 18:08 UTC (permalink / raw) To: Steven Rostedt Cc: Joe Perches, Jan Kara, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Sat, Sep 20, 2014 at 12:30:01PM -0400, Steven Rostedt wrote: > On Sat, 20 Sep 2014 09:10:47 -0700 > Joe Perches <joe@perches.com> wrote: > > > On Sat, 2014-09-20 at 17:47 +0200, Peter Zijlstra wrote: > > > On a whole, printk() is entirely useless for debugging these days, its > > > far too fragile/unreliable to be taken seriously so I really don't care > > > on that point either. > > > > That's unfortunate. > > > > Care to enumerate the issues that you believe make > > printk too fragile/unreliable for debugging? > > I seldom use printk these days. It's far too limited in its uses. For > one, most things worth debugging happen thousands of times a second, > and printk will just slow things down to a crawl if it is used. > Another, is that it can not be used in most critical sections (NMI > handlers and anything that deals with the scheduler). Also, as it no > longer blocks when another CPU is doing a printk, a bug can happen > which crashes the system and the output of that bug will never get > printed due to the delayed output from another CPU having the console > lock. If you're trying to debug a dying machine the early_serial_console which basically only does a stream of OUTBs to the right port is the only reliable thing. For anything else, trace_printk(). Now all I need to figure out is how to keep suspend from killing the early_serial_console setup :-) ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-20 16:10 ` Joe Perches 2014-09-20 16:30 ` Steven Rostedt @ 2014-09-20 18:01 ` Peter Zijlstra 1 sibling, 0 replies; 33+ messages in thread From: Peter Zijlstra @ 2014-09-20 18:01 UTC (permalink / raw) To: Joe Perches Cc: Jan Kara, Steven Rostedt, Markus Trippelsdorf, Geert Uytterhoeven, linux-kernel, Andrew Morton On Sat, Sep 20, 2014 at 09:10:47AM -0700, Joe Perches wrote: > On Sat, 2014-09-20 at 17:47 +0200, Peter Zijlstra wrote: > > On a whole, printk() is entirely useless for debugging these days, its > > far too fragile/unreliable to be taken seriously so I really don't care > > on that point either. > > That's unfortunate. > > Care to enumerate the issues that you believe make > printk too fragile/unreliable for debugging? Look at what it takes to end up at console->write(), and then realize that some console implementations require scheduling and other nonsense to actually implement ->write(). The (only) reliable option is early_printk() with the early_serial_console driver. The rest is useless crap these days. ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-20 15:47 ` Peter Zijlstra 2014-09-20 16:10 ` Joe Perches @ 2014-09-24 11:01 ` Jan Kara 2014-09-24 11:11 ` [PATCH v2] " Markus Trippelsdorf 1 sibling, 1 reply; 33+ messages in thread From: Jan Kara @ 2014-09-24 11:01 UTC (permalink / raw) To: Markus Trippelsdorf Cc: Jan Kara, Steven Rostedt, Geert Uytterhoeven, linux-kernel, Peter Zijlstra, Andrew Morton On Sat 20-09-14 17:47:33, Peter Zijlstra wrote: > On Sat, Sep 20, 2014 at 07:12:24AM +0200, Jan Kara wrote: > > On Thu 18-09-14 19:34:14, Peter Zijlstra wrote: > > > On Wed, Sep 17, 2014 at 08:31:35PM -0400, Steven Rostedt wrote: > > > > I totally didn't get what you wrote. > > > > > > :-) > > > > > > > We don't want to know if it got delayed, then the patch to remove that > > > > print seems correct. > > > > > > Why would you not want to know that? Also was that the actual argument? > > > Lemme go check the earlier emails -- I cannot find that argument in the > > > first few emails. > > Well, so what gets delayed is printing from kernel buffer to console. > > So this is the same as when you do printk() when console lock is taken by > > someone else. So it seems a bit strange to prepend [delayed] in some cases > > and not in others. > > The difference is that when someone else has the console lock, he > guarantees it gets out. Whereas with the delayed thing it can take a > virtual forever to get out. > > > Another question is what the [delayed] prefix would be useful for? If the > > message eventually gets printed to console I don't see why you would care > > it was printed few ms after it entered the kernel buffer (after all the > > time stamp before the line will be the time when it entered the kernel > > buffer). And if the kernel crashes in such a way that the message doesn't > > get printed, then bad luck but prefix in the kernel log buffer isn't going > > to make that any better :) > > > > This all feels like bikeshedding, I don't deeply care what gets done but I > > wanted to point out I don't really see a use for [delayed]... > > Sure, I was just pointing out that those arguments had not been made. I > think you're right, if you see the msg it obviously made it out. If you > don't see it, you don't know either way. > > But a patch removing it _must_ make those arguments, it did not. Markus, could you please resend the patch with Steven's ack and expanded changelog? Thanks! Honza -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 33+ messages in thread
* [PATCH v2] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-24 11:01 ` Jan Kara @ 2014-09-24 11:11 ` Markus Trippelsdorf 2014-09-24 11:26 ` Jan Kara 0 siblings, 1 reply; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-24 11:11 UTC (permalink / raw) To: Jan Kara Cc: Steven Rostedt, Geert Uytterhoeven, linux-kernel, Peter Zijlstra, Andrew Morton commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts the string "[sched_delayed] " before the actual message. However it doesn't take into account the KERN_* prefix of the message, that now ends up in the middle of the output: [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec Fix this by just getting rid of the "[sched_delayed] " scnprintf(). This is a safe, because messages get inserted in the kernel ring buffer immediately these days. So there is no big difference between printk() and printk_deferred() anymore. Acked-by: Jan Kara <jack@suse.cz> Acked-by: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: Markus Trippelsdorf <markus@trippelsdorf.de> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 1ce770687ea8..f85994b58934 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1680,12 +1680,7 @@ asmlinkage int vprintk_emit(int facility, int level, * The printf needs to come first; we need the syslog * prefix which might be passed-in as a parameter. */ - if (in_sched) - text_len = scnprintf(text, sizeof(textbuf), - KERN_WARNING "[sched_delayed] "); - - text_len += vscnprintf(text + text_len, - sizeof(textbuf) - text_len, fmt, args); + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); /* mark and strip a trailing newline */ if (text_len && text[text_len-1] == '\n') { -- Markus ^ permalink raw reply related [flat|nested] 33+ messages in thread
* Re: [PATCH v2] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-24 11:11 ` [PATCH v2] " Markus Trippelsdorf @ 2014-09-24 11:26 ` Jan Kara 2014-09-24 11:37 ` [PATCH v3] " Markus Trippelsdorf 0 siblings, 1 reply; 33+ messages in thread From: Jan Kara @ 2014-09-24 11:26 UTC (permalink / raw) To: Markus Trippelsdorf Cc: Jan Kara, Steven Rostedt, Geert Uytterhoeven, linux-kernel, Peter Zijlstra, Andrew Morton On Wed 24-09-14 13:11:44, Markus Trippelsdorf wrote: > commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts > the string "[sched_delayed] " before the actual message. > However it doesn't take into account the KERN_* prefix of the message, > that now ends up in the middle of the output: > > [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > Fix this by just getting rid of the "[sched_delayed] " scnprintf(). > This is a safe, because messages get inserted in the kernel ring buffer > immediately these days. So there is no big difference between printk() > and printk_deferred() anymore. I'd prefer to be a bit more verbose in the last paragraph like: Fix this by just getting rid of the "[sched_delayed] " scnprintf(). The prefix is useless since commit 458df9fd4815 (printk: remove separate printk_sched buffers and use printk buf instead) anyway since from that moment printk_deferred() inserts the message into the kernel printk buffer immediately. So if the message eventually gets printed to console, it is printed in the correct order with other messages and there's no need for any special prefix. And if the kernel crashes before the message makes it to console, then prefix in the printk buffer doesn't make the situation any better. Honza > Acked-by: Jan Kara <jack@suse.cz> > Acked-by: Steven Rostedt <rostedt@goodmis.org> > Signed-off-by: Markus Trippelsdorf <markus@trippelsdorf.de> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 1ce770687ea8..f85994b58934 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -1680,12 +1680,7 @@ asmlinkage int vprintk_emit(int facility, int level, > * The printf needs to come first; we need the syslog > * prefix which might be passed-in as a parameter. > */ > - if (in_sched) > - text_len = scnprintf(text, sizeof(textbuf), > - KERN_WARNING "[sched_delayed] "); > - > - text_len += vscnprintf(text + text_len, > - sizeof(textbuf) - text_len, fmt, args); > + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); > > /* mark and strip a trailing newline */ > if (text_len && text[text_len-1] == '\n') { > -- > Markus -- Jan Kara <jack@suse.cz> SUSE Labs, CR ^ permalink raw reply [flat|nested] 33+ messages in thread
* Re: [PATCH v3] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-24 11:26 ` Jan Kara @ 2014-09-24 11:37 ` Markus Trippelsdorf 2014-09-24 15:12 ` Steven Rostedt 0 siblings, 1 reply; 33+ messages in thread From: Markus Trippelsdorf @ 2014-09-24 11:37 UTC (permalink / raw) To: Jan Kara Cc: Steven Rostedt, Geert Uytterhoeven, linux-kernel, Peter Zijlstra, Andrew Morton commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts the string "[sched_delayed] " before the actual message. However it doesn't take into account the KERN_* prefix of the message, that now ends up in the middle of the output: [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec Fix this by just getting rid of the "[sched_delayed] " scnprintf(). The prefix is useless since commit 458df9fd4815 (printk: remove separate printk_sched buffers and use printk buf instead) anyway since from that moment printk_deferred() inserts the message into the kernel printk buffer immediately. So if the message eventually gets printed to console, it is printed in the correct order with other messages and there's no need for any special prefix. And if the kernel crashes before the message makes it to console, then prefix in the printk buffer doesn't make the situation any better. Acked-by: Jan Kara <jack@suse.cz> Acked-by: Steven Rostedt <rostedt@goodmis.org> Signed-off-by: Markus Trippelsdorf <markus@trippelsdorf.de> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c index 1ce770687ea8..f85994b58934 100644 --- a/kernel/printk/printk.c +++ b/kernel/printk/printk.c @@ -1680,12 +1680,7 @@ asmlinkage int vprintk_emit(int facility, int level, * The printf needs to come first; we need the syslog * prefix which might be passed-in as a parameter. */ - if (in_sched) - text_len = scnprintf(text, sizeof(textbuf), - KERN_WARNING "[sched_delayed] "); - - text_len += vscnprintf(text + text_len, - sizeof(textbuf) - text_len, fmt, args); + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); /* mark and strip a trailing newline */ if (text_len && text[text_len-1] == '\n') { -- Markus ^ permalink raw reply related [flat|nested] 33+ messages in thread
* Re: [PATCH v3] printk: git rid of [sched_delayed] message for printk_deferred 2014-09-24 11:37 ` [PATCH v3] " Markus Trippelsdorf @ 2014-09-24 15:12 ` Steven Rostedt 0 siblings, 0 replies; 33+ messages in thread From: Steven Rostedt @ 2014-09-24 15:12 UTC (permalink / raw) To: Markus Trippelsdorf Cc: Jan Kara, Geert Uytterhoeven, linux-kernel, Peter Zijlstra, Andrew Morton The commit message is fine, but you really need to send this not as a reply to another patch or even a comment. That makes it hard for maintainers to find. Create a new thread and add this tag: Link: http://lkml.kernel.org/r/20140916144252.GB32118@x4 And hopefully Andrew can pull it into his tree. Thanks, -- Steve On Wed, 24 Sep 2014 13:37:02 +0200 Markus Trippelsdorf <markus@trippelsdorf.de> wrote: > commit 458df9fd hardcodes printk_deferred() to KERN_WARNING and inserts > the string "[sched_delayed] " before the actual message. > However it doesn't take into account the KERN_* prefix of the message, > that now ends up in the middle of the output: > > [sched_delayed] ^a4CE: hpet increased min_delta_ns to 20115 nsec > > Fix this by just getting rid of the "[sched_delayed] " scnprintf(). The > prefix is useless since commit 458df9fd4815 (printk: remove separate > printk_sched buffers and use printk buf instead) anyway since from that > moment printk_deferred() inserts the message into the kernel printk buffer > immediately. So if the message eventually gets printed to console, it is > printed in the correct order with other messages and there's no need for > any special prefix. And if the kernel crashes before the message makes it > to console, then prefix in the printk buffer doesn't make the situation any > better. > > Acked-by: Jan Kara <jack@suse.cz> > Acked-by: Steven Rostedt <rostedt@goodmis.org> > Signed-off-by: Markus Trippelsdorf <markus@trippelsdorf.de> > > diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c > index 1ce770687ea8..f85994b58934 100644 > --- a/kernel/printk/printk.c > +++ b/kernel/printk/printk.c > @@ -1680,12 +1680,7 @@ asmlinkage int vprintk_emit(int facility, int level, > * The printf needs to come first; we need the syslog > * prefix which might be passed-in as a parameter. > */ > - if (in_sched) > - text_len = scnprintf(text, sizeof(textbuf), > - KERN_WARNING "[sched_delayed] "); > - > - text_len += vscnprintf(text + text_len, > - sizeof(textbuf) - text_len, fmt, args); > + text_len = vscnprintf(text, sizeof(textbuf), fmt, args); > > /* mark and strip a trailing newline */ > if (text_len && text[text_len-1] == '\n') { ^ permalink raw reply [flat|nested] 33+ messages in thread
end of thread, other threads:[~2014-09-24 15:12 UTC | newest] Thread overview: 33+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2014-09-14 5:09 Weird character in kernel message Markus Trippelsdorf 2014-09-14 5:54 ` Markus Trippelsdorf 2014-09-14 9:13 ` Geert Uytterhoeven 2014-09-15 16:37 ` Markus Trippelsdorf 2014-09-16 10:55 ` Jan Kara 2014-09-16 14:42 ` [PATCH] printk: git rid of [sched_delayed] message for printk_deferred Markus Trippelsdorf 2014-09-16 15:13 ` Steven Rostedt 2014-09-16 15:20 ` Markus Trippelsdorf 2014-09-16 19:14 ` Steven Rostedt 2014-09-16 19:17 ` Markus Trippelsdorf 2014-09-16 20:26 ` Steven Rostedt 2014-09-16 20:35 ` Jan Kara 2014-09-16 21:07 ` Steven Rostedt 2014-09-16 21:22 ` Jan Kara 2014-09-16 21:33 ` Steven Rostedt 2014-09-17 14:18 ` Peter Zijlstra 2014-09-17 14:22 ` Steven Rostedt 2014-09-17 22:36 ` Peter Zijlstra 2014-09-18 0:31 ` Steven Rostedt 2014-09-18 17:34 ` Peter Zijlstra 2014-09-20 5:12 ` Jan Kara 2014-09-20 15:32 ` Steven Rostedt 2014-09-20 16:34 ` Markus Trippelsdorf 2014-09-20 15:47 ` Peter Zijlstra 2014-09-20 16:10 ` Joe Perches 2014-09-20 16:30 ` Steven Rostedt 2014-09-20 18:08 ` Peter Zijlstra 2014-09-20 18:01 ` Peter Zijlstra 2014-09-24 11:01 ` Jan Kara 2014-09-24 11:11 ` [PATCH v2] " Markus Trippelsdorf 2014-09-24 11:26 ` Jan Kara 2014-09-24 11:37 ` [PATCH v3] " Markus Trippelsdorf 2014-09-24 15:12 ` Steven Rostedt
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.