Re: [PATCH v12 0/3] printk: Make printk() completely async

From: Sergey Senozhatsky
Date: Tue Jul 12 2016 - 12:47:22 EST


On (07/12/16 17:59), Petr Mladek wrote:
[..]
> > [ 12.874909] sched: RT throttling activated for rt_rq ffffffc0ac13fcd0 (cpu 0)
> > [ 12.874909] potential CPU hogs:
> > [ 12.874909] printk (292)
> >
> > On my system, the excessive printing happens during suspend/resume and this
> > happened after all the non-boot CPUs were offlined. So, only CPU 0 was left and
> > that was doing printing for a long time and so these errors :)
> >
> > It resulted in missing some print messages eventually as the scheduler probably
> > didn't schedule this thread for sometime after that.
> >
> > Will it be fine to get the priority of this kthread to a somewhat lower value,
> > etc ?
>
> I think that this patch helped only by chance. It causes that any
> message without a new line will force printk to the sync mode.
> Then it will print even the buffered messages immediately. It
> causes printk to behave more or less in the sync mode all the time.

KERN_CONT messages are not so often, because they are not SMP-safe, any intruding
non-KERN_CONT message will wake_up() printk_kthread. there is a chance, you are
right, that printk will operate in sync mode for some time, when we would want it
to be async, so 0004 probably better try harder.

but KERN_CONT is not what's going on in this case, I think. at lest
"[ 12.874909] printk (292)" line suggests so -- printk was in async
mode... and somehow non-preemptible for some time... a delay from spin_lock()
in call_console_drivers()->write()?... but why would async printk worsen it.

> I am still scratching my head about the problem fixed by this patch
> and also about suspend problems.

yeah, quite puzzled myself. thanks Petr and Viresh for digging this up.
I need some sleep now, it's 2 am here, will return back tomorrow.

-ss