Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1721358 > unrolled thread

printk: what is going on with additional newlines?

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-08-28 11:10 +0200
    Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-28 12:30 +0200
      Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-28 14:30 +0200
        Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-28 14:40 +0200
        Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-08-28 14:50 +0200
          Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-29 15:50 +0200
            Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 18:40 +0200
            Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 19:10 +0200
              Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 19:20 +0200
                Re: printk: what is going on with additional newlines? Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2017-08-29 22:50 +0200
                  Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 23:00 +0200
                    Re: printk: what is going on with additional newlines? Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2017-09-02 08:20 +0200
                      Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-09-02 19:10 +0200
                Re: printk: what is going on with additional newlines? Steven Rostedt <rostedt@goodmis.org> - 2017-08-30 02:00 +0200
                  Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-30 02:00 +0200
                  Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 03:10 +0200
                    Re: printk: what is going on with additional newlines? Steven Rostedt <rostedt@goodmis.org> - 2017-08-30 03:20 +0200
                      Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 03:50 +0200
                      Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-30 04:00 +0200
                        Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 04:30 +0200
                          Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-30 04:40 +0200
                            Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 04:50 +0200
                              Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-30 05:00 +0200
                                Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 07:40 +0200
                                  Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-09-08 12:20 +0200
                              Re: printk: what is going on with additional newlines? Petr Mladek <pmladek@suse.com> - 2017-09-05 11:50 +0200
                                Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-05 12:10 +0200
                                  Re: printk: what is going on with additional newlines? Petr Mladek <pmladek@suse.com> - 2017-09-05 14:30 +0200
                                    Re: printk: what is going on with additional newlines? Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2017-09-05 14:40 +0200
                                      Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-09-05 16:30 +0200
                                    Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-05 15:50 +0200
                                      Re: printk: what is going on with additional newlines? Petr Mladek <pmladek@suse.com> - 2017-09-06 10:00 +0200
                      Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-09-01 15:30 +0200
                        Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-01 19:40 +0200
                          Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-09-01 22:30 +0200
                            Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-04 07:30 +0200
                              Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-04 07:50 +0200
                              Re: printk: what is going on with additional newlines? Steven Rostedt <rostedt@goodmis.org> - 2017-09-05 17:00 +0200
                                Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-06 04:20 +0200
                                Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-09-06 04:40 +0200
                          Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-04 06:40 +0200
                            Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-04 07:30 +0200
              Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2017-08-29 19:40 +0200
                Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 20:00 +0200
                  Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 20:10 +0200
                    Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 03:10 +0200
                  Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-08-30 03:00 +0200
    Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 18:50 +0200
      Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 19:20 +0200
        Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 19:30 +0200
          Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 19:40 +0200
            Re: printk: what is going on with additional newlines? Linus Torvalds <torvalds@linux-foundation.org> - 2017-08-29 19:40 +0200
              Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-08-29 19:50 +0200
      Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-08-29 22:30 +0200
        Re: printk: what is going on with additional newlines? Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-09-01 03:50 +0200
          Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-01 04:10 +0200
            Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-09-01 09:00 +0200
              Re: printk: what is going on with additional newlines? Joe Perches <joe@perches.com> - 2017-09-01 09:30 +0200
          Re: printk: what is going on with additional newlines? Pavel Machek <pavel@ucw.cz> - 2017-09-01 09:30 +0200
            Re: printk: what is going on with additional newlines? Steven Rostedt <rostedt@goodmis.org> - 2017-09-01 13:20 +0200

Page 1 of 3  [1] 2 3  Next page →

#1721358 — printk: what is going on with additional newlines?

[Multipart message — attachments visible in raw view] — view raw

Hi!

In 4.13-rc, printk("foo"); printk("bar"); seems to produce
foo\nbar. That's... quite surprising/unwelcome. What is going on
there? Are timestamps responsible?

									Pavel
									
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [next] | [standalone]

#1721497

On (08/28/17 11:05), Pavel Machek wrote:
> Hi!
> 
> In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> foo\nbar. That's... quite surprising/unwelcome. What is going on
> there? Are timestamps responsible?

well, one thing we know for sure it is not related to this patch set  ;)


does any of the below patches fix the problem for you?

basically it sets up the rule -- if we don't have LOG_NEWLINE lflags
then we enforce LOG_CONT.

---

