From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1750924AbdBBB7W (ORCPT ); Wed, 1 Feb 2017 20:59:22 -0500 Received: from mail-pf0-f193.google.com ([209.85.192.193]:36329 "EHLO mail-pf0-f193.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750726AbdBBB7V (ORCPT ); Wed, 1 Feb 2017 20:59:21 -0500 Date: Thu, 2 Feb 2017 10:59:37 +0900 From: Sergey Senozhatsky To: Ross Zwisler Cc: Sergey Senozhatsky , Ross Zwisler , Andrew Morton , Petr Mladek , Linus Torvalds , Jan Kara , Tejun Heo , Calvin Owens , Steven Rostedt , Ingo Molnar , Peter Zijlstra , Andy Lutomirski , Peter Hurley , LKML , Sergey Senozhatsky Subject: Re: [PATCHv7 6/8] printk: use printk_safe buffers in printk Message-ID: <20170202015937.GA1954@jagdpanzerIV.localdomain> References: <20161227141611.940-1-sergey.senozhatsky@gmail.com> <20161227141611.940-7-sergey.senozhatsky@gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.7.2 (2016-11-26) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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: [] > down_trylock+0x14/0x40 > [ 13.090637] > [ 13.090637] but task is already holding lock: > [ 13.090637] (&rq->lock){-.-.-.}, at: [] > 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] [] lock_acquire+0xfd/0x200 > [ 13.090642] [] _raw_spin_lock+0x41/0x80 > [ 13.090642] [] task_fork_fair+0x3a/0x100 > [ 13.090642] [] sched_fork+0x10d/0x2c0 > [ 13.090643] [] copy_process.part.30+0x69f/0x2190 > [ 13.090643] [] _do_fork+0xf6/0x700 > [ 13.090643] [] kernel_thread+0x29/0x30 > [ 13.090644] [] rest_init+0x22/0x140 > [ 13.090644] [] start_kernel+0x461/0x482 > [ 13.090644] [] x86_64_start_reservations+0x2a/0x2c > [ 13.090645] [] x86_64_start_kernel+0x14c/0x16f > [ 13.090645] [] verify_cpu+0x0/0xfc > [ 13.090645] > [ 13.090645] -> #1 (&p->pi_lock){-.-.-.}: > [ 13.090647] [] lock_acquire+0xfd/0x200 > [ 13.090647] [] _raw_spin_lock_irqsave+0x59/0x93 > [ 13.090647] [] try_to_wake_up+0x3f/0x530 > [ 13.090648] [] wake_up_process+0x15/0x20 > [ 13.090648] [] __up.isra.0+0x4c/0x50 > [ 13.090648] [] up+0x46/0x50 > [ 13.090649] [] __up_console_sem+0x45/0x80 > [ 13.090649] [] console_unlock+0x29f/0x5e0 > [ 13.090649] [] vprintk_emit+0x2d0/0x3a0 > [ 13.090650] [] vprintk_default+0x29/0x50 > [ 13.090650] [] vprintk_func+0x25/0x80 > [ 13.090650] [] printk+0x52/0x6e > [ 13.090651] [] kauditd_hold_skb+0x9c/0xa0 > [ 13.090651] [] kauditd_thread+0x23b/0x520 > [ 13.090651] [] kthread+0x10f/0x150 > [ 13.090652] [] ret_from_fork+0x31/0x40 > [ 13.090652] > [ 13.090652] -> #0 ((console_sem).lock){-.....}: > [ 13.090653] [] __lock_acquire+0x10e5/0x1270 > [ 13.090653] [] lock_acquire+0xfd/0x200 > [ 13.090654] [] _raw_spin_lock_irqsave+0x59/0x93 > [ 13.090654] [] down_trylock+0x14/0x40 > [ 13.090654] [] __down_trylock_console_sem+0x3c/0xc0 > [ 13.090655] [] console_trylock+0x16/0x90 > [ 13.090655] [] vprintk_emit+0x2c7/0x3a0 > [ 13.090655] [] vprintk_default+0x29/0x50 > [ 13.090656] [] vprintk_func+0x25/0x80 > [ 13.090656] [] printk+0x52/0x6e > [ 13.090656] [] __warn+0x39/0xf0 > [ 13.090657] [] warn_slowpath_fmt+0x5f/0x80 > [ 13.090657] [] update_load_avg+0x85b/0xb80 > [ 13.090657] [] detach_task_cfs_rq+0x3f/0x210 > [ 13.090658] [] task_change_group_fair+0x24/0x100 > [ 13.090658] [] sched_change_group+0x5f/0x110 > [ 13.090658] [] sched_move_task+0x53/0x160 > [ 13.090659] [] cpu_cgroup_attach+0x36/0x70 > [ 13.090659] [] cgroup_migrate_execute+0x230/0x3f0 > [ 13.090659] [] cgroup_migrate+0xce/0x140 > [ 13.090660] [] cgroup_attach_task+0x27f/0x3e0 > [ 13.090660] [] __cgroup_procs_write+0x30e/0x510 > [ 13.090661] [] cgroup_procs_write+0x14/0x20 > [ 13.090661] [] cgroup_file_write+0x44/0x1e0 > [ 13.090661] [] kernfs_fop_write+0x13c/0x1c0 > [ 13.090662] [] __vfs_write+0x37/0x160 > [ 13.090662] [] vfs_write+0xcb/0x1f0 > [ 13.090662] [] SyS_write+0x58/0xc0 > [ 13.090663] [] 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