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

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Date:   Mon, 5 Mar 2018 22:18:48 -0500
From:   Steven Rostedt <rostedt@...dmis.org>
To:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>
Cc:     "Qixuan.Wu" <qixuan.wu@...ux.alibaba.com>,
        linux-kernel-owner <linux-kernel-owner@...r.kernel.org>,
        Petr Mladek <pmladek@...e.com>, Jan Kara <jack@...e.cz>,
        linux-kernel <linux-kernel@...r.kernel.org>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        "chenggang.qin" <chenggang.qin@...ux.alibaba.com>,
        caijingxian <caijingxian@...ux.alibaba.com>,
        "yuanliang.wyl" <yuanliang.wyl@...baba-inc.com>,
        Tejun Heo <tj@...nel.org>
Subject: Re: Would you help to tell why async printk solution was not taken
 to upstream kernel ?

On Tue, 6 Mar 2018 11:43:58 +0900
Sergey Senozhatsky <sergey.senozhatsky.work@...il.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