Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1350863 > unrolled thread

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

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-05 12:00 +0100
    Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-06 07:40 +0100
      Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2016-03-06 08:20 +0100
        Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-06 10:40 +0100
          Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2016-03-06 12:10 +0100
            Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-06 14:30 +0100
              Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2016-03-06 16:00 +0100
              Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-03-07 09:30 +0100
                Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-07 11:20 +0100
                  Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-03-07 12:00 +0100
                    Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-03-07 13:20 +0100
                      Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2016-03-07 13:40 +0100
                      Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-07 16:20 +0100
                        Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Tejun Heo <tj@kernel.org> - 2016-03-07 17:00 +0100
                          Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-08 11:30 +0100
                            Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Tejun Heo <tj@kernel.org> - 2016-03-11 18:30 +0100
                              Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-12 06:10 +0100
                      Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2016-03-09 07:10 +0100
                        Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Jan Kara <jack@suse.cz> - 2016-03-10 10:30 +0100
                          Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-10 17:00 +0100
                        Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Petr Mladek <pmladek@suse.com> - 2016-03-10 11:00 +0100
                          Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-10 17:30 +0100
                    Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-07 15:50 +0100
                  Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp> - 2016-03-07 12:20 +0100
                    Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Sergey Senozhatsky <sergey.senozhatsky@gmail.com> - 2016-03-07 15:40 +0100
                Re: [RFC][PATCH v2 1/2] printk: Make printk() completely async Tejun Heo <tj@kernel.org> - 2016-03-07 16:50 +0100

Page 2 of 2 — ← Prev page 1 [2]

#1354963

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

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.

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.

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.

I looking forward to see where this ends.

Thanks,
Petr

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

[toc] | [prev] | [next] | [standalone]

#1355251

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

[toc] | [prev] | [next] | [standalone]

#1351658

On (03/07/16 11:52), Jan Kara wrote:
[..]
> So for UP systems, we should by default disable async printing anyway I
> suppose. It is just a pointless overhead. So please just make printk_sync
> default to true if !CONFIG_SMP.

ok, thanks.

> When IRQs are disabled, you're right we will have a change in behavior. I
> don't see an easy way of avoiding delaying of printk until IRQs get
> enabled. I don't want to queue work directly because that creates
> possibility for lock recursion in queue_work(). And playing some tricks
> with irq_works isn't easy either - you cannot actually rely on any other
> CPU doing anything (even a timer tick) because of NOHZ.

yes. I thought about some sort of PRINTK_IPI on smp, and queue work from
PRINTK_IPI. which is a bit insane.

> So if this will be a problem in practice, using a kthread will probably be
> the easiest solution.

probably kthread is the way to go then. Tetsuo's bad experience with
workqueues also sounds a bit alarming.

I'll post a new patch soon.

	-ss

[toc] | [prev] | [next] | [standalone]

#1351543

Sergey Senozhatsky wrote:
> Hello,
> 
> On (03/07/16 09:22), Jan Kara wrote:
> [..]
> > > hm, just for note, none of system-wide wqs seem to have a ->rescuer thread
> > > (WQ_MEM_RECLAIM).
> > > 
> > > [..]
> > > > Even if you use printk_wq with WQ_MEM_RECLAIM for printing_work work item,
> > > > printing_work_func() will not be called until current work item calls
> > > > schedule_timeout_*(). That will be an undesirable random delay. If you use
> > > > a dedicated kernel thread rather than a dedicated workqueue with WQ_MEM_RECLAIM,
> > > > we can avoid this random delay.
> > > 
> > > hm. yes, seems that it may take some time until workqueue wakeup() a ->rescuer thread.
> > > need to look more.
> > 
> > Yes, it takes some time (0.1s or 2 jiffies) before workqueue code gives up
> > creating a worker process and wakes up rescuer thread. However I don't see
> > that as a problem...
> 
> yes, that's why I asked Tetsuo whether his concern was a wq's MAYDAY timer
> delay. the two commits that Tetsuo pointed at earlier in he loop (373ccbe59270
> and 564e81a57f97) solved the problem by switching to WQ_MEM_RECLAIM wq.
> I've slightly tested OOM-kill on my desktop system and haven't spotted any
> printk delays (well, a test on desktop is not really representative, of
> course).

