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
