linux-kernel - Re: [Bug 199003] console stalled, cause Hard LOCKUP.

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] [day] [month] [year] [list]

Date:   Mon, 26 Mar 2018 11:26:44 +0200
From:   Petr Mladek <pmladek@...e.com>
To:     Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>
Cc:     Steven Rostedt <rostedt@...dmis.org>,
        bugzilla-daemon@...zilla.kernel.org,
        LKML <linux-kernel@...r.kernel.org>, wen.yang99@....com.cn,
        Peter Zijlstra <peterz@...radead.org>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Christoph Hellwig <hch@...radead.org>
Subject: Re: [Bug 199003] console stalled, cause Hard LOCKUP.

On Mon 2018-03-26 14:12:22, Sergey Senozhatsky wrote:
> Given how slow serial8250_console_putchar()->wait_for_xmitr() can be -
> 10ms of delay for every char - it's possible that we had no concurrent
> printk()-s from other CPUs. So may be we had just one printing CPU,
> and several CPUs spinning on a spin_lock which was owned by the printing
> CPU.
> 
> So that's why printk_deferred() helped here. It simply detached 8250
> and made spin_lock critical secrtion to be as fast as printk->log_store().
>
> But here comes the tricky part. Suppose that we:
> a) have at least two CPUs that call printk concurrently
> b) have hand off enabled
> 
> 
> Now, what will happen if we have something like this
> 
> CPU0					CPU1				CPU2
> 					spin_lock(queue_lock)
> 					 printk				printk
> cfqg_print_rwstat_recursive()		  serial8250
>  spin_lock(queue_lock)			 printk				 serial8250
>  					  serial8250			printk
> 									 serial8250
> 
> 
> I suspect that handoff may not be very helpful. CPU1 and CPU2 will wait for
> each to finish serial8250 and to hand off printing to each other. So CPU1
> will do 2 serial8250 invocations to printk its messages, and in between it
> will spin waiting for CPU2 to do its printk->serial8250 and to handoff
> printing to CPU1. The problem is that CPU1 will be under spin_lock() all
> that time, so CPU0 is going to suffer just like before.
> 
> Opinions?

It would help if Wen Yang could provide the entire log and also try the
Steven's patches. Otherwise, we are too speculating.

The 10ms delay-per-char looks scarry. But if I get it correctly, it
would happen only if we hit the deadline for each character. So,
a question is if the serial port is really that busy and if so why.

Also I wonder how many messages were actually printed under the
queue_lock. printk_deferred() seems to help but it is an immediate
offload. I wonder if the offload from console_unlock() would actually
help. It might fail to detect the critic situation if too many lines
are printed inside the lock and console_unlock() is called for each
line separately. Also it would fail when only single line caused that
big delay.

Best Regards,
Petr