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

Groups > linux.kernel > #1570924 > unrolled thread

Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

Started byRoss Zwisler <zwisler@gmail.com>
First post2017-01-31 18:40 +0100
Last post2017-02-02 03:00 +0100
Articles 12 — 6 participants

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

  Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Ross Zwisler <zwisler@gmail.com> - 2017-01-31 18:40 +0100
    Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Jan Kara <jack@suse.cz> - 2017-02-01 10:10 +0100
      Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Peter Zijlstra <peterz@infradead.org> - 2017-02-01 10:40 +0100
        Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Petr Mladek <pmladek@suse.com> - 2017-02-01 16:40 +0100
          Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Peter Zijlstra <peterz@infradead.org> - 2017-02-01 17:20 +0100
            Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Steven Rostedt <rostedt@goodmis.org> - 2017-02-01 17:50 +0100
          Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-02-02 03:20 +0100
            Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Peter Zijlstra <peterz@infradead.org> - 2017-02-02 10:10 +0100
              Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-02-02 11:10 +0100
                Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Petr Mladek <pmladek@suse.com> - 2017-02-02 16:30 +0100
                  Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-02-03 03:50 +0100
    Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Sergey Senozhatsky <sergey.senozhatsky.work@gmail.com> - 2017-02-02 03:00 +0100

#1570924 — Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk

FromRoss Zwisler <zwisler@gmail.com>
Date2017-01-31 18:40 +0100
SubjectRe: [PATCHv7 6/8] printk: use printk_safe buffers in printk
Message-ID<t5Kzn-3vy-11@gated-at.bofh.it>
On Tue, Dec 27, 2016 at 7:16 AM, Sergey Senozhatsky
<sergey.senozhatsky@gmail.com> wrote:
> Use printk_safe per-CPU buffers in printk recursion-prone blocks:
> -- around logbuf_lock protected sections in vprintk_emit() and
>    console_unlock()
> -- around down_trylock_console_sem() and up_console_sem()
>
> Note that this solution addresses deadlocks caused by printk()
> recursive calls only. That is vprintk_emit() and console_unlock().
> The rest will be converted in a followup patch.
>
> Another thing to note is that we now keep lockdep enabled in printk,
> because we are protected against the printk recursion caused by
> lockdep in vprintk_emit() by the printk-safe mechanism - we first
> switch to per-CPU buffers and only then access the deadlock-prone
> locks.

When booting v4.10-rc5-mmots-2017-01-26-15-49 from the mmots tree, I
sometimes see the following lockdep splat which I think may be related
to this commit?

