Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Sergey Senozhatsky]

Cc-ing Steven

On (03/04/18 20:10), Qixuan.Wu wrote:
>    Hi Sergey, petr, and Jan,
>      I find you wrote a patch set of "[PATCH v12 0/3] printk: Make printk()
>    completely async"(https://lkml.org/lkml/2016/5/13/275), and many people
>    have reviewd. But I did not see them be taken to upstream kernel. Would
>    you please help to tell me the reason ? Is it just only because of the
>    LOG_CONT scenario (4th patch) ?

Hello,

	Thanks for your email, we desperately need more feedback from
people who are facing printk() related issues. While, certainly, I'm not
happy to hear that printk() causes troubles on your side.

	Regarding the async printk patch set. It's still "work in
progress", and probably will take some time (due to various reasons,
LOG_CONT is not one of them).

>      Anyway, now we also face the same problem, many CPU are printking at
>    the same time, but the poor one takes the lock and printk to console for
>    long time. Would you please help to tell does anybody are writing some
>    solution and try to fix this ?

	Yes. 4.16 has Steven's patch which tweaks printk() in a very smart
way and addresses some of the issues printk() has. If you can't test 4.16
(quite possible), then the commits you'd want to take a look at are
(Linus's tree):

 dbdda842fe96f89  printk: Add console owner and waiter logic to load balance console writes
 c162d5b4338d72d  printk: Hide console waiter logic into helpers
 fd5f7cde1b85d4c  printk: Never set console_may_schedule in console_trylock()
 c14376de3a1befa  printk: Wake klogd when passing console_lock owner

If you can backport those, test and tell us about your experience - would be
great and very much appreciated.

	-ss

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Qixuan.Wu]

Hi Sergey, 

Thank you for your fast reply. 
 
On (03/04/18 21:02), Sergey Senozhatsky wrote:

> On (03/04/18 20:10), Qixuan.Wu wrote:
>>    Hi Sergey, petr, and Jan,
>>      I find you wrote a patch set of "[PATCH v12 0/3] printk: Make printk()
>>    completely async"(https://lkml.org/lkml/2016/5/13/275), and many people
>>    have reviewd. But I did not see them be taken to upstream kernel. Would
>>    you please help to tell me the reason ? Is it just only because of the
>>    LOG_CONT scenario (4th patch) ?
> 
> Hello,
> 
>   Thanks for your email, we desperately need more feedback from
>  people who are facing printk() related issues. While, certainly, I'm not
>  happy to hear that printk() causes troubles on your side.

>   Regarding the async printk patch set. It's still "work in
>  progress", and probably will take some time (due to various reasons,
>  LOG_CONT is not one of them).

It's fine. People know the prink is important and used in the kernel at many 
many place, and it's difficult to cover all the scenario, so it's predictable there 
are some places to be improved. 
For async printk patch set, would you help to know when they can be finished.
I think it should be very useful to avoid softlockup or RCU stall.  

>   Yes. 4.16 has Steven's patch which tweaks printk() in a very smart
>  way and addresses some of the issues printk() has. If you can't test 4.16
>  (quite possible), then the commits you'd want to take a look at are
> (Linus's tree):
>  dbdda842fe96f89  printk: Add console owner and waiter logic to load balance console writes
>  c162d5b4338d72d  printk: Hide console waiter logic into helpers
>  fd5f7cde1b85d4c  printk: Never set console_may_schedule in console_trylock()
>  c14376de3a1befa  printk: Wake klogd when passing console_lock owner

Thank you for your suggested solution wrote by Steven. I looked through it, the 
thought is good. I think it can mitigate 99.999% the softlockup problem in the 
scenario.  But I have a comment for it, actually maybe it's not correct. 

Suppose there is one scenario that the system has 100 CPU(0~99). While CPU 0 is 
calling slow console, CPU 1~99 are calling printk at the same time. And suppose 
CPU 1 will be waiter, as per the patch, 2~99 will return directly. After CPU 0 finish 
it's log to console, it will return when it finds CPU 1 are waiting. Then CPU 1 need 
flush all logs of CPU(1~99) to the console, which may cause  softlockup or rcu 
stall. Above scenario is very unusual and it's very unlikely to happen. 

> If you can backport those, test and tell us about your experience - would be
> great and very much appreciated.

Anyway the code in 4.16 is also very useful to the problem. We will think over to 
try to backport. If any other problem occur, will inform you again. 

Thanks & Regards
Qixuan

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Steven Rostedt]

On Sun, 04 Mar 2018 23:08:23 +0800
"Qixuan.Wu" <qixuan.wu@linux.alibaba.com> wrote:

