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

[Sergey Senozhatsky]

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

____fput()->console_unlock()

  [<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
...

etc.


> 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.

ok.

> 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.

	-ss