[   13.090634] ======================================================
[   13.090634] [ INFO: possible circular locking dependency detected ]
[   13.090635] 4.10.0-rc5-mm1-00313-g5c0c3d7-dirty #10 Not tainted
[   13.090635] -------------------------------------------------------
[   13.090635] systemd/1 is trying to acquire lock:
[   13.090636]  ((console_sem).lock){-.....}, at: [<ffffffff81110194>]
down_trylock+0x14/0x40
[   13.090637]
[   13.090637] but task is already holding lock:
[   13.090637]  (&rq->lock){-.-.-.}, at: [<ffffffff810e6116>]
task_rq_lock+0x56/0xd0
[   13.090638]
[   13.090639] which lock already depends on the new lock.
[   13.090639]
[   13.090639]
[   13.090640] the existing dependency chain (in reverse order) is:
[   13.090640] c
[   13.090640] -> #2 (&rq->lock){-.-.-.}:
[   13.090641]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
[   13.090642]        [<ffffffff81ca3171>] _raw_spin_lock+0x41/0x80
[   13.090642]        [<ffffffff810fa38a>] task_fork_fair+0x3a/0x100
[   13.090642]        [<ffffffff810ea80d>] sched_fork+0x10d/0x2c0
[   13.090643]        [<ffffffff810b05df>] copy_process.part.30+0x69f/0x2190
[   13.090643]        [<ffffffff810b22c6>] _do_fork+0xf6/0x700
[   13.090643]        [<ffffffff810b28f9>] kernel_thread+0x29/0x30
[   13.090644]        [<ffffffff81c91572>] rest_init+0x22/0x140
[   13.090644]        [<ffffffff8280b051>] start_kernel+0x461/0x482
[   13.090644]        [<ffffffff8280a2d6>] x86_64_start_reservations+0x2a/0x2c
[   13.090645]        [<ffffffff8280a424>] x86_64_start_kernel+0x14c/0x16f
[   13.090645]        [<ffffffff810001c4>] verify_cpu+0x0/0xfc
[   13.090645]
[   13.090645] -> #1 (&p->pi_lock){-.-.-.}:
[   13.090647]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
[   13.090647]        [<ffffffff81ca3f79>] _raw_spin_lock_irqsave+0x59/0x93
[   13.090647]        [<ffffffff810e943f>] try_to_wake_up+0x3f/0x530
[   13.090648]        [<ffffffff810e9945>] wake_up_process+0x15/0x20
[   13.090648]        [<ffffffff81c9fc4c>] __up.isra.0+0x4c/0x50
[   13.090648]        [<ffffffff81110256>] up+0x46/0x50
[   13.090649]        [<ffffffff81128a55>] __up_console_sem+0x45/0x80
[   13.090649]        [<ffffffff81129baf>] console_unlock+0x29f/0x5e0
[   13.090649]        [<ffffffff8112a1c0>] vprintk_emit+0x2d0/0x3a0
[   13.090650]        [<ffffffff8112a429>] vprintk_default+0x29/0x50
[   13.090650]        [<ffffffff8112b445>] vprintk_func+0x25/0x80
[   13.090650]        [<ffffffff81205c6d>] printk+0x52/0x6e
[   13.090651]        [<ffffffff81185bdc>] kauditd_hold_skb+0x9c/0xa0
[   13.090651]        [<ffffffff8118601b>] kauditd_thread+0x23b/0x520
[   13.090651]        [<ffffffff810dbb6f>] kthread+0x10f/0x150
[   13.090652]        [<ffffffff81ca42c1>] ret_from_fork+0x31/0x40
[   13.090652]
[   13.090652] -> #0 ((console_sem).lock){-.....}:
[   13.090653]        [<ffffffff81116c85>] __lock_acquire+0x10e5/0x1270
[   13.090653]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
[   13.090654]        [<ffffffff81ca3f79>] _raw_spin_lock_irqsave+0x59/0x93
[   13.090654]        [<ffffffff81110194>] down_trylock+0x14/0x40
[   13.090654]        [<ffffffff81128b7c>] __down_trylock_console_sem+0x3c/0xc0
[   13.090655]        [<ffffffff81128c16>] console_trylock+0x16/0x90
[   13.090655]        [<ffffffff8112a1b7>] vprintk_emit+0x2c7/0x3a0
[   13.090655]        [<ffffffff8112a429>] vprintk_default+0x29/0x50
[   13.090656]        [<ffffffff8112b445>] vprintk_func+0x25/0x80
[   13.090656]        [<ffffffff81205c6d>] printk+0x52/0x6e
[   13.090656]        [<ffffffff810b3329>] __warn+0x39/0xf0
[   13.090657]        [<ffffffff810b343f>] warn_slowpath_fmt+0x5f/0x80
[   13.090657]        [<ffffffff810f550b>] update_load_avg+0x85b/0xb80
[   13.090657]        [<ffffffff810f58bf>] detach_task_cfs_rq+0x3f/0x210
[   13.090658]        [<ffffffff810f8e34>] task_change_group_fair+0x24/0x100
[   13.090658]        [<ffffffff810e46ef>] sched_change_group+0x5f/0x110
[   13.090658]        [<ffffffff810efd03>] sched_move_task+0x53/0x160
[   13.090659]        [<ffffffff810efe46>] cpu_cgroup_attach+0x36/0x70
[   13.090659]        [<ffffffff81172aa0>] cgroup_migrate_execute+0x230/0x3f0
[   13.090659]        [<ffffffff81172d2e>] cgroup_migrate+0xce/0x140
[   13.090660]        [<ffffffff8117301f>] cgroup_attach_task+0x27f/0x3e0
[   13.090660]        [<ffffffff81175b7e>] __cgroup_procs_write+0x30e/0x510
[   13.090661]        [<ffffffff81175d94>] cgroup_procs_write+0x14/0x20
[   13.090661]        [<ffffffff811700e4>] cgroup_file_write+0x44/0x1e0
[   13.090661]        [<ffffffff8135a92c>] kernfs_fop_write+0x13c/0x1c0
[   13.090662]        [<ffffffff812b8e07>] __vfs_write+0x37/0x160
[   13.090662]        [<ffffffff812ba8ab>] vfs_write+0xcb/0x1f0
[   13.090662]        [<ffffffff812bbe38>] SyS_write+0x58/0xc0
[   13.090663]        [<ffffffff81ca4041>] entry_SYSCALL_64_fastpath+0x1f/0xc2
[   13.090663]
[   13.090663] other info that might help us debug this:
[   13.090663]
[   13.090664] Chain exists of:
[   13.090664]   (console_sem).lock --> &p->pi_lock --> &rq->lock
[   13.090665]
[   13.090666]  Possible unsafe locking scenario:
[   13.090666]
[   13.090666]        CPU0                    CPU1
[   13.090667]        ----                    ----
[   13.090667]   lock(&rq->lock);
[   13.090668]                                lock(&p->pi_lock);
[   13.090668]                                lock(&rq->lock);
[   13.090669]   lock((console_sem).lock);
[   13.090670]
[   13.090670]  * DEADLOCK *
[   13.090670]
[   13.090671] 6 locks held by systemd/1:
[   13.090671]  #0:  (sb_writers#6){.+.+.+}, at: [<ffffffff812ba97b>]
vfs_write+0x19b/0x1f0
[   13.090672]  #1:  (&of->mutex){+.+.+.}, at: [<ffffffff8135a8f6>]
kernfs_fop_write+0x106/0x1c0
[   13.090673]  #2:  (cgroup_mutex){+.+.+.}, at: [<ffffffff811751aa>]
cgroup_kn_lock_live+0x5a/0x220
[   13.090674]  #3:  (&cgroup_threadgroup_rwsem){+++++.}, at:
[<ffffffff811109cb>] percpu_down_write+0x2b/0x130
[   13.090676]  #4:  (&p->pi_lock){-.-.-.}, at: [<ffffffff810e6101>]
task_rq_lock+0x41/0xd0
[   13.090677]  #5:  (&rq->lock){-.-.-.}, at: [<ffffffff810e6116>]
task_rq_lock+0x56/0xd0
[   13.090678]
[   13.090678] stack backtrace:
[   13.090679] CPU: 8 PID: 1 Comm: systemd Not tainted
4.10.0-rc5-mm1-00313-g5c0c3d7-dirty #10
[   13.090679] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS rel-1.9.1-0-gb3ef39f-prebuilt.qemu-project.org 04/01/2014
[   13.090679] Call Trace:
[   13.090680]  dump_stack+0x86/0xc3
[   13.090680]  print_circular_bug+0x1be/0x210
[   13.090680]  __lock_acquire+0x10e5/0x1270
[   13.090681]  lock_acquire+0xfd/0x200
[   13.090681]  ? down_trylock+0x14/0x40
[   13.090681]  _raw_spin_lock_irqsave+0x59/0x93
[   13.090681]  ? down_trylock+0x14/0x40
[   13.090682]  ? vprintk_emit+0x2c7/0x3a0
[   13.090682]  down_trylock+0x14/0x40
[   13.090682]  __down_trylock_console_sem+0x3c/0xc0
[   13.090683]  console_trylock+0x16/0x90
[   13.090683]  ? trace_hardirqs_off+0xd/0x10
[   13.090683]  vprintk_emit+0x2c7/0x3a0
[   13.090684]  ? update_load_avg+0x85b/0xb80
[   13.090684]  vprintk_default+0x29/0x50
[   13.090684]  vprintk_func+0x25/0x80
[   13.090684]  printk+0x52/0x6e
[   13.090685]  ? update_load_avg+0x85b/0xb80
[   13.090685]  __warn+0x39/0xf0
[   13.090685]  warn_slowpath_fmt+0x5f/0x80
[   13.090686]  update_load_avg+0x85b/0xb80
[   13.090686]  ? debug_smp_processor_id+0x17/0x20
[   13.090686]  detach_task_cfs_rq+0x3f/0x210
[   13.090687]  task_change_group_fair+0x24/0x100
[   13.090687]  sched_change_group+0x5f/0x110
[   13.090687]  sched_move_task+0x53/0x160
[   13.090687]  cpu_cgroup_attach+0x36/0x70
[   13.090688]  cgroup_migrate_execute+0x230/0x3f0
[   13.090688]  cgroup_migrate+0xce/0x140
[   13.090688]  ? cgroup_migrate+0x5/0x140
[   13.090689]  cgroup_attach_task+0x27f/0x3e0
[   13.090689]  ? cgroup_attach_task+0x9b/0x3e0
[   13.090689]  __cgroup_procs_write+0x30e/0x510
[   13.090690]  ? __cgroup_procs_write+0x70/0x510
[   13.090690]  cgroup_procs_write+0x14/0x20
[   13.090690]  cgroup_file_write+0x44/0x1e0
[   13.090690]  kernfs_fop_write+0x13c/0x1c0
[   13.090691]  __vfs_write+0x37/0x160
[   13.090691]  ? rcu_read_lock_sched_held+0x4a/0x80
[   13.090691]  ? rcu_sync_lockdep_assert+0x2f/0x60
[   13.090692]  ? __sb_start_write+0x10d/0x220
[   13.090692]  ? vfs_write+0x19b/0x1f0
[   13.090692]  ? security_file_permission+0x3b/0xc0
[   13.090693]  vfs_write+0xcb/0x1f0
[   13.090693]  SyS_write+0x58/0xc0
[   13.090693]  entry_SYSCALL_64_fastpath+0x1f/0xc2
[   13.090693] RIP: 0033:0x7f8b7c1be210
[   13.090694] RSP: 002b:00007ffe73febfd8 EFLAGS: 00000246 ORIG_RAX:
0000000000000001
[   13.090694] RAX: ffffffffffffffda RBX: 000055a84870a7e0 RCX: 00007f8b7c1be210
[   13.090695] RDX: 0000000000000004 RSI: 000055a84870aa10 RDI: 0000000000000033
[   13.090695] RBP: 0000000000000000 R08: 000055a84870a8c0 R09: 00007f8b7dbda900
[   13.090695] R10: 000055a84870aa10 R11: 0000000000000246 R12: 0000000000000000
[   13.090696] R13: 000055a848775360 R14: 000055a84870a7e0 R15: 0000000000000033