> Suppose there is one scenario that the system has 100 CPU(0~99). While CPU 0 is 
> calling slow console, CPU 1~99 are calling printk at the same time. And suppose 
> CPU 1 will be waiter, as per the patch, 2~99 will return directly. After CPU 0 finish 
> it's log to console, it will return when it finds CPU 1 are waiting. Then CPU 1 need 
> flush all logs of CPU(1~99) to the console, which may cause  softlockup or rcu 
> stall. Above scenario is very unusual and it's very unlikely to happen. 

Yes, people keep bringing up this scenario.

It would require a single burst of printks to all CPUs. And then no
more printks after that. The last one will end up printing the entire
buffer out the slow console. The thing is, this is a bounded time, and
no printk will print more than one full buffer worth.

If this is a worry, then set the timeouts for the lockup detection to
be longer than the time it takes to print one full buffer with the
slowest console.

-- Steve

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Sergey Senozhatsky]

On (03/04/18 10:43), Steven Rostedt wrote:
> On Sun, 04 Mar 2018 23:08:23 +0800
> "Qixuan.Wu" <qixuan.wu@linux.alibaba.com> wrote:
> 
> > Suppose there is one scenario that the system has 100 CPU(0~99). While CPU 0 is 
> > calling slow console, CPU 1~99 are calling printk at the same time. And suppose 
> > CPU 1 will be waiter, as per the patch, 2~99 will return directly. After CPU 0 finish 
> > it's log to console, it will return when it finds CPU 1 are waiting. Then CPU 1 need 
> > flush all logs of CPU(1~99) to the console, which may cause  softlockup or rcu 
> > stall. Above scenario is very unusual and it's very unlikely to happen. 
> 
> Yes, people keep bringing up this scenario.

Yeah.

> It would require a single burst of printks to all CPUs.

That's one possibility. The other one is - console_sem locked by a
preemptible context which gets scheduled out.

> And then no more printks after that. The last one will end up printing
> the entire buffer out the slow console. The thing is, this is a bounded
> time, and no printk will print more than one full buffer worth.

It can print more than "one full buffer worth". In theory and on practice.

> If this is a worry, then set the timeouts for the lockup detection to
> be longer than the time it takes to print one full buffer with the
> slowest console.

I see your point.
But I still think that it makes sense to change that "print it all" approach.
With more clear/explicit watchdog-dependent limits - we do direct printk for
1/2 (or 2/3) of a current watchdog threshold value and offload if there is
more stuff in the logbuf. Implicit "logbuf size * console throughput" is
harder to understand. Disabling watchdog because of printk is a bit too much
of a compromise, probably.

IOW, is logbuf worth of messages so critically important after all that we
are ready to jeopardize the system stability?

	-ss

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Steven Rostedt]

On Mon, 5 Mar 2018 11:14:16 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> It can print more than "one full buffer worth". In theory and on practice.

How so? As soon as another process adds to the buffer, it will take
over the printing.

-- Steve

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Sergey Senozhatsky]

On (03/05/18 15:45), Steven Rostedt wrote:
> On Mon, 5 Mar 2018 11:14:16 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > It can print more than "one full buffer worth". In theory and on practice.
> 
> How so? As soon as another process adds to the buffer, it will take
> over the printing.

The very same CPU which holds the console_sem can add messages to the
logbuf.

There are at least 3 cases I can easily think of.


#1 preemption under console_sem

console_lock()
 for (;;) {
  local_irq_save()
  call_console_drivers()
  local_irq_restore()
  << preemption >>
       printk // from another task, same CPU
 }


#2 IRQ->printk under console_sem

console_lock()
 for (;;) {
  local_irq_save()
  call_console_drivers()
  local_irq_restore()
  << IRQ >>
       printk
 }


#3 This, eventually, becomes #2. But the root cause and, thus,
probability are completely different. printks from console drivers
(some console drivers are really complex, with dependencies on timers,
networking, etc. etc.). We currently handle those via
printk_safe -> IRQ work. But I think we kinda should stop doing so.

console_lock()
 for (;;) {
  local_irq_save()
  call_console_drivers()
   printk()
  local_irq_restore()
 }

	-ss

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Steven Rostedt]

