All of lore.kernel.org
 help / color / mirror / Atom feed
From: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
To: Petr Mladek <pmladek@suse.com>,
	Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp>
Cc: Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com>,
	Sergey Senozhatsky <sergey.senozhatsky@gmail.com>,
	Dmitriy Vyukov <dvyukov@google.com>,
	Steven Rostedt <rostedt@goodmis.org>,
	Alexander Potapenko <glider@google.com>,
	Fengguang Wu <fengguang.wu@intel.com>,
	Josh Poimboeuf <jpoimboe@redhat.com>,
	LKML <linux-kernel@vger.kernel.org>,
	Linus Torvalds <torvalds@linux-foundation.org>,
	Andrew Morton <akpm@linux-foundation.org>,
	linux-mm@kvack.org, Ingo Molnar <mingo@redhat.com>,
	Peter Zijlstra <peterz@infradead.org>,
	Will Deacon <will.deacon@arm.com>
Subject: Re: [PATCH v6 1/3] printk: Add line-buffered printk() API.
Date: Mon, 12 Nov 2018 16:59:20 +0900	[thread overview]
Message-ID: <20181112075920.GA497@jagdpanzerIV> (raw)
In-Reply-To: <20181109141012.accx62deekzq5gh5@pathway.suse.cz>

On (11/09/18 15:10), Petr Mladek wrote:
> > 
> > If I'm not mistaken, this is for the futute "printk injection" work.
> 
> The above code only tries to push complete lines to the main log buffer
> and consoles ASAP. It sounds like a Good Idea(tm).

Probably it is. So *quite likely* I'm wrong here.

Hmm... Thinking out loud.
At the same time, splitting a single logbuf entry gives a chance to other
events to mix in. Example:
	pr_cont("Foo:");
	pr_cont("\nbar");
	pr_cont("\n");

Previously it could been stored in one logbuf entry (one logstore,
one console_trylock_spinning), which means that it could have been
printed in one go:

	call_console_drivers()
		spin_trylock_irqsave(&port->lock, flags);
		uart_console_write(.... "Foo:\nbar\n");
		spin_unlock_irqrestore(&port->lock, flags);

While with buffered printk, it will be store in two logbuf entries,
and printed in two goes:

	call_console_drivers()
		spin_trylock_irqsave(&port->lock, flags);
		uart_console_write(.... "Foo:\nbar\n");
		spin_unlock_irqrestore(&port->lock, flags);

	<< ... console driver IRQ, TX port->state->xmit chars ... >>>

	call_console_drivers()
		spin_trylock_irqsave(&port->lock, flags);
		uart_console_write(.... "Foo:\nbar\n");
		spin_unlock_irqrestore(&port->lock, flags);

So, *technically*, we now let more events to happens between printk-s.

But, let's look at some of pr_cont() usage examples.
E.g. dump() from arch/h8300/kernel/traps.c. The code in question looks
as follows:

	pr_info("\nKERNEL STACK:");
	tp = ((unsigned char *) fp) - 0x40;
	for (sp = (unsigned long *) tp, i = 0; (i < 0x40);  i += 4) {
		if ((i % 0x10) == 0)
			pr_info("\n%08x: ", (int) (tp + i));
		pr_info("%08x ", (int) *sp++);
	}
	pr_info("\n");

dmesg

[   15.260099] 0000:    00000000  00000010  00000040  00000090
               0010:    00000100  00000190  00000240  00000310
               0020:    00000400  00000510  00000640  00000790
               0030:    00000900  00000a90  00000c40  00000e10

So we have the entire KERNEL STACK stored as a single line, in
a single logbuf entry.

cat /dev/kmsg

4,687,15260099,c;\x0a0000:    00000000  00000010  00000040  00000090  \x0a0010:    00000100  00000190  00000240  00000310  \x0a0020:    00000400  00000510  00000640  00000790  \x0a0030:    00000900  00000a90  00000c40  00000e10

Shall we consider this as a "reference" representation: data that
pr_cont(), ideally, would have stored as a single logbuf entry? And
then compare the "reference" representation and what buffered printk
does.

Buffered printk always stores this as several lines, IOW several
logbuf entries.

cat /dev/kmsg

4,690,15260152,-;0000:    00000000  00000010  00000040  00000090  
4,691,15260154,-;0010:    00000100  00000190  00000240  00000310  
4,692,15260157,-;0020:    00000400  00000510  00000640  00000790  
4,694,15260161,-;0030:    00000900  00000a90  00000c40  00000e10  

So if we will have concurrent printk()-s happening on other CPUs,
then the KERNEL STACK data block still can be a bit hard to read:

[   15.260152] 0000:    00000000  00000010  00000040  00000090  
<printk CPU1> ... foo bar foo bar
<printk CPU2> ... foo bar foo bar
...
[   15.260154] 0010:    00000100  00000190  00000240  00000310  
<printk CPU3> ... foo bar foo bar
<printk CPU2> ... foo bar foo bar
...
              ... and so on; you got the idea.

> No, please note that the for cycle searches for '\n' from the end
> of the string.

You are right, I didn't notice that. Indeed.


