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 2 of 3 — ← Prev page 1 [2] 3  Next page →

#1722980

On Wed, 2017-08-30 at 11:25 +0900, Sergey Senozhatsky wrote:
> 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)

Why?

What's wrong with a simple printk?
It'd still do a log_store.

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

#1722983

On (08/29/17 19:31), Joe Perches wrote:
[..]
> > 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)
> 
> Why?
> 
> What's wrong with a simple printk?
> It'd still do a log_store.

sure, it will. but in separate logbuf entries, and between two
consequent printk calls on the same CPU a lot of stuff can happen:
IRQs->printks, rescheduling->printks, etc. etc. (not to mention
concurrent printks from other CPUs) so what people want to have is
to have a way to make several printks appear next to each other in
the logs (dmesg or serial log). Tetsuo wants this, for instance,
for OOM reports and backtraces. SCIS/ATA people want it as well.

	-ss

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

#1722985

On Wed, 2017-08-30 at 11:47 +0900, Sergey Senozhatsky wrote:
> On (08/29/17 19:31), Joe Perches wrote:
> [..]
> > > 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)
> > 
> > Why?
> > 
> > What's wrong with a simple printk?
> > It'd still do a log_store.
> 
> sure, it will. but in separate logbuf entries, and between two
> consequent printk calls on the same CPU a lot of stuff can happen:

I think you don't quite understand how this would work.
The idea is that the entire concatenated bit would be emitted
in one go.

One use case already in place with seq_buf_init is in
drivers/clk/tegra/clk-bpmp.c

Basically, it's

    static void tegra_bpmp_clk_info_dump(struct tegra_bpmp *bpmp,
    	    	    	    	         const char *level,
    	    	    	    	         const struct tegra_bpmp_clk_info *info)
    {
    	    const char *prefix = "";
    	    struct seq_buf buf;
    	    unsigned int i;
    	    char flags[64];

    	    seq_buf_init(&buf, flags, sizeof(flags));

    	    if (info->flags)
    	    	    seq_buf_printf(&buf, "(");

    	    if (info->flags & TEGRA_BPMP_CLK_HAS_MUX) {
    	    	    seq_buf_printf(&buf, "%smux", prefix);
    	    	    prefix = ", ";
    	    }

    	    if ((info->flags & TEGRA_BPMP_CLK_HAS_SET_RATE) == 0) {
    	    	    seq_buf_printf(&buf, "%sfixed", prefix);
    	    	    prefix = ", ";
    	    }

    	    if (info->flags & TEGRA_BPMP_CLK_IS_ROOT) {
    	    	    seq_buf_printf(&buf, "%sroot", prefix);
    	    	    prefix = ", ";
    	    }

    	    if (info->flags)
    	    	    seq_buf_printf(&buf, ")");

    	    [...]
    	    dev_printk(level, bpmp->dev, "  flags: %lx %s\n", info->flags, flags);

so that the dev_printk is simply emitting a buffer from
concatenated strings via the seq_buf_printf uses.

The other use case would be an entire printk buffer
all at once.

ala:

	seq_buf_init(seq, buf, sizeof(buf));
	seq_buf_printf(&buf, "KERN_<LEVEL> fmt...", args...)
	for (i = 0; i < bar; i++)
		seq_buf_printf(&buf, fmt, ...)
	seq_buf_printk(&buf);

or:

	seq_buf_init(seq, buf, sizeof(buf));
	seq_buf_printf(&buf,
fmt, args...)
	for (i = 0; i < bar; i++)
		seq_buf_printf(&bu
f, fmt, args...)
	seq_buf_printk(&buf, KERN_<LEVEL>);

I can't think of another use case.

Can you?

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

#1723034

On (08/29/17 19:58), Joe Perches wrote:
> > > 
> > > Why?
> > > 
> > > What's wrong with a simple printk?
> > > It'd still do a log_store.
> > 
> > sure, it will. but in separate logbuf entries, and between two
> > consequent printk calls on the same CPU a lot of stuff can happen:
> 
> I think you don't quite understand how this would work.
> The idea is that the entire concatenated bit would be emitted
> in one go.

may be :)

I was thinking about the way to make it work in similar way with
printk-safe/printk-nmi. basically seq buffer should hold both
continuation and "normal" lines, IMHO. when we emit the buffer
we do something like this

	/* Print line by line. */
	while (c < end) {
		if (*c == '\n') {
			printk_safe_flush_line(start, c - start + 1);
			start = ++c;
			header = true;
			continue;
		}

		/* Handle continuous lines or missing new line. */
		if ((c + 1 < end) && printk_get_level(c)) {
			if (header) {
				c = printk_skip_level(c);
				continue;
			}

			printk_safe_flush_line(start, c - start);
			start = c++;
			header = true;
			continue;
		}

		header = false;
		c++;
	}

except that instead of printk_safe_flush_line() we will call log_store()
and the whole loop will be under logbuf_lock.

for that to work, we need API to require header/loglevel etc for every
message. so the use case can look like this:

	init_printk_buffer(&buf);
	print_line(&buf, KERN_ERR "Oops....\n");

	print_line(&buf, KERN_ERR "continuation line: foo");
	print_line(&buf, KERN_CONT "bar");
	print_line(&buf, KERN_CONT "baz\n");
	...

	print_line(&buf, KERN_ERR "....\n");
	...
	print_line(&buf, KERN_ERR "--- end of oops ---\n");
	emit_printk_buffer(&buf);

so that not only concatenated continuation lines will be handled,
but also more complex things. like backtraces or whatever someone
might want to handle.

	-ss

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

#1728747

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

