Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async

From: Sergey Senozhatsky
Date: Thu Mar 10 2016 - 11:29:10 EST

On (03/10/16 10:53), Petr Mladek wrote:
> On Wed 2016-03-09 15:09:50, Sergey Senozhatsky wrote:
> > On (03/07/16 13:16), Jan Kara wrote:
> > What do you think? Or would you prefer to first introduce async
> > printk() rework, and move to console_unlock() in vprintk_emit()
> > one release cycle later?
> > IOW, in 3 steps:
> > -- first make printk() async
> > -- then console_unlock() async, and use console_unlock_for_printk() in
> > vprintk_emit()
> >
> > -- then switch to console_unlock() in vprintk_emit().
> I would sort this by priorities.

I agree, let's settle down async printk() first.

> I know about real-world problems that will get solved by
> async printk. I haven't heard yet people complaining about
> blocked console_lock()/console_unlock() calls outside printk
> code. So, I would personally prefer to handle async printk
> first.

well, I see some problems with console_lock()/console_unlock() :)

> Heh, you opened an interesting can of worms. There are definitely
> locations that just want to manipulate the list of consoles and
> their setting without the need to push the date. I wonder how
> many locations really need to push the data.

I've tested it briefly on some of the setups that I have around,
and the boot time reduced by (very roughly) ~20+%; systemd and
friends do a number of tty/etc. calls, and stuck in console_unock()
each time. of course, the "pre-condition" here are printk()s from
drivers/etc. (frequent enough to keep call_console_drivers() busy,
not necessarily "pressure").

even on my laptop, userspace does a ton of console_unlock()

[<ffffffff8108a904>] console_unlock+0x24/0x89
[<ffffffff8108ba76>] console_device+0x4a/0x54
[<ffffffff81261fbb>] tty_open+0x127/0x4c5
[<ffffffff81145316>] chrdev_open+0x13f/0x164
[<ffffffff811451d7>] ? cdev_put+0x23/0x23
[<ffffffff8113fc88>] do_dentry_open.isra.1+0x1b3/0x29e
[<ffffffff81140791>] vfs_open+0x53/0x58
[<ffffffff8114e40d>] path_openat+0xa37/0xc8c
[<ffffffff8114f2a2>] do_filp_open+0x4d/0xa3
[<ffffffff8115c1f2>] ? __alloc_fd+0x1ae/0x1c0
[<ffffffff813acdff>] ? _raw_spin_unlock+0x27/0x31
[<ffffffff81140a8b>] do_sys_open+0x13c/0x1cc
[<ffffffff81140a8b>] ? do_sys_open+0x13c/0x1cc
[<ffffffff81140b39>] SyS_open+0x1e/0x20
[<ffffffff813ad4a5>] entry_SYSCALL_64_fastpath+0x18/0xa8


[<ffffffff8108a904>] console_unlock+0x24/0x89
[<ffffffff81271910>] con_shutdown+0x2d/0x30
[<ffffffff8125e99d>] release_tty+0x52/0x12e
[<ffffffff81260722>] tty_release+0x436/0x453
[<ffffffff81142bb3>] __fput+0x107/0x1ba
[<ffffffff81142c9c>] ____fput+0xe/0x10
[<ffffffff8105d504>] task_work_run+0x67/0x90
[<ffffffff810011cc>] exit_to_usermode_loop+0x66/0x84
[<ffffffff8100179c>] syscall_return_slowpath+0x8d/0x92
[<ffffffff813ad533>] entry_SYSCALL_64_fastpath+0xa6/0xa8


> Note that console_unlock_for_printk() might be a bit
> misleading. Especially when you suggest to replace it by
> console_unlock() in vprintk_emit() ;-) I wonder if
> console_flush_and_unlock() might be more descriptive.

oh, yes, the function name was absolutely random.
console_flush_and_unlock() looks good.

> We might even split flush_console() into a separate function in the end.
> I think that the combination with unlock() is there to make sure
> that somebody will flush the last messages from printk(), see
> the retry stuff. It probably won't be needed with the asynch printk().
> Anyway, all these console_unlock() changes looks like another big step
> and I suggest to do it separately.


> PS: I want to check more precisely the async printk patchset but
> I am repeatedy sidetracked this week :-(

no prob! it's a pre-merge period, no pressure.

I'll re-spin the printk() patch tomorrow, I think.
async console_unlock() will be separated.