I wanted to tell that if kworker is running a buggy function that calls
cond_resched() but does not call schedule_timeout_*() for very long time,
such delay can become many seconds. WQ_MEM_RECLAIM is a requirement for
waking up when kworker called schedule_timeout_*(). WQ_MEM_RECLAIM wq can
still cause huge delay if kworker does not call schedule_timeout_*().
Not specific to OOM-killer or vmstat.

[toc] | [prev] | [next] | [standalone]

#1351655

On (03/07/16 20:10), Tetsuo Handa wrote:
[..]
> > > > hm. yes, seems that it may take some time until workqueue wakeup() a ->rescuer thread.
> > > > need to look more.
> > > 
> > > Yes, it takes some time (0.1s or 2 jiffies) before workqueue code gives up
> > > creating a worker process and wakes up rescuer thread. However I don't see
> > > that as a problem...
> > 
> > yes, that's why I asked Tetsuo whether his concern was a wq's MAYDAY timer
> > delay. the two commits that Tetsuo pointed at earlier in he loop (373ccbe59270
> > and 564e81a57f97) solved the problem by switching to WQ_MEM_RECLAIM wq.
> > I've slightly tested OOM-kill on my desktop system and haven't spotted any
> > printk delays (well, a test on desktop is not really representative, of
> > course).
> 
> I wanted to tell that if kworker is running a buggy function that calls
> cond_resched() but does not call schedule_timeout_*() for very long time,
> such delay can become many seconds. WQ_MEM_RECLAIM is a requirement for
> waking up when kworker called schedule_timeout_*(). WQ_MEM_RECLAIM wq can
> still cause huge delay if kworker does not call schedule_timeout_*().
> Not specific to OOM-killer or vmstat.

your point is taken. thanks.

	-ss

[toc] | [prev] | [next] | [standalone]

#1351730

Hello,

On Mon, Mar 07, 2016 at 09:22:30AM +0100, Jan Kara wrote:
> > > I don't know what MAYDAY is. I'm talking about a situation where printing_work
> > > work item is not processed (i.e. printing_work_func() is not called) until
> > > current work item calls schedule_timeout_*().

That was because the work item was percpu and not marked
CPU_INTENSIVE.  Either using an unbound or CPU_INTENSIVE workqueue
should be enough.

> > > We had a problem that since vmstat_work work item was using system_wq,
> > > vmstat_work work item was not processed (i.e. vmstat_update() was not called) if
> > > kworker was looping inside memory allocator without calling schedule_timeout_*()
> > > due to disk_events_workfn() doing GFP_NOIO allocation).
> > 
> > hm, just for note, none of system-wide wqs seem to have a ->rescuer thread
> > (WQ_MEM_RECLAIM).

Because WQ_MEM_RECLAIM only guarantees concurrency of 1, it doesn't
make sense to set it to a shared workqueue.  A dedicated workquee
should be created per domain which needs forward progress guarantee.

> > hm. yes, seems that it may take some time until workqueue wakeup() a ->rescuer thread.
> > need to look more.
> 
> Yes, it takes some time (0.1s or 2 jiffies) before workqueue code gives up
> creating a worker process and wakes up rescuer thread. However I don't see
> that as a problem...

I don't think it matters.  At that point, the system should already be
thrashing heavily and everything is crawling anyway.  A couple jiffies
delay isn't gonna be noticeable.

Thanks.

-- 
tejun

[toc] | [prev] | [standalone]

Page 2 of 2 — ← Prev page 1 [2]

Back to top | Article view | linux.kernel

csiph-web