On Wed 2017-08-30 14:37:34, Sergey Senozhatsky wrote:
> On (08/29/17 19:58), Joe Perches wrote:
> > > > 
> > > > Why?
> > > > 
> > > > What's wrong with a simple printk?
> > > > It'd still do a log_store.
> > > 
> > > sure, it will. but in separate logbuf entries, and between two
> > > consequent printk calls on the same CPU a lot of stuff can happen:
> > 
> > I think you don't quite understand how this would work.
> > The idea is that the entire concatenated bit would be emitted
> > in one go.
> 
> may be :)
> 
> I was thinking about the way to make it work in similar way with
> printk-safe/printk-nmi. basically seq buffer should hold both
> continuation and "normal" lines, IMHO. when we emit the buffer
> we do something like this
> 
> 	/* Print line by line. */
> 	while (c < end) {
> 		if (*c == '\n') {
> 			printk_safe_flush_line(start, c - start + 1);
> 			start = ++c;
> 			header = true;
> 			continue;
> 		}
> 
> 		/* Handle continuous lines or missing new line. */
> 		if ((c + 1 < end) && printk_get_level(c)) {
> 			if (header) {
> 				c = printk_skip_level(c);
> 				continue;
> 			}
> 
> 			printk_safe_flush_line(start, c - start);
> 			start = c++;
> 			header = true;
> 			continue;
> 		}
> 
> 		header = false;
> 		c++;
> 	}
> 
> except that instead of printk_safe_flush_line() we will call log_store()
> and the whole loop will be under logbuf_lock.
> 
> for that to work, we need API to require header/loglevel etc for every
> message. so the use case can look like this:
> 
> 	init_printk_buffer(&buf);
> 	print_line(&buf, KERN_ERR "Oops....\n");
> 
> 	print_line(&buf, KERN_ERR "continuation line: foo");
> 	print_line(&buf, KERN_CONT "bar");
> 	print_line(&buf, KERN_CONT "baz\n");
> 	...
> 
> 	print_line(&buf, KERN_ERR "....\n");
> 	...
> 	print_line(&buf, KERN_ERR "--- end of oops ---\n");
> 	emit_printk_buffer(&buf);
> 
> so that not only concatenated continuation lines will be handled,
> but also more complex things. like backtraces or whatever someone
> might want to handle.

For oopses... please don't. It is quite important that Oops goes out
"as soon as possible". I have seen oopses cut in half, etc... They are
still quite helpful.
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

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

#1726588

On Wed 2017-08-30 11:47:03, Sergey Senozhatsky wrote:
> On (08/29/17 19:31), Joe Perches wrote:
> [..]
> > > 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)
> > 
> > Why?
> 
> Tetsuo wants this, for instance,
> for OOM reports and backtraces. SCIS/ATA people want it as well.

The mixing of related lines might cause problems. But I am not sure
if it can be fixed a safe way on the printk side. Especially I am
afraid of an extensive buffering.

My underestanding, of the discussion about printk kthread patchset,
is that printk() has the following priorities:

  1. do not break the system (deadlock, livelock, softlock)
  2. get the message out (suddent death, panic, flood of messages)
  3. keep the message readable (cont lines, related lines)

Any buffering would delay showing the message. It increases
the risk that nobody will see it at all. It is acceptable
in printk_safe() and printk_safe_nmi() because we did not
find a better way to avoid the deadlock. But I am not sure
about any buffering used for a better readability. It is
against the priorities mentioned above.

Well, the buffering might be acceptable for single lines. I mean
to solve KERN_CONT problems. A good API might allow to get rid
of KERN_CONT, and the unreliable and rather complex code around
struct cont in kernel/printk/printk.c.

I would be afraid of adding an API that would allow to
(transparently) redirect printing into a buffer from a huge
amount of code.

Alternative solution would be to print more information
per-line, for example:

   <timestamp> <PID> <context> message

Then you might extract the related lines using a simple
grep. It would be similar to the output of
strace -f -t -o <log> <command>.

Best Regards,
Petr

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

#1726596

On (09/05/17 11:44), Petr Mladek wrote:
[..]
> > Tetsuo wants this, for instance,
> > for OOM reports and backtraces. SCIS/ATA people want it as well.
> 
> The mixing of related lines might cause problems. But I am not sure
> if it can be fixed a safe way on the printk side. Especially I am
> afraid of an extensive buffering.
> 
> My underestanding, of the discussion about printk kthread patchset,
> is that printk() has the following priorities

this discussion is not related to printk ktrehad. it's just the
first messages was posted as a reply to printk kthread patch set,
other than that it's unrelated.


> Any buffering would delay showing the message. It increases
> the risk that nobody will see it at all. It is acceptable
> in printk_safe() and printk_safe_nmi() because we did not
> find a better way to avoid the deadlock.

that's why I want buffered printk to re-use the printk-safe buffer
on that particular CPU [ if buffered printk will ever land ].
printk-safe buffer is not allocated on stack, or kmalloc-ed for
temp usafe, and, more importantly, we flush it from panic().

and I'm not sure that lost messages due to missing panic flush()
can really be an option even for a single cont line buffer. well,
may be it can. printk has a sort of guarantee that messages will
be at some well known location when pr_foo or printk function
returns. buffered printk kills it. and I don't want to have
several "flavors" of printk. printk-safe buffer seems to be the
way to preserve that guarantee.

	-ss

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

#1726661

On Tue 2017-09-05 18:59:00, Sergey Senozhatsky wrote:
> On (09/05/17 11:44), Petr Mladek wrote:
> [..]
> > > Tetsuo wants this, for instance,
> > > for OOM reports and backtraces. SCIS/ATA people want it as well.
> > 
> > The mixing of related lines might cause problems. But I am not sure
> > if it can be fixed a safe way on the printk side. Especially I am
> > afraid of an extensive buffering.
> > 
> > My underestanding, of the discussion about printk kthread patchset,
> > is that printk() has the following priorities
> 
> this discussion is not related to printk ktrehad. it's just the
> first messages was posted as a reply to printk kthread patch set,
> other than that it's unrelated.

But it is related in the sense of what people expect from printk().
This has been discussed in all the patchsets that try to avoid
soft-lockups. Any printk() feature or fix must be in sync with
these expectations. See below for more.