On Tue, 6 Mar 2018 11:00:26 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> On (03/05/18 15:45), Steven Rostedt wrote:
> > On Mon, 5 Mar 2018 11:14:16 +0900
> > Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> >   
> > > It can print more than "one full buffer worth". In theory and on practice.  
> > 
> > How so? As soon as another process adds to the buffer, it will take
> > over the printing.  
> 
> The very same CPU which holds the console_sem can add messages to the
> logbuf.
> 
> There are at least 3 cases I can easily think of.
> 
> 
> #1 preemption under console_sem
> 
> console_lock()
>  for (;;) {
>   local_irq_save()
>   call_console_drivers()
>   local_irq_restore()
>   << preemption >>

At this moment all watchdogs are working fine. And the continuing will
be done as if it was the first printk. No lockup eminent.

>        printk // from another task, same CPU
>  }
> 
> 
> #2 IRQ->printk under console_sem
> 
> console_lock()
>  for (;;) {
>   local_irq_save()
>   call_console_drivers()
>   local_irq_restore()
>   << IRQ >>
>        printk

So basically, the CPU is just printing what that CPU is printing. It
only becomes an issue if the system has an issue (one CPU spamming
printk). Which is another bug.

>  }
> 
> 
> #3 This, eventually, becomes #2. But the root cause and, thus,
> probability are completely different. printks from console drivers
> (some console drivers are really complex, with dependencies on timers,
> networking, etc. etc.). We currently handle those via
> printk_safe -> IRQ work. But I think we kinda should stop doing so.
> 
> console_lock()
>  for (;;) {
>   local_irq_save()
>   call_console_drivers()
>    printk()

Which is another issue as well. But this is due to issues with printk
having issues, and is a different category of bug.

#2 and #3 are more recursive bugs and not a "printk locks up due to
other CPUs" kind of bug.

-- Steve


>   local_irq_restore()
>  }
> 
> 	-ss

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Sergey Senozhatsky]

On (03/05/18 21:47), Steven Rostedt wrote:
[..]
> At this moment all watchdogs are working fine. And the continuing will
> be done as if it was the first printk. No lockup eminent.
> 
[..]

> So basically, the CPU is just printing what that CPU is printing. It
> only becomes an issue if the system has an issue (one CPU spamming
> printk). Which is another bug.
>
[..]

> Which is another issue as well. But this is due to issues with printk
> having issues, and is a different category of bug.
> 
> #2 and #3 are more recursive bugs and not a "printk locks up due to
> other CPUs" kind of bug.

Yes. My point was that "CPU can print one full buffer max" is not
guaranteed and not exactly true. There are ways for CPUs to break
that O(logbuf) boundary.

	-ss

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Steven Rostedt]

On Tue, 6 Mar 2018 11:53:50 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:


> Yes. My point was that "CPU can print one full buffer max" is not
> guaranteed and not exactly true. There are ways for CPUs to break
> that O(logbuf) boundary.

Yes, when printk or the consoles have a bug, it can be greater than
O(logbuf).

-- Steve

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Sergey Senozhatsky]

On (03/05/18 22:16), Steven Rostedt wrote:
> > Yes. My point was that "CPU can print one full buffer max" is not
> > guaranteed and not exactly true. There are ways for CPUs to break
> > that O(logbuf) boundary.
> 
> Yes, when printk or the consoles have a bug, it can be greater than
> O(logbuf).

OK. Now the question is - what is "a bug" in this case? Are those
printk-s really a bug? Consoles are very complex, with dependencies
on timers, networking, etc. having them appending more messages to
the logbuf is not very cool, but at the time the kernel does not
BUG_ON(), nor panic(); it moves on. It's printk()->console_unlock()
that turns it into lockup->panic(). Is the bug really in the consoles
then?

	-ss

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Steven Rostedt]

On Mon, 5 Mar 2018 11:14:16 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> But I still think that it makes sense to change that "print it all" approach.
> With more clear/explicit watchdog-dependent limits - we do direct printk for
> 1/2 (or 2/3) of a current watchdog threshold value and offload if there is
> more stuff in the logbuf. Implicit "logbuf size * console throughput" is
> harder to understand. Disabling watchdog because of printk is a bit too much
> of a compromise, probably.

If you know the baud rate, logbuf size * console throughput is actually
trivial to calculate.

Let's see. CONFIG_LOG_BUF_SHIFT defaults to 18 (2^18 = 262144).
Lets say we have a slow 9600 baud serial, which would give us:

 262144 * 8 / 9600 = 219 (rounded up).

Thus, the worse case scenario would be 219 seconds to output the entire
buffer. Add 10 seconds more for extra overhead, and then you have 229
second watchdog that should never trigger because of a very slow
console.

(A more common 151200 baud modem would empty the buffer in 14 seconds).

> 
> IOW, is logbuf worth of messages so critically important after all that we
> are ready to jeopardize the system stability?

The stability is only in jeopardy if the watchdogs trigger, right?

-- Steve

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Sergey Senozhatsky]

Hello Steven,