[toc] | [next] | [standalone]

#1571342

FromJan Kara <jack@suse.cz>
Date2017-02-01 10:10 +0100
Message-ID<t5Z5o-3VC-25@gated-at.bofh.it>
In reply to#1570924
On Tue 31-01-17 10:27:53, Ross Zwisler wrote:
> On Tue, Dec 27, 2016 at 7:16 AM, Sergey Senozhatsky
> <sergey.senozhatsky@gmail.com> wrote:
> > Use printk_safe per-CPU buffers in printk recursion-prone blocks:
> > -- around logbuf_lock protected sections in vprintk_emit() and
> >    console_unlock()
> > -- around down_trylock_console_sem() and up_console_sem()
> >
> > Note that this solution addresses deadlocks caused by printk()
> > recursive calls only. That is vprintk_emit() and console_unlock().
> > The rest will be converted in a followup patch.
> >
> > Another thing to note is that we now keep lockdep enabled in printk,
> > because we are protected against the printk recursion caused by
> > lockdep in vprintk_emit() by the printk-safe mechanism - we first
> > switch to per-CPU buffers and only then access the deadlock-prone
> > locks.
> 
> When booting v4.10-rc5-mmots-2017-01-26-15-49 from the mmots tree, I
> sometimes see the following lockdep splat which I think may be related
> to this commit?