> > Any buffering would delay showing the message. It increases
> > the risk that nobody will see it at all. It is acceptable
> > in printk_safe() and printk_safe_nmi() because we did not
> > find a better way to avoid the deadlock.
> 
> that's why I want buffered printk to re-use the printk-safe buffer
> on that particular CPU [ if buffered printk will ever land ].
> printk-safe buffer is not allocated on stack, or kmalloc-ed for
> temp usafe, and, more importantly, we flush it from panic().
> 
> and I'm not sure that lost messages due to missing panic flush()
> can really be an option even for a single cont line buffer. well,
> may be it can. printk has a sort of guarantee that messages will
> be at some well known location when pr_foo or printk function
> returns. buffered printk kills it. and I don't want to have
> several "flavors" of printk. printk-safe buffer seems to be the
> way to preserve that guarantee.

But the well known locations would help only when they are flushed
in panic() or when a crashdump is created. They do not help
in other cases, especially where there is a sudden death.

There are many fears that printk offloading does not have enough
guarantees to actually happen. IMHO, there must be similar fears
that the messages in a temporary buffer will never get flushed.

And there are more risks with this approach:

  + soft-lockups caused by disabled preemption; we would
    need this to stay on the same CPU and use the same buffer

  + broken preempt-count and missing message when one forgets
    to close the buffered section or do it twice

  + lost messages because a per-CPU buffer size limitations

  + races in printk_safe() that is not recursions safe

  + not to say the problems mentioned by Linus as reply
    to the Tetsuo's proposal, see
https://lkml.kernel.org/r/CA+55aFx+5R-vFQfr7+Ok9Yrs2adQ2Ma4fz+S6nCyWHY_-2mrmw@mail.gmail.com


Some of these problems would be solved by a custom buffer.
But you are right. There are less guarantees that it would
get flushed or that it can be found in case of troubles.
Now, I am not sure that it is a good idea to use it even
for a single continuous line.

I wonder if all this is worth the effort, complexity, and risk.
We are talking about cosmetic problems after all.

Well, what do you think about the extra printed information?
For example:

    <timestamp> <PID> <context> message

It looks straightforward to me. These information
might be helpful on its own. So, it might be a
win-win solution.

Best Regards,
Petr

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

#1726665

Petr Mladek wrote:
> Some of these problems would be solved by a custom buffer.
> But you are right. There are less guarantees that it would
> get flushed or that it can be found in case of troubles.
> Now, I am not sure that it is a good idea to use it even
> for a single continuous line.
> 
> I wonder if all this is worth the effort, complexity, and risk.
> We are talking about cosmetic problems after all.
> 
> Well, what do you think about the extra printed information?
> For example:
> 
>     <timestamp> <PID> <context> message
> 
> It looks straightforward to me. These information
> might be helpful on its own. So, it might be a
> win-win solution.

Yes, if buffering multiple lines will not be implemented, I do want
printk context identifier field for each line. I think <PID> <context>
part will be something like TASK#pid (if outside interrupt) or
CPU#cpunum/#irqlevel (if inside interrupt).

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

#1726779

On (09/05/17 21:35), Tetsuo Handa wrote:
[..]
> > Well, what do you think about the extra printed information?
> > For example:
> > 
> >     <timestamp> <PID> <context> message
> > 
> > It looks straightforward to me. These information
> > might be helpful on its own. So, it might be a
> > win-win solution.
> 
> Yes, if buffering multiple lines will not be implemented, I do want
> printk context identifier field for each line. I think <PID> <context>
> part will be something like TASK#pid (if outside interrupt) or
> CPU#cpunum/#irqlevel (if inside interrupt).

well, depending on what's your aim.

it's not always printk() that causes troubles, but console_unlock().
which is busy because of printk()-s. and those are not necessarily
running on the same CPU. so if you want to have a full picture (don't
know what for) then you need to log both vprintk_emit() and
console_unlock() sides. vprintk_emit() side requires changes to
`struct printk_log', console_unlock() does not - you can just sprintf()
the required data to `text' buffer.

for example, I do the following on my PC boxes to keep track the
behaviour of printk kthread offloading.

---

diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index a4e3f84ef365..ac1fd606d6c5 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -2493,15 +2493,16 @@ void console_unlock(void)
                        seen_seq = log_next_seq;
                }
 
+               len = sprintf(text, "{%s/%d/%d}", current->comm,
+                               smp_processor_id(), do_cond_resched);
+
                if (console_seq < log_first_seq) {
-                       len = sprintf(text, "** %u printk messages dropped ** ",
+                       len += sprintf(text + len, "** %u printk messages dropped ** ",
                                      (unsigned)(log_first_seq - console_seq));
 
                        /* messages are gone, move to first one */
                        console_seq = log_first_seq;
                        console_idx = log_first_idx;
-               } else {
-                       len = 0;
                }
 skip:
                if (did_offload || console_seq == log_next_seq)

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

#1726740

On (09/05/17 14:21), Petr Mladek wrote:
[..]
> > that's why I want buffered printk to re-use the printk-safe buffer
> > on that particular CPU [ if buffered printk will ever land ].
> > printk-safe buffer is not allocated on stack, or kmalloc-ed for
> > temp usafe, and, more importantly, we flush it from panic().
> > 
> > and I'm not sure that lost messages due to missing panic flush()
> > can really be an option even for a single cont line buffer. well,
> > may be it can. printk has a sort of guarantee that messages will
> > be at some well known location when pr_foo or printk function
> > returns. buffered printk kills it. and I don't want to have
> > several "flavors" of printk. printk-safe buffer seems to be the
> > way to preserve that guarantee.
> 
> But the well known locations would help only when they are flushed
> in panic() or when a crashdump is created. They do not help
> in other cases, especially where there is a sudden death.

if the system locked up and there is no panic()->flush_on_panic(),
no console_unlock(), crashdump, no nothing - then even having
messages in the logbuf is probably not really helpful. you can't
reach them anyway :)
so yes, I'm speaking here about the cases when we flush_on_panic()
or/and generate crash dump.


> There are many fears that printk offloading does not have enough
> guarantees to actually happen. IMHO, there must be similar fears
> that the messages in a temporary buffer will never get flushed.
> 
> And there are more risks with this approach:
> 
>   + soft-lockups caused by disabled preemption; we would
>     need this to stay on the same CPU and use the same buffer