Let me Cc Tejun

On (03/05/18 15:58), Steven Rostedt wrote:
> On Mon, 5 Mar 2018 11:14:16 +0900
> Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:
> 
> > But I still think that it makes sense to change that "print it all" approach.
> > With more clear/explicit watchdog-dependent limits - we do direct printk for
> > 1/2 (or 2/3) of a current watchdog threshold value and offload if there is
> > more stuff in the logbuf. Implicit "logbuf size * console throughput" is
> > harder to understand. Disabling watchdog because of printk is a bit too much
> > of a compromise, probably.
> 
> If you know the baud rate, logbuf size * console throughput is actually
> trivial to calculate.
> 
> Let's see. CONFIG_LOG_BUF_SHIFT defaults to 18 (2^18 = 262144).
> Lets say we have a slow 9600 baud serial, which would give us:
>
>  262144 * 8 / 9600 = 219 (rounded up).
> 
> Thus, the worse case scenario would be 219 seconds to output the entire
> buffer. Add 10 seconds more for extra overhead, and then you have 229
> second watchdog that should never trigger because of a very slow
> console.
>
> (A more common 151200 baud modem would empty the buffer in 14 seconds).

Right. And when you register one more console (e.g. net console), you need
to re-calculate and re-adjust watchdog. When you set kernel log_buf_len
param (e.g. you might do log_buf_len=32G to store ftrace dumps from NMI)
you need to re-calculate and re-adjust watchdog, etc.

> > IOW, is logbuf worth of messages so critically important after all that we
> > are ready to jeopardize the system stability?
> 
> The stability is only in jeopardy if the watchdogs trigger, right?

Not limited to, watchdog threshold is at least deterministic.
Unlike, for instance, this guy

	rcu_read_lock()
	 printk()
	rcu_read_unlock()

It will block RCU grace periods. In the worst case this can become a
full-blown RCU stall and even OOM. In a less dramatic case this can
increase memory pressure, cause reclaimer activities, etc, which is not
a very good development, whether you have a small embedded device or a
server under high load, especially given that all you did was a bunch
of printks.

	-ss

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Sergey Senozhatsky]

One more thing

On (03/06/18 10:52), Sergey Senozhatsky wrote:
[..]
> > If you know the baud rate, logbuf size * console throughput is actually
> > trivial to calculate.

It's trivial when your setup is trivial. In a less trivial case if you
set watchdog threshold based on "logbuf size * console throughput" then
things are still too bad.

So this is what a typical printk over serial console looks like

printk()
 console_unlock()
  for (;;) {
   local_irq_save()
    call_console_drivers()
     foo_console_write()
      spin_lock_irqsave(&port->lock, flags);
      uart_console_write(port, s, count, foo_console_putchar);
      spin_unlock_irqrestore(&port->lock, flags);
   local_irq_restore()
  }

Notice that call_console_drivers->foo_console_write spins on
port->lock every time it wants to print out a logbuf line.
Why does it do this?

In short, because of printf(). Yes, printk() may depend on printf().

printf()
 n_tty_write()
  uart_write()
   uart_port_lock(state, flags)                  // spin_lock_irqsave(&uport->lock, flags)
    memcpy(circ->buf + circ->head, buf, c);
   uart_port_unlock(port, flags)                 // spin_unlock_irqrestore(&port->lock, flags);

Now, printf() messages stored in uart circ buffer must be printed
to the console. And this is where console's IRQ handler jumps in.

A typical IRQ handler does something like this

static irqreturn_t foo_console_irq_handler(...)
{
	spin_lock(&port->lock);
	rx_chars(port, status);
	tx_chars(port, status);
	spin_unlock(&port->lock);
}

Where tx_chars() usually does something like this

	while (...) {
		write_char(port, xmit->buf[xmit->tail]);
		xmit->tail = (xmit->tail + 1) & (UART_XMIT_SIZE - 1);
		if (uart_circ_empty(xmit))
			break;
	}

Some drivers flush all pending chars, some drivers limit the number
of TX chars to some number, e.g. 512.

But in any case, printk() -> call_console_drivers() -> foo_console_write()
must spin on port->lock as long as foo_console_irq_handler() has chars to
TX / RX.

Thus, if you have O(logbuf) of kernel messages, and O(circ->buf) of user
space messages, then printk() will spend O(logbuf) + O(circ->buf) + O(RX).

So the watchdog threshold value based purely on O(logbuf) (printing to
_all_ of the consoles) will not always work.

	-ss

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Steven Rostedt]

On Tue, 6 Mar 2018 11:43:58 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> wrote:

> One more thing
> 
> On (03/06/18 10:52), Sergey Senozhatsky wrote:
> [..]
> > > If you know the baud rate, logbuf size * console throughput is actually
> > > trivial to calculate.  
> 
> It's trivial when your setup is trivial. In a less trivial case if you
> set watchdog threshold based on "logbuf size * console throughput" then
> things are still too bad.
> 
> So this is what a typical printk over serial console looks like
> 
> printk()
>  console_unlock()
>   for (;;) {
>    local_irq_save()
>     call_console_drivers()
>      foo_console_write()
>       spin_lock_irqsave(&port->lock, flags);
>       uart_console_write(port, s, count, foo_console_putchar);
>       spin_unlock_irqrestore(&port->lock, flags);
>    local_irq_restore()
>   }
> 
> Notice that call_console_drivers->foo_console_write spins on
> port->lock every time it wants to print out a logbuf line.
> Why does it do this?
> 
> In short, because of printf(). Yes, printk() may depend on printf().
> 
> printf()
>  n_tty_write()
>   uart_write()
>    uart_port_lock(state, flags)                  // spin_lock_irqsave(&uport->lock, flags)
>     memcpy(circ->buf + circ->head, buf, c);
>    uart_port_unlock(port, flags)                 // spin_unlock_irqrestore(&port->lock, flags);
> 
> Now, printf() messages stored in uart circ buffer must be printed
> to the console. And this is where console's IRQ handler jumps in.
> 
> A typical IRQ handler does something like this
> 
> static irqreturn_t foo_console_irq_handler(...)
> {
> 	spin_lock(&port->lock);
> 	rx_chars(port, status);
> 	tx_chars(port, status);
> 	spin_unlock(&port->lock);
> }
> 
> Where tx_chars() usually does something like this
> 
> 	while (...) {
> 		write_char(port, xmit->buf[xmit->tail]);
> 		xmit->tail = (xmit->tail + 1) & (UART_XMIT_SIZE - 1);
> 		if (uart_circ_empty(xmit))
> 			break;
> 	}
> 
> Some drivers flush all pending chars, some drivers limit the number
> of TX chars to some number, e.g. 512.
> 
> But in any case, printk() -> call_console_drivers() -> foo_console_write()
> must spin on port->lock as long as foo_console_irq_handler() has chars to
> TX / RX.
> 
> Thus, if you have O(logbuf) of kernel messages, and O(circ->buf) of user
> space messages, then printk() will spend O(logbuf) + O(circ->buf) + O(RX).
> 
> So the watchdog threshold value based purely on O(logbuf) (printing to
> _all_ of the consoles) will not always work.
> 

If you have a complex setup happening like above, you most likely have
printks happening on multiple CPUs which means the work load will be
spread out across those CPUs.

-- Steve

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Qixuan.Wu]

Hi Steve,  

On Sun, 04 Mar 2018 23:43:23 +0800
Steven Rostedt <rostedt@goodmis.org> wrote:

> Yes, people keep bringing up this scenario.
> It would require a single burst of printks to all CPUs. And then no
> more printks after that. The last one will end up printing the entire
> buffer out the slow console. The thing is, this is a bounded time, and
> no printk will print more than one full buffer worth.

> If this is a worry, then set the timeouts for the lockup detection to
> be longer than the time it takes to print one full buffer with the
> slowest console.

Thanks for your information and suggestion. We will think of backport 
the code as per the workload, or recently, maybe we will think of disable 
ttyS0 console just for the printk. 

Thanks & Regards
Qixuan

Re: Would you help to tell why async printk solution was not taken to upstream kernel ?

[Petr Mladek]

On Mon 2018-03-05 14:56:59, Qixuan.Wu wrote:
> Hi Steve,  
> 
> On Sun, 04 Mar 2018 23:43:23 +0800
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > Yes, people keep bringing up this scenario.
> > It would require a single burst of printks to all CPUs. And then no
> > more printks after that. The last one will end up printing the entire
> > buffer out the slow console. The thing is, this is a bounded time, and
> > no printk will print more than one full buffer worth.
> 
> > If this is a worry, then set the timeouts for the lockup detection to
> > be longer than the time it takes to print one full buffer with the
> > slowest console.
> 
> Thanks for your information and suggestion. We will think of backport 
> the code as per the workload, or recently, maybe we will think of disable 
> ttyS0 console just for the printk. 

Please, share the log if you still see a soft/hard lockups with the 4
commits (console waiter logic). It would help to improve the solution.

We need some justification to make the printk code more complicated.
Also many possible solutions might improve some scenarios and make
worse some others. Therefore we need data to make decisions.

Best Regards,
Petr