Re: [PATCH v6 1/3] printk: Add line-buffered printk() API.

[Sergey Senozhatsky]

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