well, yes. like any control path that disables IRQs there are
rules to follow. so printk-safe based solution has limitations.
I mentioned them probably every time I speak about printk-safe
buffering. but those limitations come with a bonus - flush on
panic and well known location of the messages.

one thing to notice, is that
printk-safe is usually faster than printk() or at least as fast as
the fastest printk() path. because, unlike printk, it does not take
spin on the logbuf lock; it does not console_trylock(), it does not
do console_unlock().


>   + broken preempt-count and missing message when one forgets
>     to close the buffered section or do it twice

yes, coding errors are possible.


>   + lost messages because a per-CPU buffer size limitations

which is true for any type of buffers. including logbuf. and
stack allocated buffers, any buffer. printk-safe buffer is at
least much-much bigger than any stack allocated buffer.


>   + races in printk_safe() that is not recursions safe
>
>   + not to say the problems mentioned by Linus as reply
>     to the Tetsuo's proposal, see
> https://lkml.kernel.org/r/CA+55aFx+5R-vFQfr7+Ok9Yrs2adQ2Ma4fz+S6nCyWHY_-2mrmw@mail.gmail.com

like "limited in where you can actually expect buffering to happen"?

sure. it does not come for free, it's not all beautiful and shiny.


[..]
> I wonder if all this is worth the effort, complexity, and risk.
> We are talking about cosmetic problems after all.

the thing about printk-safe buffering is that _mostly_ everything
is already in the kernel. especially if we talk about single cont
line buffering. just add public API printk_buffering_begin() and
printk_buffering_end() that will __printk_safe_enter() and
__printk_safe_exit(). and that's it. unless I'm missing something.

but I'm not super eager to have printk-safe based buffering.
that's why I never posted a patch set. this approach has its
limitations.


> Well, what do you think about the extra printed information?
> For example:
> 
>     <timestamp> <PID> <context> message
> 
> It looks straightforward to me. These information
> might be helpful on its own. So, it might be a
> win-win solution.

hm... don't know. frankly, I never found PID useful. I mostly look
at the serial logs postmortem. so lines
	12231 foo
	21331 bar

are not much better than just
	foo
	bar


I prepend every line with the CPU number that has printk()-ed it.
and that's helpful because one can grep and filter out messages
from other CPUs. it's quite OK thing to have given that messages
can be really mixed sometimes.

so adding extra information to `struct printk_log' could be helpful.
I think we had this discussion before and you didn't want to change
the size of `struct printk_log' because that might break gdb/crash/etc
user space tools. has it changed?

may be we can #ifdef CONFIG_PRINTK_ABC them.

	-ss

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

#1727192

On Tue 2017-09-05 22:42:28, Sergey Senozhatsky wrote:
> On (09/05/17 14:21), Petr Mladek wrote:
> [..]
> > > that's why I want buffered printk to re-use the printk-safe buffer
> > > on that particular CPU [ if buffered printk will ever land ].
> > > printk-safe buffer is not allocated on stack, or kmalloc-ed for
> > > temp usafe, and, more importantly, we flush it from panic().
> > > 
> > > and I'm not sure that lost messages due to missing panic flush()
> > > can really be an option even for a single cont line buffer. well,
> > > may be it can. printk has a sort of guarantee that messages will
> > > be at some well known location when pr_foo or printk function
> > > returns. buffered printk kills it. and I don't want to have
> > > several "flavors" of printk. printk-safe buffer seems to be the
> > > way to preserve that guarantee.
> > 
> > But the well known locations would help only when they are flushed
> > in panic() or when a crashdump is created. They do not help
> > in other cases, especially where there is a sudden death.
> 
> if the system locked up and there is no panic()->flush_on_panic(),
> no console_unlock(), crashdump, no nothing - then even having
> messages in the logbuf is probably not really helpful. you can't
> reach them anyway :)
> so yes, I'm speaking here about the cases when we flush_on_panic()
> or/and generate crash dump.

Why are we that much paranoid about the locked up system when
discussing the console handling offload (printk kthread)?
Why should we be more relaxed when talking about pushing
messages from extra buffers?


> > There are many fears that printk offloading does not have enough
> > guarantees to actually happen. IMHO, there must be similar fears
> > that the messages in a temporary buffer will never get flushed.
> > 
> > And there are more risks with this approach:
> > 
> >   + soft-lockups caused by disabled preemption; we would
> >     need this to stay on the same CPU and use the same buffer
> 
> well, yes. like any control path that disables IRQs there are
> rules to follow. so printk-safe based solution has limitations.
> I mentioned them probably every time I speak about printk-safe
> buffering. but those limitations come with a bonus - flush on
> panic and well known location of the messages.
> 
> one thing to notice, is that
> printk-safe is usually faster than printk() or at least as fast as
> the fastest printk() path. because, unlike printk, it does not take
> spin on the logbuf lock; it does not console_trylock(), it does not
> do console_unlock().
> 
> 
> >   + broken preempt-count and missing message when one forgets
> >     to close the buffered section or do it twice
> 
> yes, coding errors are possible.
> 
> 
> >   + lost messages because a per-CPU buffer size limitations
> 
> which is true for any type of buffers. including logbuf. and
> stack allocated buffers, any buffer. printk-safe buffer is at
> least much-much bigger than any stack allocated buffer.
> 
> 
> >   + races in printk_safe() that is not recursions safe
> >
> >   + not to say the problems mentioned by Linus as reply
> >     to the Tetsuo's proposal, see
> > https://lkml.kernel.org/r/CA+55aFx+5R-vFQfr7+Ok9Yrs2adQ2Ma4fz+S6nCyWHY_-2mrmw@mail.gmail.com
> 
> like "limited in where you can actually expect buffering to happen"?
> 
> sure. it does not come for free, it's not all beautiful and shiny.

It is great that we see the risks and limitations.

