Weird character in kernel message

Weird character in kernel message

[Markus Trippelsdorf]

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

Re: Weird character in kernel message

[Markus Trippelsdorf]

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

Re: Weird character in kernel message

[Geert Uytterhoeven]

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

Re: Weird character in kernel message

[Markus Trippelsdorf]

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

Re: Weird character in kernel message

[Jan Kara]

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

[PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Markus Trippelsdorf]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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') {

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Markus Trippelsdorf]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Markus Trippelsdorf]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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
> 

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Jan Kara]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Jan Kara]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Peter Zijlstra]

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.

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Peter Zijlstra]

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.

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Peter Zijlstra]

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.

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Jan Kara]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Peter Zijlstra]

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.

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Joe Perches]

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?

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Markus Trippelsdorf]

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

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Peter Zijlstra]

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.

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Peter Zijlstra]

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 :-)

Re: [PATCH] printk: git rid of [sched_delayed] message for printk_deferred

[Jan Kara]

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

[PATCH v2] printk: git rid of [sched_delayed] message for printk_deferred

[Markus Trippelsdorf]

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

Re: [PATCH v2] printk: git rid of [sched_delayed] message for printk_deferred

[Jan Kara]

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

Re: [PATCH v3] printk: git rid of [sched_delayed] message for printk_deferred

[Markus Trippelsdorf]

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

Re: [PATCH v3] printk: git rid of [sched_delayed] message for printk_deferred

[Steven Rostedt]

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') {