I don't think it is really related. Look at the backtrace:

> [   13.090684]  printk+0x52/0x6e
> [   13.090685]  ? update_load_avg+0x85b/0xb80
> [   13.090685]  __warn+0x39/0xf0
> [   13.090685]  warn_slowpath_fmt+0x5f/0x80
> [   13.090686]  update_load_avg+0x85b/0xb80
> [   13.090686]  ? debug_smp_processor_id+0x17/0x20
> [   13.090686]  detach_task_cfs_rq+0x3f/0x210
> [   13.090687]  task_change_group_fair+0x24/0x100
> [   13.090687]  sched_change_group+0x5f/0x110
> [   13.090687]  sched_move_task+0x53/0x160
> [   13.090687]  cpu_cgroup_attach+0x36/0x70
> [   13.090688]  cgroup_migrate_execute+0x230/0x3f0
> [   13.090688]  cgroup_migrate+0xce/0x140
> [   13.090688]  ? cgroup_migrate+0x5/0x140
> [   13.090689]  cgroup_attach_task+0x27f/0x3e0
> [   13.090689]  ? cgroup_attach_task+0x9b/0x3e0
> [   13.090689]  __cgroup_procs_write+0x30e/0x510
> [   13.090690]  ? __cgroup_procs_write+0x70/0x510
> [   13.090690]  cgroup_procs_write+0x14/0x20
> [   13.090690]  cgroup_file_write+0x44/0x1e0
> [   13.090690]  kernfs_fop_write+0x13c/0x1c0
> [   13.090691]  __vfs_write+0x37/0x160
> [   13.090691]  ? rcu_read_lock_sched_held+0x4a/0x80
> [   13.090691]  ? rcu_sync_lockdep_assert+0x2f/0x60
> [   13.090692]  ? __sb_start_write+0x10d/0x220
> [   13.090692]  ? vfs_write+0x19b/0x1f0
> [   13.090692]  ? security_file_permission+0x3b/0xc0
> [   13.090693]  vfs_write+0xcb/0x1f0
> [   13.090693]  SyS_write+0x58/0xc0

Clearly scheduler code (update_load_avg) calls WARN_ON from scheduler while
holding rq_lock which has been always forbidden. Sergey and Petr were doing
some work to prevent similar deadlocks but I'm not sure how far they
went...

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

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

#1571374

FromPeter Zijlstra <peterz@infradead.org>
Date2017-02-01 10:40 +0100
Message-ID<t5Zyr-4a5-41@gated-at.bofh.it>
In reply to#1571342
On Wed, Feb 01, 2017 at 10:06:25AM +0100, Jan Kara wrote:
> Clearly scheduler code (update_load_avg) calls WARN_ON from scheduler while
> holding rq_lock which has been always forbidden. Sergey and Petr were doing
> some work to prevent similar deadlocks but I'm not sure how far they
> went...

Its not forbidden, just can result in the occasional deadlock, meh.


In any case, there's a patch in tip fixing that warn trigger.

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

#1571667

FromPetr Mladek <pmladek@suse.com>
Date2017-02-01 16:40 +0100
Message-ID<t65aO-7Hf-25@gated-at.bofh.it>
In reply to#1571374
On Wed 2017-02-01 10:37:39, Peter Zijlstra wrote:
> On Wed, Feb 01, 2017 at 10:06:25AM +0100, Jan Kara wrote:
> > Clearly scheduler code (update_load_avg) calls WARN_ON from scheduler while
> > holding rq_lock which has been always forbidden. Sergey and Petr were doing
> > some work to prevent similar deadlocks but I'm not sure how far they
> > went...
> 
> Its not forbidden, just can result in the occasional deadlock, meh.
> 
> 
> In any case, there's a patch in tip fixing that warn trigger.

I guess that you are talking about the introduction of
#define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)

It reduces the risk of the deadlock but some risk is still there.
IMHO, it does not avoid the lockdep warning.

One solution would be to hide the occasional deadlock and disable
lockdep in SCHED_WARN_ON():