Tetsuo, lockdep report with buffered printks looks a bit different:

 kernel:  Possible unsafe locking scenario:
 kernel:        CPU0                    CPU1
 kernel:        ----                    ----
 kernel:   lock(bar_lock);
 kernel:                                lock(
 kernel: foo_lock);
 kernel:                                lock(bar_lock);
 kernel:   lock(foo_lock);
 kernel: 


> > 	len = vsprintf();
> > 	if (len && text[len - 1] == '\n' || overflow)
> > 		flush();
> 
> I had the same idea. Tetsuo ignored it. I looked for more arguments
> and found that '\n' is used in the middle of several pr_cont()
> calls

OK, so we probably can have that new semantics. But we might split
something that possibly was meant to be a single line with a bunch
of \n in the middle.

	-ss

  reply	other threads:[~2018-11-12  7:59 UTC|newest]

Thread overview: 55+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2018-11-02 13:31 Tetsuo Handa
2018-11-02 13:31 ` [PATCH 2/3] mm: Use line-buffered printk() for show_free_areas() Tetsuo Handa
2018-11-07 14:07   ` Petr Mladek
2018-11-02 13:31 ` [PATCH 3/3] lockdep: Use line-buffered printk() for lockdep messages Tetsuo Handa
2018-11-02 13:36   ` Peter Zijlstra
2018-11-03  2:00     ` Tetsuo Handa
2018-11-06  8:38     ` Petr Mladek
2018-11-06  9:05       ` Sergey Senozhatsky
2018-11-06 12:57         ` Petr Mladek
2018-11-06  9:56       ` Tetsuo Handa
2018-11-07 15:19   ` Petr Mladek
2018-11-08  4:45     ` Sergey Senozhatsky
2018-11-08 11:37       ` Tetsuo Handa
2018-11-09  6:12         ` Sergey Senozhatsky
2018-11-09  9:55           ` Tetsuo Handa
2018-11-09 15:43             ` Petr Mladek
2018-11-10  2:42               ` Tetsuo Handa
2018-11-23 12:46                 ` Petr Mladek
2018-11-23 13:12                   ` Tetsuo Handa
2018-11-23 15:56                   ` Steven Rostedt
2018-11-24  0:24                     ` Tetsuo Handa
2018-11-26  4:34                       ` Sergey Senozhatsky
2018-11-28 13:29                     ` David Laight
2018-11-29 10:09                       ` Tetsuo Handa
2018-11-30 16:01                         ` Petr Mladek
2018-11-10  8:52               ` Tetsuo Handa
2018-11-23 12:52                 ` Petr Mladek
2018-11-09 14:08           ` Linus Torvalds
2018-11-09 14:42             ` Steven Rostedt
2018-11-08 11:53       ` Petr Mladek
2018-11-08 12:44         ` Sergey Senozhatsky
2018-11-08 14:21           ` Sergey Senozhatsky
2018-11-09  9:54     ` Tetsuo Handa
2018-11-02 14:40 ` [PATCH v6 1/3] printk: Add line-buffered printk() API Matthew Wilcox
2018-11-03  1:55   ` Tetsuo Handa
2018-11-02 18:12 ` kbuild test robot
2018-11-02 18:12   ` kbuild test robot
2018-11-06 14:35 ` Sergey Senozhatsky
2018-11-07 10:21   ` Petr Mladek
2018-11-07 12:54     ` Tetsuo Handa
2018-11-08  2:21     ` Sergey Senozhatsky
2018-11-08 11:24       ` Petr Mladek
2018-11-08 11:46         ` Tetsuo Handa
2018-11-08 12:30         ` Sergey Senozhatsky
2018-11-09 14:10           ` Petr Mladek
2018-11-12  7:59             ` Sergey Senozhatsky [this message]
2018-11-12 10:42               ` Tetsuo Handa
2018-11-17 10:14               ` Tetsuo Handa
2018-11-07 10:52   ` Tetsuo Handa
2018-11-07 11:01     ` David Laight
2018-11-07 12:00       ` Petr Mladek
2018-11-07 11:45     ` Petr Mladek
2018-11-08  2:30     ` Sergey Senozhatsky
2018-11-07 13:41 ` Petr Mladek
2018-11-07 14:06 ` Petr Mladek

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20181112075920.GA497@jagdpanzerIV \
    --to=sergey.senozhatsky.work@gmail.com \
    --cc=akpm@linux-foundation.org \
    --cc=dvyukov@google.com \
    --cc=fengguang.wu@intel.com \
    --cc=glider@google.com \
    --cc=jpoimboe@redhat.com \
    --cc=linux-kernel@vger.kernel.org \
    --cc=linux-mm@kvack.org \
    --cc=mingo@redhat.com \
    --cc=penguin-kernel@i-love.sakura.ne.jp \
    --cc=peterz@infradead.org \
    --cc=pmladek@suse.com \
    --cc=rostedt@goodmis.org \
    --cc=sergey.senozhatsky@gmail.com \
    --cc=torvalds@linux-foundation.org \
    --cc=will.deacon@arm.com \
    --subject='Re: [PATCH v6 1/3] printk: Add line-buffered printk() API.' \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.