@@ -1721,9 +1723,13 @@ asmlinkage int vprintk_emit(int facility, int level,
 	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
 
 	/* mark and strip a trailing newline */
-	if (text_len && text[text_len-1] == '\n') {
-		text_len--;
-		lflags |= LOG_NEWLINE;
+	if (text_len) {
+		if (text[text_len-1] == '\n') {
+			text_len--;
+			lflags |= LOG_NEWLINE;
+		} else {
+			lflags |= LOG_CONT;
+		}
 	}
 
 	/* strip kernel syslog prefix and extract log level or control flags */


---


=== 8< === 8< ===


or... an alternative "solution"

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863f629c..5fd567abc5e6 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1670,7 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	 * write from the same process, try to add it to the buffer.
 	 */
 	if (cont.len) {
-		if (cont.owner == current && (lflags & LOG_CONT)) {
+		if (cont.owner == current &&
+				((lflags & LOG_CONT) ||
+				 !(lflags & LOG_NEWLINE))) {
 			if (cont_add(facility, level, lflags, text, text_len))
 				return text_len;
 		}


---

	-ss

[toc] | [prev] | [next] | [standalone]

#1721571

On (08/28/17 19:28), Sergey Senozhatsky wrote:
> On (08/28/17 11:05), Pavel Machek wrote:
> > Hi!
> > 
> > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > there? Are timestamps responsible?
> 
> well, one thing we know for sure it is not related to this patch set  ;)
> 
> 
> does any of the below patches fix the problem for you?
> 
> basically it sets up the rule -- if we don't have LOG_NEWLINE lflags
> then we enforce LOG_CONT.

[..]

> @@ -1670,7 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
>  	 * write from the same process, try to add it to the buffer.
>  	 */
>  	if (cont.len) {
> 		if (cont.owner == current && (lflags & LOG_CONT)) {


on the other hand... I don't think I like that check at all.
so I *probably* want to change it to -- !LOG_NEWLINE messages of the
same loglevel AND from the same task are getting concatenated.
a message with LOG_NEWLINE flushes the cont buffer.

for example:

       printk("foo"); printk("foo"); printk("bar\n");
       printk("buz"); printk("buz"); printk("buz"); pr_info("INFO msg\n");
       printk("buz"); printk("buz"); printk("buz"); pr_err("ERR msg\n");
       printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
       printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");
       printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR"bar err\n");


for instance,
	printk(KERN_ERR"foo err"); printk(KERN_ERR"bar err\n");

should produce    "foo errbar err\n".    from the same task and of
the same loglevel, no new line. must be cont messages with a missing
KERN_CONT. right?


so, for the examples I posted above, I think, the output must be

 foofoobar
 buzbuzbuz
 INFO msg
 buzbuzbuz
 ERR msg
 foofoobar
 foofoo
 bar
 foo
 foo errbar err


how about something like this?

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863f629c..675febf84dc8 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1670,10 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	 * write from the same process, try to add it to the buffer.
 	 */
 	if (cont.len) {
-		if (cont.owner == current && (lflags & LOG_CONT)) {
+		if (cont.owner == current && cont.level == level)
 			if (cont_add(facility, level, lflags, text, text_len))
 				return text_len;
-		}
 		/* Otherwise, make sure it's flushed */
 		cont_flush();
 	}
 

[toc] | [prev] | [next] | [standalone]

#1721579

On (08/28/17 21:21), Sergey Senozhatsky wrote:
> how about something like this?
> 

...ok, definetely breaks the

	KERN_ERR "foo"; KERN_CONT "bar"; KERN_CONT "bar"; KERN_CONT "\n";

case. um... something like this then?

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index fc47863f629c..098e280e9fe0 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1670,10 +1670,11 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	 * write from the same process, try to add it to the buffer.
 	 */
 	if (cont.len) {
-		if (cont.owner == current && (lflags & LOG_CONT)) {
+		if (cont.owner == current &&
+				((cont.level == level) ||
+				(lflags & LOG_CONT)))
 			if (cont_add(facility, level, lflags, text, text_len))
 				return text_len;
-		}
 		/* Otherwise, make sure it's flushed */
 		cont_flush();
 	}
 

[toc] | [prev] | [next] | [standalone]

#1721586

[Multipart message — attachments visible in raw view] — view raw

Hi!

On Mon 2017-08-28 21:21:09, Sergey Senozhatsky wrote:
> On (08/28/17 19:28), Sergey Senozhatsky wrote:
> > On (08/28/17 11:05), Pavel Machek wrote:
> > > Hi!
> > > 
> > > In 4.13-rc, printk("foo"); printk("bar"); seems to produce
> > > foo\nbar. That's... quite surprising/unwelcome. What is going on
> > > there? Are timestamps responsible?
> > 
> > well, one thing we know for sure it is not related to this patch set  ;)
> > 
> > 
> > does any of the below patches fix the problem for you?
> > 
> > basically it sets up the rule -- if we don't have LOG_NEWLINE lflags
> > then we enforce LOG_CONT.
> 
> [..]
> 
> > @@ -1670,7 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
> >  	 * write from the same process, try to add it to the buffer.
> >  	 */
> >  	if (cont.len) {
> > 		if (cont.owner == current && (lflags & LOG_CONT)) {
> 
> 
> on the other hand... I don't think I like that check at all.
> so I *probably* want to change it to -- !LOG_NEWLINE messages of the
> same loglevel AND from the same task are getting concatenated.
> a message with LOG_NEWLINE flushes the cont buffer.

Looks good to me.

> for example:
> 
>        printk("foo"); printk("foo"); printk("bar\n");

This behaviour is important for me... and this sounds ok.

>        printk("buz"); printk("buz"); printk("buz"); pr_info("INFO msg\n");
>        printk("buz"); printk("buz"); printk("buz"); pr_err("ERR msg\n");
>        printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
>        printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");
>        printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR"bar err\n");
>

> 
> for instance,
> 	printk(KERN_ERR"foo err"); printk(KERN_ERR"bar err\n");
> 
> should produce    "foo errbar err\n".    from the same task and of
> the same loglevel, no new line. must be cont messages with a missing
> KERN_CONT. right?

Not sure. Historically it produce foo err<9>bar err\n. Concatening is
probably okay.

> how about something like this?

Umm.. No?

printk(KERN_INFO "foo"); printk(KERN_CONT "bar\n");

should produce "foobar\n", right? Will not your patch insert newline
there?

								Pavel

> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index fc47863f629c..675febf84dc8 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1670,10 +1670,9 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
>  	 * write from the same process, try to add it to the buffer.
>  	 */
>  	if (cont.len) {
> -		if (cont.owner == current && (lflags & LOG_CONT)) {
> +		if (cont.owner == current && cont.level == level)
>  			if (cont_add(facility, level, lflags, text, text_len))
>  				return text_len;
> -		}
>  		/* Otherwise, make sure it's flushed */
>  		cont_flush();
>  	}
>  

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[toc] | [prev] | [next] | [standalone]

#1722499

Hi,

so I had a second look, and I think the patch I posted yesterday is
pretty wrong. How about something like below?

---

From d65d1b74d3acc51e5d998c5d2cf10d20c28dc2f9 Mon Sep 17 00:00:00 2001
From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Date: Tue, 29 Aug 2017 22:30:07 +0900
Subject: [PATCH] printk: restore non-log_prefix messages handling

Pavel reported that
	printk("foo"); printk("bar");

now does not produce a single continuation "foobar" line, but
instead produces two lines
		foo
		bar

The first printk() goes to cont buffer, just as before. The difference
is how we handle the second one. We used to just add it to the cont
buffer:

	if (!(lflags & LOG_NEWLINE)) {
		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
			cont_flush();

		cont_add(...)
	}

but now we flush the existing cont buffer and store the second
printk() message separately:

	if (cont.len) {
		if (cont.owner == current && (lflags & LOG_CONT))
			return cont_add();

		/* otherwise flush */
		cont_flush();
	}

because printk("bar") does not have LOG_CONT.

The patch restores the old behaviour.

To verify the change I did the following printk() test again the v4.5
and patched linux-next:

 pr_err("foo"); pr_cont("bar"); pr_cont("bar\n");
 printk("foo"); printk("foo"); printk("bar\n");

 printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo");
 printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo");

 printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
 printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");

 printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR "ERR foo\n");

 printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo\n");
 printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo\n");

 printk(KERN_INFO "foo"); printk(KERN_CONT "bar\n"); printk(KERN_CONT "bar\n");

I, however, got a slightly different output (I'll explain the difference):

	v4.5                    linux-next

	foobarbar               foobarbar
	foofoobar               foofoobar
	bazbazbaz               bazbazbaz
	INFO foo                INFO foobazbazbaz
	bazbazbaz
	ERR foo                 ERR foofoofoobar
	foofoobar
	foofoo                  foofoo
	bar                     bar
	foo                     foo
	foo err                 foo err
	ERR foo                 ERR foo
	bazbazbaz               bazbazbaz
	INFO foo                INFO foo
	bazbazbaz               bazbazbaz
	ERR foo                 ERR foo
	foobar                  foobar
	bar                     bar

As we can see the difference is in:
   pr_info("INFO foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo")...
and
   pr_err("ERR foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo");...
handling.

The output is expected to be two continuation lines; but this is not
the case for old kernels.

What the old kernel does here is:

- it sees that cont buffer already has data: all those !LOG_PREFIX messages

- it also sees that the current messages is LOG_PREFIX and that part of
  the cont buffer was already printed to the serial console:

	// Flush the conflicting buffer. An earlier newline was missing
	// or another task also prints continuation lines

	if (!(lflags & LOG_NEWLINE)) {
		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
			cont_flush(LOG_NEWLINE);

		if (cont_add(text))
			printed_len += text_len;
		else
			printed_len += log_store(text);
	}

  the problem here is that, flush does not actually flush the buffer and
  does not reset the conf buffer state, but sets cont.flushed to true
  instead:

	if (cont.cons) {
		log_store(cont.text);
		cont.flags = flags;
		cont.flushed = true;
	}

- then the kernel attempts to cont_add() the messages. but cont_add() does
  not append the messages to the cont buffer, because of this check

	if (cont.len && cont.flushed)
		return false;

  both cont.len and cont.flushed are true. because the kernel waits for
  console_unlock() to call console_cont_flush()->cont_print_text(),
  which should print the cont.text to the serial console and reset the
  cont buffer state.

- but cont_print_text() must be called under logbuf_lock lock, which
  we still hold in vprintk_emit(). so the kernel has no chance to flush
  the cont buffer and thus cont_add() fails there and forces the kernel
  to log_store() the message, allocating a separate logbuf entry for
  it.

That's why we see the difference in v4.5 vs linux-next logs. This is
visible only when !LOG_NEWLINE path has to cont_flush() partially
printed cont buffer from under the logbuf_lock.

I think the old behavior had a bug - we need to concatenate

	KERN_ERR foo; KERN_CONT bar; KERN_CON bar\n;

regardless the previous cont buffer state.

Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
Reported-by: Pavel Machek <pavel@ucw.cz>
---
 kernel/printk/printk.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index ac1fd606d6c5..be868b7d9ceb 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -1914,12 +1914,17 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	 * write from the same process, try to add it to the buffer.
 	 */
 	if (cont.len) {
-		if (cont.owner == current && (lflags & LOG_CONT)) {
+		/*
+		 * Flush the conflicting buffer. An earlier newline was missing,
+		 * or another task also prints continuation lines.
+		 */
+		if (lflags & LOG_PREFIX || cont.owner != current)
+			cont_flush();
+
+		if (!(lflags & LOG_PREFIX) || lflags & LOG_CONT) {
 			if (cont_add(facility, level, lflags, text, text_len))
 				return text_len;
 		}
-		/* Otherwise, make sure it's flushed */
-		cont_flush();
 	}
 
 	/* Skip empty continuation lines that couldn't be added - they just flush */
-- 
2.14.1

[toc] | [prev] | [next] | [standalone]

#1722603

On Tue, 2017-08-29 at 22:40 +0900, Sergey Senozhatsky wrote:
> Hi,
> 
> so I had a second look, and I think the patch I posted yesterday is
> pretty wrong. How about something like below?

> ---
> 
> From d65d1b74d3acc51e5d998c5d2cf10d20c28dc2f9 Mon Sep 17 00:00:00 2001
> From: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Date: Tue, 29 Aug 2017 22:30:07 +0900
> Subject: [PATCH] printk: restore non-log_prefix messages handling
> 
> Pavel reported that
> 	printk("foo"); printk("bar");
> 
> now does not produce a single continuation "foobar" line, but
> instead produces two lines
> 		foo
> 		bar
> 
> The first printk() goes to cont buffer, just as before. The difference
> is how we handle the second one. We used to just add it to the cont
> buffer:
> 
> 	if (!(lflags & LOG_NEWLINE)) {
> 		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
> 			cont_flush();
> 
> 		cont_add(...)
> 	}
> 
> but now we flush the existing cont buffer and store the second
> printk() message separately:
> 
> 	if (cont.len) {
> 		if (cont.owner == current && (lflags & LOG_CONT))
> 			return cont_add();
> 
> 		/* otherwise flush */
> 		cont_flush();
> 	}
> 
> because printk("bar") does not have LOG_CONT.
> 
> The patch restores the old behaviour.
> 
> To verify the change I did the following printk() test again the v4.5
> and patched linux-next:

It's possibly dubious to go back to v4.5 behavior.
Linus changed the
printk continuation behavior in v4.9
Unfortunately he did this without
posting anything to lkml
for comment and he broke a bunch of continuation
printks.


>  pr_err("foo"); pr_cont("bar"); pr_cont("bar\n");
>  printk("foo"); printk("foo"); printk("bar\n");
> 
>  printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo");
>  printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo");
> 
>  printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"bar\n");
>  printk(KERN_CONT"foo"); printk(KERN_CONT"foo"); printk(KERN_ERR"bar\n");
> 
>  printk(KERN_CONT"foo"); printk(KERN_ERR"foo err"); printk(KERN_ERR "ERR foo\n");
> 
>  printk("baz"); printk("baz"); printk("baz"); pr_info("INFO foo\n");
>  printk("baz"); printk("baz"); printk("baz"); pr_err("ERR foo\n");
> 
>  printk(KERN_INFO "foo"); printk(KERN_CONT "bar\n"); printk(KERN_CONT "bar\n");
> 
> I, however, got a slightly different output (I'll explain the difference):
> 
> 	v4.5                    linux-next
> 
> 	foobarbar               foobarbar
> 	foofoobar               foofoobar
> 	bazbazbaz               bazbazbaz
> 	INFO foo                INFO foobazbazbaz
> 	bazbazbaz
> 	ERR foo                 ERR foofoofoobar
> 	foofoobar
> 	foofoo                  foofoo
> 	bar                     bar
> 	foo                     foo
> 	foo err                 foo err
> 	ERR foo                 ERR foo
> 	bazbazbaz               bazbazbaz
> 	INFO foo                INFO foo
> 	bazbazbaz               bazbazbaz
> 	ERR foo                 ERR foo
> 	foobar                  foobar
> 	bar                     bar
> 
> As we can see the difference is in:
>    pr_info("INFO foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo")...
> and
>    pr_err("ERR foo"); printk(KERN_CONT"foo"); printk(KERN_CONT"foo");...
> handling.
> 
> The output is expected to be two continuation lines; but this is not
> the case for old kernels.
> 
> What the old kernel does here is:
> 
> - it sees that cont buffer already has data: all those !LOG_PREFIX messages
> 
> - it also sees that the current messages is LOG_PREFIX and that part of
>   the cont buffer was already printed to the serial console:
> 
> 	// Flush the conflicting buffer. An earlier newline was missing
> 	// or another task also prints continuation lines
> 
> 	if (!(lflags & LOG_NEWLINE)) {
> 		if (cont.len && (lflags & LOG_PREFIX || cont.owner != current))
> 			cont_flush(LOG_NEWLINE);
> 
> 		if (cont_add(text))
> 			printed_len += text_len;
> 		else
> 			printed_len += log_store(text);
> 	}
> 
>   the problem here is that, flush does not actually flush the buffer and
>   does not reset the conf buffer state, but sets cont.flushed to true
>   instead:
> 
> 	if (cont.cons) {
> 		log_store(cont.text);
> 		cont.flags = flags;
> 		cont.flushed = true;
> 	}
> 
> - then the kernel attempts to cont_add() the messages. but cont_add() does
>   not append the messages to the cont buffer, because of this check
> 
> 	if (cont.len && cont.flushed)
> 		return false;
> 
>   both cont.len and cont.flushed are true. because the kernel waits for
>   console_unlock() to call console_cont_flush()->cont_print_text(),
>   which should print the cont.text to the serial console and reset the
>   cont buffer state.
> 
> - but cont_print_text() must be called under logbuf_lock lock, which
>   we still hold in vprintk_emit(). so the kernel has no chance to flush
>   the cont buffer and thus cont_add() fails there and forces the kernel
>   to log_store() the message, allocating a separate logbuf entry for
>   it.
> 
> That's why we see the difference in v4.5 vs linux-next logs. This is
> visible only when !LOG_NEWLINE path has to cont_flush() partially
> printed cont buffer from under the logbuf_lock.
> 
> I think the old behavior had a bug - we need to concatenate
> 
> 	KERN_ERR foo; KERN_CONT bar; KERN_CON bar\n;
> 
> regardless the previous cont buffer state.
> 
> Signed-off-by: Sergey Senozhatsky <sergey.senozhatsky@gmail.com>
> Reported-by: Pavel Machek <pavel@ucw.cz>
> ---
>  kernel/printk/printk.c | 11 ++++++++---
>  1 file changed, 8 insertions(+), 3 deletions(-)
> 
> diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
> index ac1fd606d6c5..be868b7d9ceb 100644
> --- a/kernel/printk/printk.c
> +++ b/kernel/printk/printk.c
> @@ -1914,12 +1914,17 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
>  	 * write from the same process, try to add it to the buffer.
>  	 */
>  	if (cont.len) {
> -		if (cont.owner == current && (lflags & LOG_CONT)) {
> +		/*
> +		 * Flush the conflicting buffer. An earlier newline was missing,
> +		 * or another task also prints continuation lines.
> +		 */
> +		if (lflags & LOG_PREFIX || cont.owner != current)
> +			cont_flush();
> +
> +		if (!(lflags & LOG_PREFIX) || lflags & LOG_CONT) {
>  			if (cont_add(facility, level, lflags, text, text_len))
>  				return text_len;
>  		}
> -		/* Otherwise, make sure it's flushed */
> -		cont_flush();
>  	}
>  
>  	/* Skip empty continuation lines that couldn't be added - they just flush */

[toc] | [prev] | [next] | [standalone]

#1722615

On Tue, Aug 29, 2017 at 6:40 AM, Sergey Senozhatsky
<sergey.senozhatsky.work@gmail.com> wrote:
> Pavel reported that
>         printk("foo"); printk("bar");
>
> now does not produce a single continuation "foobar" line, but
> instead produces two lines
>                 foo
>                 bar

And that's the *correct* behavior.

Stop trying to fix that. Fix the printk's instead.

In particular, the

    printk("bar");

could have come from an interrupt, and have nothing what-so-ever to do
with "foo".

If you want continuations, you

 (a) make sure the first one doesn't end in a newline

 (b) make sure the second printk has a KERN_CONT

 (c) even after that, ask yourself how much you _really_ want
continuations, because there are going to be situations where it still
doesn't work.

I refuse to help those things. We mis-designed things, and the
continuations were a mistake to begin with, but they were a mistake
that was understandable in the timeframe they happened. But it's not
something we should support, and it's most definitely is not something
we should then say "oh, you were broken shit that didn't even bother
to add the KERN_CONT, let me help your crap".

No.

Only acceptable use of continuations is basically boot-time testing,
when you do things like

     printk("Testing feature XYZ..");
     this_may_blow_up_because_of_hw_bugs();
     printk(KERN_CONT " ... ok\n");

and anything else you should seriously try to marshal the data
*before* doing a printk(), and not expect printk() to marshal it for
you. But for legacy reasons, we do end up trying to support KERN_CONT.
Just barely.

I'd really like to get rid of it entirely, because the whole log-based
structure really really doesn't work well for it (what if somebody has
already read the partial line from the logs?)

Our printk stuff didn't used to be log-based. It was just a plain
character-based circular buffer. Back then that KERN_CONT made a whole
lot more sense.

              Linus

[toc] | [prev] | [next] | [standalone]

#1722622

On Tue, Aug 29, 2017 at 10:00 AM, Linus Torvalds
<torvalds@linux-foundation.org> wrote:
>
> I refuse to help those things. We mis-designed things

Actually, let me rephrase that:

It might actually be a good idea to help those things, by making
helper functions available that do the marshalling.

So not calling "printk()" directly, but having a set of simple
"buffer_print()" functions where each user has its own buffer, and
then the "buffer_print()" functions will help people do nicely output
data.

So if the issue is that people want to print (for example) hex dumps
one character at a time, but don't want to have each character show up
on a line of their own, I think we might well add a few functions to
help dop that.

But they wouldn't be "printk". They would be the buffering functions
that then call printk when tyhey have buffered a line.

That avoids the whole nasty issue with printk - printk wants to show
stuff early (because _maybe_ it's critical) and printk wants to make
log records with timestamps and loglevels. And printk has serious
locking issues that are really nasty and fundamental.

A private buffer has none of those issues.

                 Linus

[toc] | [prev] | [next] | [standalone]

#1722847

Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 10:00 AM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> >
> > I refuse to help those things. We mis-designed things
> 
> Actually, let me rephrase that:
> 
> It might actually be a good idea to help those things, by making
> helper functions available that do the marshalling.
> 
> So not calling "printk()" directly, but having a set of simple
> "buffer_print()" functions where each user has its own buffer, and
> then the "buffer_print()" functions will help people do nicely output
> data.
> 
> So if the issue is that people want to print (for example) hex dumps
> one character at a time, but don't want to have each character show up
> on a line of their own, I think we might well add a few functions to
> help dop that.
> 
> But they wouldn't be "printk". They would be the buffering functions
> that then call printk when tyhey have buffered a line.
> 
> That avoids the whole nasty issue with printk - printk wants to show
> stuff early (because _maybe_ it's critical) and printk wants to make
> log records with timestamps and loglevels. And printk has serious
> locking issues that are really nasty and fundamental.
> 
> A private buffer has none of those issues.

Yes, I posted "[PATCH] printk: Add best-effort printk() buffering." at
http://lkml.kernel.org/r/1493560477-3016-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp .

> 
>                  Linus
> 

[toc] | [prev] | [next] | [standalone]

#1722853

On Tue, Aug 29, 2017 at 1:41 PM, Tetsuo Handa
<penguin-kernel@i-love.sakura.ne.jp> wrote:
>>
>> A private buffer has none of those issues.
>
> Yes, I posted "[PATCH] printk: Add best-effort printk() buffering." at
> http://lkml.kernel.org/r/1493560477-3016-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp .

No, this is exactly what I *don't* want, because it takes over printk() itself.

And that's problematic, because nesting happens for various reasons.

For example, you try to handle that nesting with printk_context(), and
nothing when an interrupt happens.

But that is fundamentally broken.

Just to give an example: what if an interrupt happens, it does this
buffering thing, then it gets interrupted by *another* interrupt, and
now the printk from that other interrupt gets incorrectly nested
together with the first one, because your "printk_context()" gives
them the same context?

And it really doesn't have to even be interrupts. Look at what happens
if you take a page fault in kernel space. Same exact deal. Both are
sleeping contexts.

So I really think that the only thing that knows what the "context" is
is the person who does the printing. So if you want to create a
printing buffer, it should be explicit. You allocate the buffer ahead
of time (perhaps on the stack, possibly using actual allocations), and
you use that explicit context.

Yes, it means that you don't do "printk()". You do an actual
"buf_print()" or similar.

             Linus

[toc] | [prev] | [next] | [standalone]

#1725453

Linus Torvalds wrote:
> On Tue, Aug 29, 2017 at 1:41 PM, Tetsuo Handa
> <penguin-kernel@i-love.sakura.ne.jp> wrote:
> >>
> >> A private buffer has none of those issues.
> >
> > Yes, I posted "[PATCH] printk: Add best-effort printk() buffering." at
> > http://lkml.kernel.org/r/1493560477-3016-1-git-send-email-penguin-kernel@I-love.SAKURA.ne.jp .
> 
> No, this is exactly what I *don't* want, because it takes over printk() itself.
> 
> And that's problematic, because nesting happens for various reasons.
> 
> For example, you try to handle that nesting with printk_context(), and
> nothing when an interrupt happens.
> 
> But that is fundamentally broken.
> 
> Just to give an example: what if an interrupt happens, it does this
> buffering thing, then it gets interrupted by *another* interrupt, and
> now the printk from that other interrupt gets incorrectly nested
> together with the first one, because your "printk_context()" gives
> them the same context?

My assumption was that

  (1) task context can be preempted by soft IRQ context, hard IRQ context and NMI context.
  (2) soft IRQ context can be preempted by hard IRQ context and NMI context.
  (3) hard IRQ context can be preempted by NMI context.
  (4) An kernel-oops event can interrupt task context, soft IRQ context, hard IRQ context
      and NMI context, but the interrupted context can not continue execution of
      vprintk_default() after returning from the kernel-oops event even if the
      kernel-oops event occurred in schedulable context and panic_on_oops == 0.

and thus my "printk_context()" gives them different context.

But my assumption was wrong that

  soft IRQ context can be preempted by different soft IRQ context
  (e.g. SoftIRQ1 can be preempted by SoftIRQ2 while running
  handler for SoftIRQ1, and SoftIRQ2 can be preempted by SoftIRQ3
  while running handler for SoftIRQ2, and so on)

  hard IRQ context can be preempted by different hard IRQ context
  (e.g. HardIRQ1 can be preempted by HardIRQ2 while running
  handler for HardIRQ1, and HardIRQ2 can be preempted by HardIRQ3
  while running handler for HardIRQ2, and so on)

? Then, we need to recognize how many IRQs are nested.

I just tried to distinguish context using one "unsigned long" value
by embedding IRQ status into lower bits of "struct task_struct *".
I can change to distinguish context using multiple "unsigned long" values.

> 
> And it really doesn't have to even be interrupts. Look at what happens
> if you take a page fault in kernel space. Same exact deal. Both are
> sleeping contexts.

Is merging messages from outside a page fault and inside a page fault
so serious? That would happen only if memory access which might cause
a page fault occurs between get_printk_buffer() and put_printk_buffer(),
and I think that such user is rare.

> 
> So I really think that the only thing that knows what the "context" is
> is the person who does the printing. So if you want to create a
> printing buffer, it should be explicit. You allocate the buffer ahead
> of time (perhaps on the stack, possibly using actual allocations), and
> you use that explicit context.

If my assumption was wrong, isn't it dangerous from stack usage point of
view that we try to call kmalloc() (or allocate from stack memory) for
prbuf_init() for each nested level because it is theoretically possible
that a different IRQ jumps in while kmalloc() is in progress (or stack
memory is in use)?

> 
> Yes, it means that you don't do "printk()". You do an actual
> "buf_print()" or similar.
> 
>              Linus
> 

My worry is that there are so many functions which will need to receive
"struct seq_buf *" argument (from tail of __dump_stack() to head of
out_of_memory(), including e.g. cpuset_print_current_mems_allowed()) that
patches for passing "struct seq_buf *" argument becomes so large and
difficult to synchronize. I tried to pass such argument to relevant
functions before I propose "[PATCH] printk: Add best-effort printk()
buffering." patch, but I came to conclusion that passing such argument is
too complicated and too much bloat compared to merit.

If we teach printk subsystem that "I want to use buffering" via
get_printk_buffer(), we don't need to scatter around "struct seq_buf *"
argument throughout the kernel.

Using kmalloc() for prbuf_init() also introduces problems such as

  (a) we need to care about safe GFP flags (i.e. GFP_ATOMIC or
      GFP_KERNEL or something else which cannot be managed by
      current_gfp_context()) based on locking context

  (b) allocations can fail, and printing allocation failure messages
      when printing original messages is disturbing

  (c) allocation stall/failure messages are printed under memory pressure,
      but stack memory is not large enough to store messages related
      allocation stall/failure messages

and thus I want to use "statically allocated buffer" like workqueue's
rescuer kernel thread which can be used under memory pressure.

Linus Torvalds wrote at http://lkml.kernel.org/r/CA+55aFxmL4ybpz19OPn97VYqAk2ZS-tf=0W2Ff1K=-UUB6mYyg@mail.gmail.com :
> On Fri, Sep 1, 2017 at 10:32 AM, Joe Perches <joe@perches.com> wrote:
> >
> > Yes, it's a poor name.  At least keep using a pr_ prefix.
> 
> I'd suggest perhaps just "pr_line()".
> 
> And instead of having those "err/info/cont" variations, the severity
> level should just be set at initialization time.  Not different
> versions of "pr_line()".
> 
> There's no point to having different severity variations, since the
> *only* reason for this would be for buffering. So "pr_cont()" is kind
> of assumed for everything but the first.

But it is annoying for me that

  Lines1-for-event1-with-loglevel-foo
  Lines2-for-event1-with-loglevel-bar
  Lines3-for-event1-with-loglevel-baz

(like OOM killer messages) are all treated as loglevel foo
breaks console_loglevel filtering and

> 
> And even if you end up doing multiple lines, if you actually do
> different severities, you damn well shouldn't buffer them together.
> They are clearly different things!

two series of messages

  Line1-for-event1-with-loglevel-foo
  Line2-for-event1-with-loglevel-bar
  Line3-for-event1-with-loglevel-bar
  Line4-for-event1-with-loglevel-bar
  Line5-for-event1-with-loglevel-baz

by task/1000 and

  Line1-for-event2-with-loglevel-foo
  Line2-for-event2-with-loglevel-bar
  Line3-for-event2-with-loglevel-bar
  Line4-for-event2-with-loglevel-bar
  Line5-for-event2-with-loglevel-baz

by task/1001 are mixed due to not to buffering lines with different
loglevels causes unreadable logs (unless printk() automatically
inserts context identifier into each line like

  foo task/1000 Line1-for-event1-with-loglevel-foo
  foo task/1001 Line1-for-event2-with-loglevel-foo
  bar task/1001 Line2-for-event2-with-loglevel-bar
  bar task/1001 Line3-for-event2-with-loglevel-bar
  bar task/1001 Line4-for-event2-with-loglevel-bar
  bar task/1000 Line2-for-event1-with-loglevel-bar
  bar task/1000 Line3-for-event1-with-loglevel-bar
  bar task/1000 Line4-for-event1-with-loglevel-bar
  baz task/1000 Line5-for-event1-with-loglevel-baz
  baz task/1001 Line5-for-event2-with-loglevel-baz

).

[toc] | [prev] | [next] | [standalone]

#1725539

On Fri, Sep 1, 2017 at 11:12 PM, Tetsuo Handa
<penguin-kernel@i-love.sakura.ne.jp> wrote:
>
> I just tried to distinguish context using one "unsigned long" value
> by embedding IRQ status into lower bits of "struct task_struct *".
> I can change to distinguish context using multiple "unsigned long" values.

I really really don't think we want to use implicit contexts. I
suspect you'd end up doing something like a per-cpu counter (with
perhaps the CPU number in the low bits or something) and every
exception and sw interrupt etc would increment it.

.. oh, and workqueues etc.

And the end result would be that you'd be very limited in where you
can actually expect buffering to happen.

Which is all a bad design, since just making the buffer explicit is
(a) cheaper and (b) better. Now you can put the buffer on the stack,
you never have to worry about where you need to track context, and you
have no buffering limits (ie you can buffer across any event).

> If my assumption was wrong, isn't it dangerous from stack usage point of
> view that we try to call kmalloc()

I think there might be situations where you want to do that, but since
we're talking _printing_, we also know that the buffering normally is
about a single line.

Sure, some situations might want to buffer more before they print out
(perhaps you want to have guarantees that the register state of an
oops never gets mixed up with anything else, or whatever), and maybe
sometimes you'd want bigger lines.

But I definitely suspect that "single line" is often sufficient. I
mean, that's all that KERN_CONT ever gave you anyway (and not
reliably).

And then a 80 character buffer really isn't any different from having
a structure with a few pointers in it, which we do on the stack all
the time.

                  Linus

[toc] | [prev] | [next] | [standalone]

#1722915

On Tue, 29 Aug 2017 10:12:22 -0700
Linus Torvalds <torvalds@linux-foundation.org> wrote:

> On Tue, Aug 29, 2017 at 10:00 AM, Linus Torvalds
> <torvalds@linux-foundation.org> wrote:
> >
> > I refuse to help those things. We mis-designed things  
> 
> Actually, let me rephrase that:
> 
> It might actually be a good idea to help those things, by making
> helper functions available that do the marshalling.
> 
> So not calling "printk()" directly, but having a set of simple
> "buffer_print()" functions where each user has its own buffer, and
> then the "buffer_print()" functions will help people do nicely output
> data.
> 
> So if the issue is that people want to print (for example) hex dumps
> one character at a time, but don't want to have each character show up
> on a line of their own, I think we might well add a few functions to
> help dop that.
> 
> But they wouldn't be "printk". They would be the buffering functions
> that then call printk when tyhey have buffered a line.
> 
> That avoids the whole nasty issue with printk - printk wants to show
> stuff early (because _maybe_ it's critical) and printk wants to make
> log records with timestamps and loglevels. And printk has serious
> locking issues that are really nasty and fundamental.
> 
> A private buffer has none of those issues.

What about using the seq_buf*() then?

	struct seq_buf s;

	buf = kmalloc(mysize);
	seq_buf_init(&s, buf, mysize);

	seq_printf(&s,"blah blah %d", bah_blah);
	[...]
	seq_printf(&s, "my last print\n");

	printk("%.*s", s.len, s.buffer);

	kfree(buf);

This is what the NMI "safe" printks basically do.

-- Steve

[toc] | [prev] | [next] | [standalone]

#1722927

On Tue, Aug 29, 2017 at 4:50 PM, Steven Rostedt <rostedt@goodmis.org> wrote:
>
> What about using the seq_buf*() then?

They do have the nice property that because we use them for various
/proc files, there are some helper functions in addition to just the
puts/printt/vprintf.

Ie seq_buf_putmem_hex().

And yeah, you can just do

        char buffer[80];
        struct seq_buf s;

        seq_buf_init(&s, buffer, sizeof(buffer));

if you want to use a stack buffer for a single line.

          Linus

[toc] | [prev] | [next] | [standalone]

#1722948

Hello,

On (08/29/17 19:50), Steven Rostedt wrote:
[..]
> > A private buffer has none of those issues.
> 
> What about using the seq_buf*() then?
> 
> 	struct seq_buf s;
> 
> 	buf = kmalloc(mysize);
> 	seq_buf_init(&s, buf, mysize);
> 
> 	seq_printf(&s,"blah blah %d", bah_blah);
> 	[...]
> 	seq_printf(&s, "my last print\n");
> 
> 	printk("%.*s", s.len, s.buffer);
> 
> 	kfree(buf);

could do. for a single continuation line printk("%.*s", s.len, s.buffer)
this will work perfectly fine. for a more general case - backtraces, dumps,
etc. - this requires some tweaks.

	-ss

[toc] | [prev] | [next] | [standalone]

#1722957

On Wed, 30 Aug 2017 10:03:48 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> Hello,
> 
> On (08/29/17 19:50), Steven Rostedt wrote:
> [..]
> > > A private buffer has none of those issues.  
> > 
> > What about using the seq_buf*() then?
> > 
> > 	struct seq_buf s;
> > 
> > 	buf = kmalloc(mysize);
> > 	seq_buf_init(&s, buf, mysize);
> > 
> > 	seq_printf(&s,"blah blah %d", bah_blah);
> > 	[...]
> > 	seq_printf(&s, "my last print\n");
> > 
> > 	printk("%.*s", s.len, s.buffer);
> > 
> > 	kfree(buf);  
> 
> could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> this will work perfectly fine. for a more general case - backtraces, dumps,
> etc. - this requires some tweaks.

We could simply add a seq_buf_printk() that is implemented in the printk
proper, to parse the seq_buf buffer properly, and add the timestamps and
such.

-- Steve

[toc] | [prev] | [next] | [standalone]

#1722963

On (08/29/17 21:10), Steven Rostedt wrote:
> > On (08/29/17 19:50), Steven Rostedt wrote:
> > [..]
> > > > A private buffer has none of those issues.  
> > > 
> > > What about using the seq_buf*() then?
> > > 
> > > 	struct seq_buf s;
> > > 
> > > 	buf = kmalloc(mysize);
> > > 	seq_buf_init(&s, buf, mysize);
> > > 
> > > 	seq_printf(&s,"blah blah %d", bah_blah);
> > > 	[...]
> > > 	seq_printf(&s, "my last print\n");
> > > 
> > > 	printk("%.*s", s.len, s.buffer);
> > > 
> > > 	kfree(buf);  
> > 
> > could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> > this will work perfectly fine. for a more general case - backtraces, dumps,
> > etc. - this requires some tweaks.
> 
> We could simply add a seq_buf_printk() that is implemented in the printk
> proper, to parse the seq_buf buffer properly, and add the timestamps and
> such.

sounds like a plan :)

	-ss

[toc] | [prev] | [next] | [standalone]

#1722967

On Tue, 2017-08-29 at 21:10 -0400, Steven Rostedt wrote:
> On Wed, 30 Aug 2017 10:03:48 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > Hello,
> > 
> > On (08/29/17 19:50), Steven Rostedt wrote:
> > [..]
> > > > A private buffer has none of those issues.  
> > > 
> > > What about using the seq_buf*() then?
> > > 
> > > 	struct seq_buf s;
> > > 
> > > 	buf = kmalloc(mysize);
> > > 	seq_buf_init(&s, buf, mysize);
> > > 
> > > 	seq_printf(&s,"blah blah %d", bah_blah);
> > > 	[...]
> > > 	seq_printf(&s, "my last print\n");
> > > 
> > > 	printk("%.*s", s.len, s.buffer);
> > > 
> > > 	kfree(buf);  
> > 
> > could do. for a single continuation line printk("%.*s", s.len, s.buffer)
> > this will work perfectly fine. for a more general case - backtraces, dumps,
> > etc. - this requires some tweaks.
> 
> We could simply add a seq_buf_printk() that is implemented in the printk
> proper, to parse the seq_buf buffer properly, and add the timestamps and
> such.

No need.  printk would already add timestamps.

One addition might be to add a bit to initialize
the buffer so that printk("%s", s->buffer) is simpler.
---
diff --git a/include/linux/seq_buf.h b/include/linux/seq_buf.h
index fb7eb9ccb1cd..fb6c9de0ee33 100644
--- a/include/linux/seq_buf.h
+++ b/include/linux/seq_buf.h
@@ -26,6 +26,7 @@ static inline void seq_buf_clear(struct seq_buf *s)
 {
 	s->len = 0;
 	s->readpos = 0;
+	*s->buffer = 0;
 }
 
 static inline void

[toc] | [prev] | [next] | [standalone]

#1722976

On (08/29/17 18:52), Joe Perches wrote:
[..]
> > We could simply add a seq_buf_printk() that is implemented in the printk
> > proper, to parse the seq_buf buffer properly, and add the timestamps and
> > such.
> 
> No need.  printk would already add timestamps.

the idea is not to do printk() on that seq buffer at all, but to
log_store(), atomically, seq buffer messages

	spin_lock(&logbuf_lock)
	while (offset < seq_buffer->len) {
		...
		log_store(seq->buffer + offset);
		...
	}
	spin_unlock(&logbuf_unlock)

	-ss

[toc] | [prev] | [next] | [standalone]

Page 1 of 3  [1] 2 3  Next page →

Back to top | Article view | linux.kernel

csiph-web