lkml.org 
[lkml]   [2018]   [Nov]   [12]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH v6 1/3] printk: Add line-buffered printk() API.
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

\
 
 \ /
  Last update: 2018-11-12 08:59    [W:0.102 / U:1.832 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site