#define SCHED_WARN_ON(x)				\
({							\
	int __ret_sched_warn_on;			\
	lockdep_off();					\
	__ret_sched_warn_on = WARN_ONCE(x, #x);		\
	lockdep_on();					\
	unlikely(__ret_sched_warn_on);			\
})


Another solution would be to redirect it into the
alternative buffer and let it printed later:

#define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)		\
({								\
	unsigned long __sched_warn_on_flags;			\
	printk_safe_enter_irqsave(__sched_warn_on_flags);	\
	__ret_sched_warn_on = WARN_ONCE(x, #x);			\
	printk_safe_exit_irqrestore(__sched_warn_on_flags);	\
	unlikely(__ret_sched_warn_on);				\
})

Best Regards,
Petr

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

#1571696

FromPeter Zijlstra <peterz@infradead.org>
Date2017-02-01 17:20 +0100
Message-ID<t65Nx-8ap-31@gated-at.bofh.it>
In reply to#1571667
On Wed, Feb 01, 2017 at 04:39:10PM +0100, Petr Mladek wrote:
> I guess that you are talking about the introduction of
> #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)

No, there's a lot of regular WARN/WARN_ON/etc.. usage in the scheduler.
That thing was just a convenience wapper to print the condition that
warned.

> It reduces the risk of the deadlock but some risk is still there.
> IMHO, it does not avoid the lockdep warning.

It doesn't reduce anything, nor did it ever try. I really don't care if
it occasionally deadlocks, as long as it mostly gets out.

> One solution would be to hide the occasional deadlock and disable
> lockdep in SCHED_WARN_ON():
> 
> #define SCHED_WARN_ON(x)				\
> ({							\
> 	int __ret_sched_warn_on;			\
> 	lockdep_off();					\
> 	__ret_sched_warn_on = WARN_ONCE(x, #x);		\
> 	lockdep_on();					\
> 	unlikely(__ret_sched_warn_on);			\
> })

Like said, there's plenty of regular WARN/WARN_ON usage, so this will
not help much.

> Another solution would be to redirect it into the
> alternative buffer and let it printed later:
> 
> #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)		\
> ({								\
> 	unsigned long __sched_warn_on_flags;			\
> 	printk_safe_enter_irqsave(__sched_warn_on_flags);	\
> 	__ret_sched_warn_on = WARN_ONCE(x, #x);			\
> 	printk_safe_exit_irqrestore(__sched_warn_on_flags);	\
> 	unlikely(__ret_sched_warn_on);				\
> })

So my kernel doesn't yet have that abomination; that redirects it to a
buffer for later printing right? I hope that buffer is big enough to
hold a full WARN splat and the machine lives long enough to make it to
printing that crap.

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

#1571723

FromSteven Rostedt <rostedt@goodmis.org>
Date2017-02-01 17:50 +0100
Message-ID<t66gx-8kU-7@gated-at.bofh.it>
In reply to#1571696
On Wed, 1 Feb 2017 17:15:41 +0100
Peter Zijlstra <peterz@infradead.org> wrote:
 
> So my kernel doesn't yet have that abomination; that redirects it to a
> buffer for later printing right? I hope that buffer is big enough to
> hold a full WARN splat and the machine lives long enough to make it to
> printing that crap.


By default the buffer is 8K (minus 3 * sizeof(long)). But there's a
config option to grow it up to 128K if you like.

-- Steve

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

#1572119

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2017-02-02 03:20 +0100
Message-ID<t6fa9-5Yb-1@gated-at.bofh.it>
In reply to#1571667
On (02/01/17 16:39), Petr Mladek wrote:
[..]
> I guess that you are talking about the introduction of
> #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)

my guess would be that Jan was talking about printk_deferred() patch.
it's on my TODO list.

I want to entirely remove console_sem and scheduler out of printk() path.
that's the only way to make printk() deadlock safe.

	-ss

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

#1572201

FromPeter Zijlstra <peterz@infradead.org>
Date2017-02-02 10:10 +0100
Message-ID<t6lyW-1O8-11@gated-at.bofh.it>
In reply to#1572119
On Thu, Feb 02, 2017 at 11:11:34AM +0900, Sergey Senozhatsky wrote:
> On (02/01/17 16:39), Petr Mladek wrote:
> [..]
> > I guess that you are talking about the introduction of
> > #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)
> 
> my guess would be that Jan was talking about printk_deferred() patch.
> it's on my TODO list.
> 
> I want to entirely remove console_sem and scheduler out of printk() path.
> that's the only way to make printk() deadlock safe.

And useless.. if you never get around to the 'later' part where you
print the content. This way you still mostly get the output.

And no, its not the only way, see my printk->early_printk patches. early
serial console only does a loop over outb, impossible to mess that up.

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

#1572241

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2017-02-02 11:10 +0100
Message-ID<t6mv0-2sH-13@gated-at.bofh.it>
In reply to#1572201
On (02/02/17 10:07), Peter Zijlstra wrote:
> On Thu, Feb 02, 2017 at 11:11:34AM +0900, Sergey Senozhatsky wrote:
> > On (02/01/17 16:39), Petr Mladek wrote:
> > [..]
> > > I guess that you are talking about the introduction of
> > > #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)
> > 
> > my guess would be that Jan was talking about printk_deferred() patch.
> > it's on my TODO list.
> > 
> > I want to entirely remove console_sem and scheduler out of printk() path.
> > that's the only way to make printk() deadlock safe.
> 
> And useless.. if you never get around to the 'later' part where you
> print the content. This way you still mostly get the output.

well, I wouldn't say that printk_deferred() has less chances. I see your
point, of course. but with printk_deferred() we, at least, will have messages
in logbuf (or printk_safe buffers), so they can appear in crash dump, for
instance. that "later" part can be sysrq, for example, or panic->flush_on_panic(),
etc. if "normal" printk->queue irq_work doesn't work.

needless to say, that in this particular case (WARN from sched), if the
first printk() out of N printk()-s, which sched core calls to dump_stack(),
deadlocks, then we got nothing to print/dump.

> And no, its not the only way, see my printk->early_printk patches. early
> serial console only does a loop over outb, impossible to mess that up.

certainly :)

	-ss

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

#1572467

FromPetr Mladek <pmladek@suse.com>
Date2017-02-02 16:30 +0100
Message-ID<t6ruG-5L1-21@gated-at.bofh.it>
In reply to#1572241
On Thu 2017-02-02 19:03:48, Sergey Senozhatsky wrote:
> On (02/02/17 10:07), Peter Zijlstra wrote:
> > On Thu, Feb 02, 2017 at 11:11:34AM +0900, Sergey Senozhatsky wrote:
> > > On (02/01/17 16:39), Petr Mladek wrote:
> > > [..]
> > > > I guess that you are talking about the introduction of
> > > > #define SCHED_WARN_ON(x)	WARN_ONCE(x, #x)
> > > 
> > > my guess would be that Jan was talking about printk_deferred() patch.
> > > it's on my TODO list.
> > > 
> > > I want to entirely remove console_sem and scheduler out of printk() path.
> > > that's the only way to make printk() deadlock safe.
> > 
> > And useless.. if you never get around to the 'later' part where you
> > print the content. This way you still mostly get the output.
> 
> well, I wouldn't say that printk_deferred() has less chances. I see your
> point, of course. but with printk_deferred() we, at least, will have messages
> in logbuf (or printk_safe buffers), so they can appear in crash dump, for
> instance. that "later" part can be sysrq, for example, or panic->flush_on_panic(),
> etc. if "normal" printk->queue irq_work doesn't work.
> 
> needless to say, that in this particular case (WARN from sched), if the
> first printk() out of N printk()-s, which sched core calls to dump_stack(),
> deadlocks, then we got nothing to print/dump.

An always deferred printk() or another deferred ways are future work.
We should try to find a good solution, definitely.

The question is what to do with this patch. We need to change things
step by step. The printk_safe patchset is one of them and looks
almost ready.

The lockdep warnings are correct and help to find locations where
scheduler warnings might cause a deadlock.

One solution would be to keep lockdep as is in this patch. It means
to hide existing risk until we have some reasonable printk_deferred()
solution.

Another solution would to keep this patch as is and implement
WARN*_DEFERRED() variants that would either use
printk_safe_enter()/exit() as the currently usable deferred and
lockless solution. Or they could just disable lockdep and hide
the report for now. These deferred variants should be
used on all locations reported by lockdep where we want to accept the
risk. We will at least know where the potential risk is and could find
a proper solution later.

Note that I do not like hiding problems but they were hidden before this
patchset as well. I am just looking for the best way forward.


> > And no, its not the only way, see my printk->early_printk patches. early
> > serial console only does a loop over outb, impossible to mess that up.
> 
> certainly :)

Yup. I still would like to get Peter's patches in. They are in the
queue.

Best Regards,
Petr

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

#1572861

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2017-02-03 03:50 +0100
Message-ID<t6C6J-3XW-7@gated-at.bofh.it>
In reply to#1572467
On (02/02/17 16:20), Petr Mladek wrote:
> > well, I wouldn't say that printk_deferred() has less chances. I see your
> > point, of course. but with printk_deferred() we, at least, will have messages
> > in logbuf (or printk_safe buffers), so they can appear in crash dump, for
> > instance. that "later" part can be sysrq, for example, or panic->flush_on_panic(),
> > etc. if "normal" printk->queue irq_work doesn't work.
> > 
> > needless to say, that in this particular case (WARN from sched), if the
> > first printk() out of N printk()-s, which sched core calls to dump_stack(),
> > deadlocks, then we got nothing to print/dump.
> 
> An always deferred printk() or another deferred ways are future work.
> We should try to find a good solution, definitely.
> 
> The question is what to do with this patch. We need to change things
> step by step. The printk_safe patchset is one of them and looks
> almost ready.
> 
> The lockdep warnings are correct and help to find locations where
> scheduler warnings might cause a deadlock.

I like that lockdep warning. and looking at it... I think lockdep does
not add any additional risks.

we are in deadlock risky sched->printk condition due to WARN from
sched, not lockdep. the lockdep warning that we see happens after
we switch to printk_safe mode.


please see console_trylock()->__down_trylock_console_sem()


static int __down_trylock_console_sem(unsigned long ip)
{
...
 224        printk_safe_enter_irqsave(flags);
 225        lock_failed = down_trylock(&console_sem);   << print_circular_bug() comes from here
 226        printk_safe_exit_irqrestore(flags);
...
}

so the unsafe/safe printk 'map' should be as follows

[   13.090679] Call Trace:
[   13.090680]  dump_stack+0x86/0xc3
[   13.090680]  print_circular_bug+0x1be/0x210          << still in printk_safe
[   13.090680]  __lock_acquire+0x10e5/0x1270
[   13.090681]  lock_acquire+0xfd/0x200
[   13.090681]  ? down_trylock+0x14/0x40
[   13.090681]  _raw_spin_lock_irqsave+0x59/0x93
[   13.090681]  ? down_trylock+0x14/0x40
[   13.090682]  ? vprintk_emit+0x2c7/0x3a0
[   13.090682]  down_trylock+0x14/0x40
[   13.090682]  __down_trylock_console_sem+0x3c/0xc0    << we are in printk_safe now (!)
[   13.090683]  console_trylock+0x16/0x90
[   13.090683]  ? trace_hardirqs_off+0xd/0x10
[   13.090683]  vprintk_emit+0x2c7/0x3a0
[   13.090684]  ? update_load_avg+0x85b/0xb80
[   13.090684]  vprintk_default+0x29/0x50
[   13.090684]  vprintk_func+0x25/0x80                  << we are in unsafe printk here (!)
[   13.090684]  printk+0x52/0x6e
[   13.090685]  ? update_load_avg+0x85b/0xb80
[   13.090685]  __warn+0x39/0xf0
[   13.090685]  warn_slowpath_fmt+0x5f/0x80
[   13.090686]  update_load_avg+0x85b/0xb80
[   13.090686]  ? debug_smp_processor_id+0x17/0x20
[   13.090686]  detach_task_cfs_rq+0x3f/0x210
[   13.090687]  task_change_group_fair+0x24/0x100
[   13.090687]  sched_change_group+0x5f/0x110
[   13.090687]  sched_move_task+0x53/0x160
[   13.090687]  cpu_cgroup_attach+0x36/0x70
[   13.090688]  cgroup_migrate_execute+0x230/0x3f0
[   13.090688]  cgroup_migrate+0xce/0x140
[   13.090688]  ? cgroup_migrate+0x5/0x140
[   13.090689]  cgroup_attach_task+0x27f/0x3e0
[   13.090689]  ? cgroup_attach_task+0x9b/0x3e0
[   13.090689]  __cgroup_procs_write+0x30e/0x510
[   13.090690]  ? __cgroup_procs_write+0x70/0x510
[   13.090690]  cgroup_procs_write+0x14/0x20
[   13.090690]  cgroup_file_write+0x44/0x1e0
[   13.090690]  kernfs_fop_write+0x13c/0x1c0
[   13.090691]  __vfs_write+0x37/0x160
[   13.090691]  ? rcu_read_lock_sched_held+0x4a/0x80
[   13.090691]  ? rcu_sync_lockdep_assert+0x2f/0x60
[   13.090692]  ? __sb_start_write+0x10d/0x220
[   13.090692]  ? vfs_write+0x19b/0x1f0
[   13.090692]  ? security_file_permission+0x3b/0xc0
[   13.090693]  vfs_write+0xcb/0x1f0
[   13.090693]  SyS_write+0x58/0xc0
[   13.090693]  entry_SYSCALL_64_fastpath+0x1f/0xc2


that unsafe console_trylock() is not caused by lockdep. yes, we can
deadlock in down_trylock(), but lockdep is not the root cause. and
if we will disable lockdep, sched->printk->console_trylock() still
will have pretty much same chances to deadlock.

let me know if I'm missing something.


> One solution would be to keep lockdep as is in this patch. It means
> to hide existing risk until we have some reasonable printk_deferred()
> solution.

well, yes. this is still a possible way to go (until the deferred printk()).


> Another solution would to keep this patch as is and implement
> WARN*_DEFERRED() variants that would either use
> printk_safe_enter()/exit() as the currently usable deferred and
> lockless solution. Or they could just disable lockdep and hide
> the report for now. These deferred variants should be
> used on all locations reported by lockdep where we want to accept the
> risk. We will at least know where the potential risk is and could find
> a proper solution later.

WARN*_DEFERRED() looks to me like almost unmaintainable thing.
too much work; a never ending work.


> Note that I do not like hiding problems but they were hidden before this
> patchset as well. I am just looking for the best way forward.

sure.

	-ss

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

#1572114

FromSergey Senozhatsky <sergey.senozhatsky.work@gmail.com>
Date2017-02-02 03:00 +0100
Message-ID<t6eQN-5Cs-1@gated-at.bofh.it>
In reply to#1570924
Hello Ross,

I was offline for a week for personal reasons.

On (01/31/17 10:27), Ross Zwisler wrote:
[..]
> [   13.090634] ======================================================
> [   13.090634] [ INFO: possible circular locking dependency detected ]
> [   13.090635] 4.10.0-rc5-mm1-00313-g5c0c3d7-dirty #10 Not tainted
> [   13.090635] -------------------------------------------------------
> [   13.090635] systemd/1 is trying to acquire lock:
> [   13.090636]  ((console_sem).lock){-.....}, at: [<ffffffff81110194>]
> down_trylock+0x14/0x40
> [   13.090637]
> [   13.090637] but task is already holding lock:
> [   13.090637]  (&rq->lock){-.-.-.}, at: [<ffffffff810e6116>]
> task_rq_lock+0x56/0xd0
> [   13.090638]
> [   13.090639] which lock already depends on the new lock.
> [   13.090639]
> [   13.090639]
> [   13.090640] the existing dependency chain (in reverse order) is:
> [   13.090640] c
> [   13.090640] -> #2 (&rq->lock){-.-.-.}:
> [   13.090641]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
> [   13.090642]        [<ffffffff81ca3171>] _raw_spin_lock+0x41/0x80
> [   13.090642]        [<ffffffff810fa38a>] task_fork_fair+0x3a/0x100
> [   13.090642]        [<ffffffff810ea80d>] sched_fork+0x10d/0x2c0
> [   13.090643]        [<ffffffff810b05df>] copy_process.part.30+0x69f/0x2190
> [   13.090643]        [<ffffffff810b22c6>] _do_fork+0xf6/0x700
> [   13.090643]        [<ffffffff810b28f9>] kernel_thread+0x29/0x30
> [   13.090644]        [<ffffffff81c91572>] rest_init+0x22/0x140
> [   13.090644]        [<ffffffff8280b051>] start_kernel+0x461/0x482
> [   13.090644]        [<ffffffff8280a2d6>] x86_64_start_reservations+0x2a/0x2c
> [   13.090645]        [<ffffffff8280a424>] x86_64_start_kernel+0x14c/0x16f
> [   13.090645]        [<ffffffff810001c4>] verify_cpu+0x0/0xfc
> [   13.090645]
> [   13.090645] -> #1 (&p->pi_lock){-.-.-.}:
> [   13.090647]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
> [   13.090647]        [<ffffffff81ca3f79>] _raw_spin_lock_irqsave+0x59/0x93
> [   13.090647]        [<ffffffff810e943f>] try_to_wake_up+0x3f/0x530
> [   13.090648]        [<ffffffff810e9945>] wake_up_process+0x15/0x20
> [   13.090648]        [<ffffffff81c9fc4c>] __up.isra.0+0x4c/0x50
> [   13.090648]        [<ffffffff81110256>] up+0x46/0x50
> [   13.090649]        [<ffffffff81128a55>] __up_console_sem+0x45/0x80
> [   13.090649]        [<ffffffff81129baf>] console_unlock+0x29f/0x5e0
> [   13.090649]        [<ffffffff8112a1c0>] vprintk_emit+0x2d0/0x3a0
> [   13.090650]        [<ffffffff8112a429>] vprintk_default+0x29/0x50
> [   13.090650]        [<ffffffff8112b445>] vprintk_func+0x25/0x80
> [   13.090650]        [<ffffffff81205c6d>] printk+0x52/0x6e
> [   13.090651]        [<ffffffff81185bdc>] kauditd_hold_skb+0x9c/0xa0
> [   13.090651]        [<ffffffff8118601b>] kauditd_thread+0x23b/0x520
> [   13.090651]        [<ffffffff810dbb6f>] kthread+0x10f/0x150
> [   13.090652]        [<ffffffff81ca42c1>] ret_from_fork+0x31/0x40
> [   13.090652]
> [   13.090652] -> #0 ((console_sem).lock){-.....}:
> [   13.090653]        [<ffffffff81116c85>] __lock_acquire+0x10e5/0x1270
> [   13.090653]        [<ffffffff8111727d>] lock_acquire+0xfd/0x200
> [   13.090654]        [<ffffffff81ca3f79>] _raw_spin_lock_irqsave+0x59/0x93
> [   13.090654]        [<ffffffff81110194>] down_trylock+0x14/0x40
> [   13.090654]        [<ffffffff81128b7c>] __down_trylock_console_sem+0x3c/0xc0
> [   13.090655]        [<ffffffff81128c16>] console_trylock+0x16/0x90
> [   13.090655]        [<ffffffff8112a1b7>] vprintk_emit+0x2c7/0x3a0
> [   13.090655]        [<ffffffff8112a429>] vprintk_default+0x29/0x50
> [   13.090656]        [<ffffffff8112b445>] vprintk_func+0x25/0x80
> [   13.090656]        [<ffffffff81205c6d>] printk+0x52/0x6e
> [   13.090656]        [<ffffffff810b3329>] __warn+0x39/0xf0
> [   13.090657]        [<ffffffff810b343f>] warn_slowpath_fmt+0x5f/0x80
> [   13.090657]        [<ffffffff810f550b>] update_load_avg+0x85b/0xb80
> [   13.090657]        [<ffffffff810f58bf>] detach_task_cfs_rq+0x3f/0x210
> [   13.090658]        [<ffffffff810f8e34>] task_change_group_fair+0x24/0x100
> [   13.090658]        [<ffffffff810e46ef>] sched_change_group+0x5f/0x110
> [   13.090658]        [<ffffffff810efd03>] sched_move_task+0x53/0x160
> [   13.090659]        [<ffffffff810efe46>] cpu_cgroup_attach+0x36/0x70
> [   13.090659]        [<ffffffff81172aa0>] cgroup_migrate_execute+0x230/0x3f0
> [   13.090659]        [<ffffffff81172d2e>] cgroup_migrate+0xce/0x140
> [   13.090660]        [<ffffffff8117301f>] cgroup_attach_task+0x27f/0x3e0
> [   13.090660]        [<ffffffff81175b7e>] __cgroup_procs_write+0x30e/0x510
> [   13.090661]        [<ffffffff81175d94>] cgroup_procs_write+0x14/0x20
> [   13.090661]        [<ffffffff811700e4>] cgroup_file_write+0x44/0x1e0
> [   13.090661]        [<ffffffff8135a92c>] kernfs_fop_write+0x13c/0x1c0
> [   13.090662]        [<ffffffff812b8e07>] __vfs_write+0x37/0x160
> [   13.090662]        [<ffffffff812ba8ab>] vfs_write+0xcb/0x1f0
> [   13.090662]        [<ffffffff812bbe38>] SyS_write+0x58/0xc0
> [   13.090663]        [<ffffffff81ca4041>] entry_SYSCALL_64_fastpath+0x1f/0xc2


... so it looks like a printk() from the scheduler; I don't think it's
related to printk_safe(). and to make it worse, printk is not in safe mode
when sched_move_task()->update_load_avg() calls it... so the system is
free to deadlock. we need printk_deferred() patch here.

I may be wrong, I just saw the message -- so this is a rather quick reply.


does the patch below fix the problem for you?
https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git/commit/?h=sched/core&id=1b1d62254df0fe42a711eb71948f915918987790


	-ss

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web