> 
> [..]
> > I wonder if all this is worth the effort, complexity, and risk.
> > We are talking about cosmetic problems after all.
> 
> the thing about printk-safe buffering is that _mostly_ everything
> is already in the kernel. especially if we talk about single cont
> line buffering. just add public API printk_buffering_begin() and
> printk_buffering_end() that will __printk_safe_enter() and
> __printk_safe_exit(). and that's it. unless I'm missing something.
> 
> but I'm not super eager to have printk-safe based buffering.
> that's why I never posted a patch set. this approach has its
> limitations.

Ah, I am happy to read this. From the previous mails,
I got the feeling that you were eager to go this way.

I personally do not feel comfortable with taking all the risks
and limitations just to avoid mixed messages.

To be more precise. I am more and more pessimistic about
getting a safe buffer-based solution for multiple lines.

Well, it might make some sense for continuous lines. The
entire line should get printed within few lines of code
and limited time. Otherwise people could hardly expect
to see the pieces together. Then all the above risks and
limitations might be small and acceptable.


> > Well, what do you think about the extra printed information?
> > For example:
> > 
> >     <timestamp> <PID> <context> message
> > 
> > It looks straightforward to me. These information
> > might be helpful on its own. So, it might be a
> > win-win solution.
> 
> hm... don't know. frankly, I never found PID useful. I mostly look
> at the serial logs postmortem. so lines
> 	12231 foo
> 	21331 bar
> 
> are not much better than just
> 	foo
> 	bar

Sure, the main intention is to allow greping.


> I prepend every line with the CPU number that has printk()-ed it.
> and that's helpful because one can grep and filter out messages
> from other CPUs. it's quite OK thing to have given that messages
> can be really mixed sometimes.
> 
> so adding extra information to `struct printk_log' could be helpful.
> I think we had this discussion before and you didn't want to change
> the size of `struct printk_log' because that might break gdb/crash/etc
> user space tools. has it changed?

Yup, there should be a serious reason to change 'struct printk_log'.
I am not sure if this is the case. But I am sure that there will
be need to change the structure sooner or later.

Anyway, it seems that we will need to update all the tools
for the different time stamps, see
https://lkml.kernel.org/r/1504613201-23868-1-git-send-email-prarit@redhat.com
Then we will be more clever how painful it is.


> may be we can #ifdef CONFIG_PRINTK_ABC them.

I agree that this kind of change should be optional.

Best Regards,
Petr

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

#1725062

On (08/29/17 21:10), Steven Rostedt wrote:
[..]
> > 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.

so I quickly cooked the first version. like really quickly. just to
check if this is what people might like/use.

RFC.

so wondering if this will suffice. the name is somewhat hideous -- prbuf(),
wanted to keep it short and somehow aligned with pr_foo().

the patch also defines a number of prbuf_err()/prbuf_cont() macros that
call __prbuf_write() -- I don't want people to invoke __prbuf_write()
directly, because we need KERN_FOO prefix for stored messages and people
tend to forget to provide one.

prbuf_init() function inits the seq_buf buffer. it takes size and GFP
mask, just to permit prbuf usage from different contexts. if we fail
to kmalloc() the buffer, then __prbuf_write() does direct printk().

a usage example:


       struct seq_buf s;

       prbuf_init(&s, 256, GFP_KERNEL);

       prbuf_err(&s, "Opps at %lu\n", _RET_IP_);
       prbuf_info(&s, "Start of cont line");
       prbuf_cont(&s, " foo ");
       prbuf_cont(&s, " bar ");
       prbuf_cont(&s, " status: %s\n", "done");

       ret = 0;
       while (ret++ < 10)
               prbuf_err(&s, "%x\n", ret);

       prbuf_flush(&s);
       prbuf_free(&s);


this will store everything in conseq logbuf entries. if the buffer
was too small, we print overflow message.

any comments?

---
 include/linux/printk.h |  58 ++++++++++++++++
 kernel/printk/printk.c | 178 +++++++++++++++++++++++++++++++++++++++++--------
 2 files changed, 209 insertions(+), 27 deletions(-)

diff --git a/include/linux/printk.h b/include/linux/printk.h
index e10f27468322..ab39b85cff8e 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -206,6 +206,17 @@ void show_regs_print_info(const char *log_lvl);
 extern void printk_safe_init(void);
 extern void printk_safe_flush(void);
 extern void printk_safe_flush_on_panic(void);
+
+struct seq_buf;
+
+extern int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags);
+
+extern __printf(2, 3) __cold
+int __prbuf_write(struct seq_buf *s, const char *fmt, ...);
+
+extern int prbuf_flush(struct seq_buf *s);
+
+extern void prbuf_free(struct seq_buf *s);
 #else
 static inline __printf(1, 0)
 int vprintk(const char *s, va_list args)
@@ -277,6 +288,29 @@ static inline void printk_safe_flush(void)
 static inline void printk_safe_flush_on_panic(void)
 {
 }
+
+struct seq_buf;
+
+static inline
+int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
+{
+	return 0;
+}
+
+static inlin __printf(2, 3) __cold
+static int __prbuf_write(struct seq_buf *s, const char *fmt, ...)
+{
+	return 0;
+}
+
+static inline int prbuf_flush(struct seq_buf *s)
+{
+	return 0;
+}
+
+static inline void prbuf_free(struct seq_buf *s)
+{
+}
 #endif
 
 extern asmlinkage void dump_stack(void) __cold;
@@ -323,6 +357,30 @@ extern asmlinkage void dump_stack(void) __cold;
 	no_printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
 #endif
 
