From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751325Ab3FYLsA (ORCPT ); Tue, 25 Jun 2013 07:48:00 -0400 Received: from mailout39.mail01.mtsvc.net ([216.70.64.83]:60031 "EHLO n12.mail01.mtsvc.net" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1750830Ab3FYLr6 (ORCPT ); Tue, 25 Jun 2013 07:47:58 -0400 Message-ID: <51C9836A.9020602@hurleysoftware.com> Date: Tue, 25 Jun 2013 07:47:54 -0400 From: Peter Hurley User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:17.0) Gecko/20130510 Thunderbird/17.0.6 MIME-Version: 1.0 To: Calvin Owens CC: Greg Kroah-Hartman , Jiri Slaby , linux-kernel@vger.kernel.org Subject: Re: tty/vt: Lockdep splat when Magic Sysrq SAK invoked References: <20130621223711.GA1686@gmail.com> In-Reply-To: <20130621223711.GA1686@gmail.com> Content-Type: text/plain; charset=UTF-8; format=flowed Content-Transfer-Encoding: 7bit X-Authenticated-User: 990527 peter@hurleysoftware.com X-MT-INTERNAL-ID: 8fa290c2a27252aacf65dbc4a42f3ce3735fb2a4 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 06/21/2013 06:37 PM, Calvin Owens wrote: > Hello all, > > I get the following lockdep splat when I invoke the "ALT+SYSRQ+K" > combination on the keyboard. It usually happens the first time, but > doing it repeatedly always triggers it. > > Kconfig follows splat. > > Cheers, > Calvin > > [ 175.523980] SysRq : SAK > [ 175.524066] SAK: killed process 1629 (agetty): task_session(p)==tty->session > [ 178.213640] SysRq : SAK > [ 178.213745] SAK: killed process 1648 (agetty): task_session(p)==tty->session > [ 179.154891] SysRq : SAK > [ 179.154981] SAK: killed process 1649 (agetty): task_session(p)==tty->session > [ 180.409357] SysRq : SAK > [ 180.409429] SAK: killed process 1650 (agetty): task_session(p)==tty->session > [ 181.102312] SysRq : SAK > [ 181.102400] SAK: killed process 1651 (agetty): task_session(p)==tty->session > [ 181.866974] SysRq : SAK > [ 181.867057] SAK: killed process 1652 (agetty): task_session(p)==tty->session > [ 182.929591] SysRq : SAK > [ 182.929665] SAK: killed process 1653 (agetty): task_session(p)==tty->session > [ 184.221174] ====================================================== > [ 184.221174] [ INFO: possible circular locking dependency detected ] > [ 184.221175] 3.10.0-rc6-newinteloldnohz-00136-gf71194a #3 Not tainted > [ 184.221176] ------------------------------------------------------- > [ 184.221177] kworker/0:1/78 is trying to acquire lock: > [ 184.221182] (console_lock){+.+.+.}, at: [] do_con_write.part.25+0x40/0x1ed0 > [ 184.221182] > but task is already holding lock: > [ 184.221185] (&ldata->echo_lock){+.+...}, at: [] process_echoes+0x62/0x310 > [ 184.221185] > which lock already depends on the new lock. > > [ 184.221186] > the existing dependency chain (in reverse order) is: > [ 184.221187] > -> #1 (&ldata->echo_lock){+.+...}: > [ 184.221190] [] lock_acquire+0x57/0x70 > [ 184.221193] [] mutex_lock_nested+0x62/0x400 > [ 184.221194] [] reset_buffer_flags+0x53/0x120 > [ 184.221195] [] n_tty_flush_buffer+0x18/0x40 > [ 184.221197] [] tty_ldisc_flush+0x31/0x50 > [ 184.221198] [] __do_SAK+0x27/0x2b0 > [ 184.221199] [] vc_SAK+0x2b/0x40 > [ 184.221201] [] process_one_work+0x1ca/0x480 > [ 184.221203] [] worker_thread+0x11b/0x370 > [ 184.221204] [] kthread+0xd6/0xe0 > [ 184.221205] [] ret_from_fork+0x7c/0xb0 > [ 184.221206] > -> #0 (console_lock){+.+.+.}: > [ 184.221208] [] __lock_acquire+0x1ae8/0x1d50 > [ 184.221209] [] lock_acquire+0x57/0x70 > [ 184.221211] [] console_lock+0x6f/0x80 > [ 184.221212] [] do_con_write.part.25+0x40/0x1ed0 > [ 184.221213] [] con_put_char+0x34/0x40 > [ 184.221214] [] tty_put_char+0x1f/0x40 > [ 184.221215] [] do_output_char+0x7d/0x210 > [ 184.221217] [] process_echoes+0x177/0x310 > [ 184.221218] [] n_tty_receive_buf+0xa12/0x1570 > [ 184.221219] [] flush_to_ldisc+0x116/0x160 > [ 184.221220] [] process_one_work+0x1ca/0x480 > [ 184.221221] [] worker_thread+0x11b/0x370 > [ 184.221222] [] kthread+0xd6/0xe0 > [ 184.221223] [] ret_from_fork+0x7c/0xb0 > [ 184.221223] > other info that might help us debug this: > > [ 184.221223] Possible unsafe locking scenario: > > [ 184.221224] CPU0 CPU1 > [ 184.221224] ---- ---- > [ 184.221224] lock(&ldata->echo_lock); > [ 184.221225] lock(console_lock); > [ 184.221226] lock(&ldata->echo_lock); > [ 184.221226] lock(console_lock); > [ 184.221226] > *** DEADLOCK *** > > [ 184.221227] 4 locks held by kworker/0:1/78: > [ 184.221229] #0: (events){.+.+.+}, at: [] process_one_work+0x16d/0x480 > [ 184.221231] #1: ((&buf->work)){+.+...}, at: [] process_one_work+0x16d/0x480 > [ 184.221233] #2: (&ldata->output_lock){+.+...}, at: [] process_echoes+0x4d/0x310 > [ 184.221234] #3: (&ldata->echo_lock){+.+...}, at: [] process_echoes+0x62/0x310 > [ 184.221235] > stack backtrace: > [ 184.221236] CPU: 0 PID: 78 Comm: kworker/0:1 Not tainted 3.10.0-rc6-newinteloldnohz-00136-gf71194a #3 > [ 184.221237] Hardware name: ASUSTeK COMPUTER INC. K55A/K55A, BIOS K55A.404 08/20/2012 > [ 184.221238] Workqueue: events flush_to_ldisc > [ 184.221241] ffffffff8259f260 ffff8801199038c8 ffffffff816b77ab ffff880119903918 > [ 184.221242] ffffffff816b4dd7 0000000000000001 ffff8801199039a0 ffff88011a34e970 > [ 184.221243] ffff88011a34eff8 ffff88011a34e970 ffff88011a34f020 ffffffff8259f260 > [ 184.221244] Call Trace: > [ 184.221245] [] dump_stack+0x19/0x1b > [ 184.221248] [] print_circular_bug+0x1fb/0x20c > [ 184.221249] [] __lock_acquire+0x1ae8/0x1d50 > [ 184.221251] [] lock_acquire+0x57/0x70 > [ 184.221252] [] ? do_con_write.part.25+0x40/0x1ed0 > [ 184.221253] [] console_lock+0x6f/0x80 > [ 184.221254] [] ? do_con_write.part.25+0x40/0x1ed0 > [ 184.221255] [] do_con_write.part.25+0x40/0x1ed0 > [ 184.221257] [] ? mutex_lock_nested+0x2f6/0x400 > [ 184.221258] [] ? trace_hardirqs_on_caller+0xfd/0x1c0 > [ 184.221259] [] con_put_char+0x34/0x40 > [ 184.221261] [] tty_put_char+0x1f/0x40 > [ 184.221262] [] do_output_char+0x7d/0x210 > [ 184.221263] [] process_echoes+0x177/0x310 > [ 184.221265] [] n_tty_receive_buf+0xa12/0x1570 > [ 184.221266] [] ? mark_held_locks+0x72/0x130 > [ 184.221267] [] ? _raw_spin_unlock_irqrestore+0x65/0x80 > [ 184.221269] [] ? trace_hardirqs_on_caller+0xfd/0x1c0 > [ 184.221270] [] flush_to_ldisc+0x116/0x160 > [ 184.221271] [] process_one_work+0x1ca/0x480 > [ 184.221272] [] ? process_one_work+0x16d/0x480 > [ 184.221273] [] worker_thread+0x11b/0x370 > [ 184.221274] [] ? rescuer_thread+0x300/0x300 > [ 184.221275] [] kthread+0xd6/0xe0 > [ 184.221276] [] ? _raw_spin_unlock_irq+0x2b/0x60 > [ 184.221277] [] ? __kthread_unpark+0x50/0x50 > [ 184.221278] [] ret_from_fork+0x7c/0xb0 > [ 184.221279] [] ? __kthread_unpark+0x50/0x50 Calvin, Thanks for this report. There is indeed a possibility of deadlock from lock inversion here. The VT driver is particularly uncareful regarding interface layering, and often calls directly into internal tty functions which cause these lock inversions. At some point, the mess that is console_lock() needs to be addressed. Unfortunately, there are few volunteers for such an undertaking. Regards, Peter Hurley