linux-kernel - Re: [RFC][PATCHv6 00/12] printk: introduce printing kernel thread

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]

Message-ID: <20171218123541.GC31274@jagdpanzerIV>
Date:   Mon, 18 Dec 2017 21:35:41 +0900
From:   Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>
To:     Petr Mladek <pmladek@...e.com>,
        Steven Rostedt <rostedt@...dmis.org>
Cc:     Tejun Heo <tj@...nel.org>,
        Sergey Senozhatsky <sergey.senozhatsky.work@...il.com>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Jan Kara <jack@...e.cz>,
        Andrew Morton <akpm@...ux-foundation.org>,
        Peter Zijlstra <peterz@...radead.org>,
        Rafael Wysocki <rjw@...ysocki.net>,
        Pavel Machek <pavel@....cz>,
        Tetsuo Handa <penguin-kernel@...ove.SAKURA.ne.jp>,
        linux-kernel@...r.kernel.org
Subject: Re: [RFC][PATCHv6 00/12] printk: introduce printing kernel thread

On (12/18/17 19:36), Sergey Senozhatsky wrote:
[..]
> it takes call_console_drivers() 0.01+ of a second to print some of
> the messages [I think we can ignore raw_spin_lock(&console_owner_lock)
> and fully blame call_console_drivers()]. so vprintk_emit() seems to be
> gazillion times faster and i_do_printks can add tons of messages while
> some other process prints just one.
> 
> 
> to be more precise, I see from the traces that i_do_printks can add 1100
> messages to the logbuf while call_console_drivers() prints just one.
> 
> 
> systemd-udevd-671 owns the lock. sets the console_owner. i_do_printks
> keeps adding printks. there kworker/0:1-135 that just ahead of
> i_do_printks-1992 and registers itself as the console_sem waiter.
> 
>    systemd-udevd-671   [003] d..3    66.334866: offloading: set console_owner  :0
>      kworker/0:1-135   [000] d..2    66.335999: offloading: vprintk_emit()->trylock FAIL  will spin? :1
>     i_do_printks-1992  [002] d..2    66.345474: offloading: vprintk_emit()->trylock FAIL  will spin? :0    x 1100
>    ...
>    systemd-udevd-671   [003] d..3    66.345917: offloading: cleaar console_owner  waiter != NULL :1
> 
> 
> i_do_printks-1992 finishes printing [it does limited number of printks],
> it does not compete for console_sem anymore, so those are other tasks
> that have to flush pending messages stored by i_do_printks-1992           :(

even in this case the task that took over printing had to flush logbuf
messages worth of 1100 x 0.01s == 10+ seconds of printing. which is
enough to cause problem. if there are 2200 messages in logbuf, then
there will be 2200 x 0.01 == 20+ seconds of printing. if the task is
atomic, then you probably can imagine what will happen. numbers don't lie.
if we have enough tasks competing for console_sem then the tasks that
actually fills up the logbuf buffer may never call_console_drivers().
so the lockups are still very much possible. *in my particular case*

	-ss