+/*
+ * Macros for buffered printk. All messages are stored in seq_buf instead of
+ * logbuf, user is required to flush the buffer in order to emit the messages
+ * and move them to the logbuf.
+ *
+ * Please use these macros and never call __prbuf_write() directly.
+ */
+#define prbuf_emerg(s, fmt, ...) \
+	__prbuf_write((s). KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_alert(s, fmt, ...) \
+	__prbuf_write((s), KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_crit(s, fmt, ...) \
+	__prbuf_write((s), KERN_CRIT pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_err(s, fmt, ...) \
+	__prbuf_write((s), KERN_ERR pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_warning(s, fmt, ...) \
+	__prbuf_write((s), KERN_WARNING pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_warn pr_buf_warning
+#define prbuf_notice(s, fmt, ...) \
+	__prbuf_write((s), KERN_NOTICE pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_info(s, fmt, ...) \
+	__prbuf_write((s), KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
+#define prbuf_cont(s, fmt, ...) \
+	__prbuf_write((s), KERN_CONT fmt, ##__VA_ARGS__)
 
 /* If you are writing a driver, please use dev_dbg instead */
 #if defined(CONFIG_DYNAMIC_DEBUG)
diff --git a/kernel/printk/printk.c b/kernel/printk/printk.c
index 512f7c2baedd..6ccc7edda3a4 100644
--- a/kernel/printk/printk.c
+++ b/kernel/printk/printk.c
@@ -48,6 +48,7 @@
 #include <linux/sched/clock.h>
 #include <linux/sched/debug.h>
 #include <linux/sched/task_stack.h>
+#include <linux/seq_buf.h>
 
 #include <linux/uaccess.h>
 #include <asm/sections.h>
@@ -1651,7 +1652,9 @@ static bool cont_add(int facility, int level, enum log_flags flags, const char *
 	return true;
 }
 
-static size_t log_output(int facility, int level, enum log_flags lflags, const char *dict, size_t dictlen, char *text, size_t text_len)
+static size_t log_output(int facility, int level, enum log_flags lflags,
+			 const char *dict, size_t dictlen,
+			 const char *text, size_t text_len)
 {
 	/*
 	 * If an earlier line was buffered, and we're a continuation
@@ -1680,33 +1683,11 @@ static size_t log_output(int facility, int level, enum log_flags lflags, const c
 	return log_store(facility, level, lflags, 0, dict, dictlen, text, text_len);
 }
 
-asmlinkage int vprintk_emit(int facility, int level,
-			    const char *dict, size_t dictlen,
-			    const char *fmt, va_list args)
+static int process_log(int facility, int level,
+		       const char *dict, size_t dictlen,
+		       const char *text, size_t text_len)
 {
-	static char textbuf[LOG_LINE_MAX];
-	char *text = textbuf;
-	size_t text_len;
 	enum log_flags lflags = 0;
-	unsigned long flags;
-	int printed_len;
-	bool in_sched = false;
-
-	if (level == LOGLEVEL_SCHED) {
-		level = LOGLEVEL_DEFAULT;
-		in_sched = true;
-	}
-
-	boot_delay_msec(level);
-	printk_delay();
-
-	/* This stops the holder of console_sem just where we want him */
-	logbuf_lock_irqsave(flags);
-	/*
-	 * The printf needs to come first; we need the syslog
-	 * prefix which might be passed-in as a parameter.
-	 */
-	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
 
 	/* mark and strip a trailing newline */
 	if (text_len && text[text_len-1] == '\n') {
@@ -1742,8 +1723,38 @@ asmlinkage int vprintk_emit(int facility, int level,
 	if (dict)
 		lflags |= LOG_PREFIX|LOG_NEWLINE;
 
-	printed_len = log_output(facility, level, lflags, dict, dictlen, text, text_len);
+	return log_output(facility, level, lflags, dict, dictlen, text, text_len);
+}
+
+asmlinkage int vprintk_emit(int facility, int level,
+			    const char *dict, size_t dictlen,
+			    const char *fmt, va_list args)
+{
+	static char textbuf[LOG_LINE_MAX];
+	char *text = textbuf;
+	size_t text_len;
+	unsigned long flags;
+	int printed_len;
+	bool in_sched = false;
+
+	if (level == LOGLEVEL_SCHED) {
+		level = LOGLEVEL_DEFAULT;
+		in_sched = true;
+	}
+
+	boot_delay_msec(level);
+	printk_delay();
 
+	/* This stops the holder of console_sem just where we want him */
+	logbuf_lock_irqsave(flags);
+	/*
+	 * The printf needs to come first; we need the syslog
+	 * prefix which might be passed-in as a parameter.
+	 */
+	text_len = vscnprintf(text, sizeof(textbuf), fmt, args);
+	printed_len = process_log(facility, level,
+				  dict, dictlen,
+				  text, text_len);
 	logbuf_unlock_irqrestore(flags);
 
 	/* If called from the scheduler, we can not call up(). */
@@ -1833,6 +1844,119 @@ asmlinkage __visible int printk(const char *fmt, ...)
 }
 EXPORT_SYMBOL(printk);
 
+int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
+{
+	char *b;
+
+	b = kmalloc(size, flags);
+	seq_buf_init(s, b, size);
+	return !!b;
+}
+EXPORT_SYMBOL(prbuf_init);
+
+/*
+ * Do not use this function directly. Use dedicated macros instead.
+ *
+ * If you'll you use this function, Linus will kindly ask you to
+ * consider other options.
+ */
+int __prbuf_write(struct seq_buf *s, const char *fmt, ...)
+{
+	va_list args;
+	int r;
+
+	va_start(args, fmt);
+	if (likely(s->buffer))
+		r = seq_buf_vprintf(s, fmt, args);
+	else
+		r = vprintk_func(fmt, args);
+	va_end(args);
+
+	return r;
+}
+EXPORT_SYMBOL(__prbuf_write);
+
+int prbuf_flush(struct seq_buf *s)
+{
+	unsigned long flags;
+	const char *start, *c, *end;
+	bool header;
+	int len = 0;
+
+	if (!s->buffer)
+		return 0;
+
+	start = s->buffer;
+	c = start;
+	end = start + seq_buf_used(s);
+	header = true;
+
+	logbuf_lock_irqsave(flags);
+
+	if (seq_buf_has_overflowed(s)) {
+		static const char *msg = KERN_ERR "Print buffer overflow\n";
+
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   msg, strlen(msg));
+	}
+
+	/* Print line by line. */
+	while (c < end) {
+		if (*c == '\n') {
+			len += process_log(0, LOGLEVEL_DEFAULT,
+					   NULL, 0,
+					   start, c - start + 1);
+			start = ++c;
+			header = true;
+			continue;
+		}
+
+		/* Handle continuous lines or missing new line. */
+		if ((c + 1 < end) && printk_get_level(c)) {
+			if (header) {
+				c = printk_skip_level(c);
+				continue;
+			}
+
+			len += process_log(0, LOGLEVEL_DEFAULT,
+					   NULL, 0,
+					   start, c - start);
+			start = c++;
+			header = true;
+			continue;
+		}
+
+		header = false;
+		c++;
+	}
+
+	/* Check if there was a partial line. Ignore pure header. */
+	if (start < end && !header) {
+		static const char *newline = KERN_CONT "\n";
+
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   start, end - start);
+		len += process_log(0, LOGLEVEL_DEFAULT,
+				   NULL, 0,
+				   newline, strlen(newline));
+	}
+
+	logbuf_unlock_irqrestore(flags);
+
+	seq_buf_clear(s);
+	return len;
+}
+EXPORT_SYMBOL(prbuf_flush);
+
+void prbuf_free(struct seq_buf *s)
+{
+	kfree(s->buffer);
+	seq_buf_init(s, NULL, 0);
+}
+EXPORT_SYMBOL(prbuf_free);
+
 #else /* CONFIG_PRINTK */
 
 #define LOG_LINE_MAX		0
-- 
2.14.1

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

#1725258

On Fri, 2017-09-01 at 22:19 +0900, Sergey Senozhatsky wrote:
> On (08/29/17 21:10), Steven Rostedt wrote:
> [..]
> > > 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.
> 
> so I quickly cooked the first version. like really quickly. just to
> check if this is what people might like/use.
> 
> RFC.
> 
> so wondering if this will suffice. the name is somewhat hideous -- prbuf(),
> wanted to keep it short and somehow aligned with pr_foo().

Yes, it's a poor name.  At least keep using a pr_ prefix.

> the patch also defines a number of prbuf_err()/prbuf_cont() macros that
> call __prbuf_write() -- I don't want people to invoke __prbuf_write()
> directly, because we need KERN_FOO prefix for stored messages and people
> tend to forget to provide one.

> prbuf_init() function inits the seq_buf buffer. it takes size and GFP
> mask, just to permit prbuf usage from different contexts. if we fail
> to kmalloc() the buffer, then __prbuf_write() does direct printk().

I think there's relatively little value in multiple line output.
It seems like buffering for buffering's sake.
Just keep it to a single line and simple.

> a usage example:
> 
> 
>        struct seq_buf s;
> 
>        prbuf_init(&s, 256, GFP_KERNEL);
> 
>        prbuf_err(&s, "Opps at %lu\n", _RET_IP_);
>        prbuf_info(&s, "Start of cont line");
>        prbuf_cont(&s, " foo ");
>        prbuf_cont(&s, " bar ");
>        prbuf_cont(&s, " status: %s\n", "done");
> 
>        ret = 0;
>        while (ret++ < 10)
>                prbuf_err(&s, "%x\n", ret);
> 
>        prbuf_flush(&s);
>        prbuf_free(&s);
> 
> 
> this will store everything in conseq logbuf entries. if the buffer
> was too small, we print overflow message.
> 
> any comments?
[]
> diff --git a/include/linux/printk.h b/include/linux/printk.h
[]
> @@ -277,6 +288,29 @@ static inline void printk_safe_flush(void)
>  static inline void printk_safe_flush_on_panic(void)
>  {
>  }
> +
> +struct seq_buf;
> +
> +static inline
> +int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
> +{
> +	return 0;
> +}
> +
> +static inlin __printf(2, 3) __cold

uncompiled

> +static int __prbuf_write(struct seq_buf *s, const char *fmt, ...)

inline

> +int prbuf_init(struct seq_buf *s, size_t size, gfp_t flags)
> +{
> +	char *b;
> +
> +	b = kmalloc(size, flags);
> +	seq_buf_init(s, b, size);
> +	return !!b;
> +}

Most of the time, this buffer should be on the stack
and not be malloc'd.

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

#1725330

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.

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!

               Linus

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

#1725843

Hello,

I'll answer to both Linus and Joe, just to keep it all one place.

On (09/01/17 13:21), Linus Torvalds wrote:
> 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()".

ok, pr_line sound good.

> 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.
> 
> 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!

hm... may be.
the main point of prbuf is not the support of cont lines, but the
fact that buffered messages are added to the logbuf atomically,
and thus are printed in consequent lines, not the usual way:

CPU0	because
CPU1	this
CPU0	it's easier
CPU1	might
CPU0	to read
CPU1	be
CPU1	inconvenient.
CPU0	seq messages.

some people want to be able to make it to look less spaghetti-like:

CPU0	because
CPU0	it's easier
CPU0	to read
CPU0	seq messages.
CPU1	this
CPU1	might
CPU1	be
CPU1	inconvenient.

and it's not something completely wrong to ask for, I think.
well, who knows.

there is only way to serialize printks against other printks -- take
the logbuf lock. and that's what pr_line/prbuf flush is doing.


now, pr_line/prbuf/pr_buf is, of course, very limited. it should NOT
be used for things that are really important and absolutely must [if
possible] appear in serial logs/on screens/etc. simply because panic
can happen on CPUA before we flush any pending pr_line/prbuf buffers
on other CPUs. and that's exactly the reason why I initially wanted
(and still do) to implement pr_line/prbuf using printk-safe
mechanism - because we flush printk-safe buffers from panic(). so
utilizing printk-safe buffers can make pr_line less fragile. apart
from that printk-safe buffers are always there, so OOM is not a show
stopper anymore. but, like I said in another email, printk-safe buffer
is per-CPU and is also used for actual printk-safe, hence it must be
used with local IRQs disabled when we "borrow" the buffer for pr_line
(disabled preemption is not enough due to possible IRQ printk-safe
print out). this can be a bit annoying.

in it's current form, pr_line/pr_buf is NOT a replacement for pr_cont
or printk(KERN_CONT). because pr_cont has no such thing as "we were
unable to flush the buffer from CPUB because of panic on CPUA". so
pr_cont/printk(KERN_CONT) beats pr_line/pr_buf here. This can be a
major limitation. am I wrong?


another thing,
if we eventually will decide to stick to "use a seq_buf with stack
allocated char buffer to hold a single line only" design, then I'm
not entirely sure I get it why do we want to add a new API at all.
I mean, the new API does not make anything simpler or shorter. we
need to declare the buffer, seq_buf, init seq_buf, append chars to
seq_buf, flush it:

	char buf[80];
	struct seq_buf cont_line;

	pr_line_init(&cont_line, buf, sizeof(buf));
	pr_line_printf(&cont_line, "....");
	pr_line_printf(&cont_line, "....");
	pr_line_flush(&cont_line);

this asks for  s/pr_line_/seq_buf_/g, no? well, except for the flush()
part. it can be replaced with printk("%s\n", cont_line->buffer).

so it seems that we need to re-think it.

	-ss

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

#1725844

On Mon, 2017-09-04 at 14:22 +0900, Sergey Senozhatsky wrote:
> there is only way to serialize printks against other printks -- take
> the logbuf lock.

If that's really necessary, instead make that
logbuf_lock a public interface and keep the rest
of the code simple.

I think it's more important to get printk to work
reliably than keep expanding the number of lines
possible to buffer.

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

#1726801

On Mon, 4 Sep 2017 14:22:46 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> like I said in another email, printk-safe buffer
> is per-CPU and is also used for actual printk-safe, hence it must be
> used with local IRQs disabled when we "borrow" the buffer for pr_line
> (disabled preemption is not enough due to possible IRQ printk-safe
> print out). this can be a bit annoying.

You can do what I did with trace_printk(). I have a buffer per context.
Then you only need to use preempt_disable() to do the print. That is,
trace_printk() has 4 buffers:

 1. Normal context
 2. softirq context
 3. irq context
 4. NMI context

It determines which context it is in, disables preemption, and uses the
corresponding buffer. This way I don't need to worry about being
preempted by an interrupt or NMI.

Grant it, it does make the memory needed 4x bigger.

I have an array of 4 buffers, and the following code:

static char *get_trace_buf(void)
{
	struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);

	if (!buffer || buffer->nesting >= 4)
		return NULL;

	return &buffer->buffer[buffer->nesting++][0];
}

Hmm, I probably need to add a "barrier()" before the return, or use a
this_cpu_inc() on nesting. As long as the nesting variable is updated
before the return of the buffer being used, then everything is fine.
Because we have:

static void put_trace_buf(void)
{
	this_cpu_dec(trace_percpu_buffer->nesting);
}

And anything that preempts this call will have returned it back to its
original state before returning.

-- Steve

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

#1727114

On (09/05/17 10:54), Steven Rostedt wrote:
> On Mon, 4 Sep 2017 14:22:46 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > like I said in another email, printk-safe buffer
> > is per-CPU and is also used for actual printk-safe, hence it must be
> > used with local IRQs disabled when we "borrow" the buffer for pr_line
> > (disabled preemption is not enough due to possible IRQ printk-safe
> > print out). this can be a bit annoying.
> 
> You can do what I did with trace_printk(). I have a buffer per context.
> Then you only need to use preempt_disable() to do the print. That is,
> trace_printk() has 4 buffers:
> 
>  1. Normal context
>  2. softirq context
>  3. irq context
>  4. NMI context

thanks. looks interesting.

> It determines which context it is in, disables preemption, and uses the
> corresponding buffer. This way I don't need to worry about being
> preempted by an interrupt or NMI.
> 
> Grant it, it does make the memory needed 4x bigger.

yep. that's a concern. buffered printk must come with a sound number
of users in this case. otherwise people will just see a massive bump
(x2) in memory usage for no particular reason.

> I have an array of 4 buffers, and the following code:
> 
> static char *get_trace_buf(void)
> {
> 	struct trace_buffer_struct *buffer = this_cpu_ptr(trace_percpu_buffer);
> 
> 	if (!buffer || buffer->nesting >= 4)
> 		return NULL;
> 
> 	return &buffer->buffer[buffer->nesting++][0];
> }
> 
> Hmm, I probably need to add a "barrier()" before the return, or use a
> this_cpu_inc() on nesting. As long as the nesting variable is updated
> before the return of the buffer being used, then everything is fine.
> Because we have:
> 
> static void put_trace_buf(void)
> {
> 	this_cpu_dec(trace_percpu_buffer->nesting);
> }
> 
> And anything that preempts this call will have returned it back to its
> original state before returning.

there is a tiny-tiny-tiny chance of losing some very specific messages
from the top most context. consider the following
	trace_printk("fat fingers %o\n", 100);

from the NMI (nesting 3) context. vscnprintf() must

	WARN_ONCE(1, "Unsupported flags modifier: %c\n", fmt[1]);

which will be lost - we are above the nesting limit buffer->nesting >= 4.
// vscnprintf()->... has several more recursion entry points.

	-ss

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

#1727119

On Tue, Sep 5, 2017 at 7:54 AM, Steven Rostedt <rostedt@goodmis.org> wrote:
> You can do what I did with trace_printk(). I have a buffer per context.
> Then you only need to use preempt_disable() to do the print. That is,
> trace_printk() has 4 buffers:
>
>  1. Normal context
>  2. softirq context
>  3. irq context
>  4. NMI context

This is exactly what Tetsuo's code did (except he also added the
current thread context), and I already told people once in this thread
why that doesn't work.

It may be fine if you want to do CPU tracing, but it's not acceptable
for the whole line buffering.

If I'm printing out bytes of a hex buffer, and I have a bug, and take
a page fault, the context above doesn't change.

But I sure as #%!Ing hell don't want the page fault information
buffered with my hex bytes.  They share no context at all.

So no. Stop this idiotic "implicit context". Get that disease off your
brain. It's wrong.

Either you guys are happy with the current line buffering, or you do
it with an explicit buffer context. No ifs, buts or idiotic context
markers.

                 Linus

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

Page 2 of 3 — ← Prev page 1 [2] 3  Next page →

Back to top | Article view | linux.kernel

csiph-web