From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1758623AbZC0FIb (ORCPT ); Fri, 27 Mar 2009 01:08:31 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1752101AbZC0FIW (ORCPT ); Fri, 27 Mar 2009 01:08:22 -0400 Received: from fmailhost02.isp.att.net ([204.127.217.102]:46349 "EHLO fmailhost02.isp.att.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751895AbZC0FIU (ORCPT ); Fri, 27 Mar 2009 01:08:20 -0400 X-Originating-IP: [69.76.240.125] Message-ID: <49CC5F15.4020404@lwfinger.net> Date: Fri, 27 Mar 2009 00:07:33 -0500 From: Larry Finger User-Agent: Thunderbird 2.0.0.19 (X11/20081227) MIME-Version: 1.0 To: LKML Subject: Possible IRQ lock inversion from 2.6.29-Linus-03321-gbe0ea69 (2.6.29-git) Content-Type: text/plain; charset=ISO-8859-1 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On my x86_64 dual core system, I get the following messages logged. ========================================================= [ INFO: possible irq lock inversion dependency detected ] 2.6.29-Linus-03321-gbe0ea69 #55 --------------------------------------------------------- swapper/0 just changed the state of lock: (fasync_lock){..+.}, at: [] kill_fasync+0x2c/0x4e but this lock took another, hard-irq-unsafe lock in the past: (&f->f_lock){--..} and interrupts could create inverse lock ordering between them. other info that might help us debug this: 4 locks held by swapper/0: #0: (&serio->lock){+...}, at: [] serio_interrupt+0x2b/0x83 #1: (&dev->event_lock){+...}, at: [] input_event+0x40/0x7d #2: (rcu_read_lock){..--}, at: [] input_pass_event+0x0/0xcc #3: (rcu_read_lock){..--}, at: [] evdev_event+0x0/0xfd the first lock's dependencies: -> (fasync_lock){..+.} ops: 0 { initial-use at: [] __lock_acquire+0x79e/0x1697 [] lock_acquire+0x55/0x71 [] _write_lock_irq+0x37/0x43 [] fasync_helper+0x57/0x110 [] locks_delete_lock+0x50/0x9f [] __posix_lock_file+0x326/0x549 [] vfs_lock_file+0x38/0x3a [] locks_remove_posix+0x91/0xb2 [] filp_close+0x56/0x68 [] sys_close+0xaa/0xe9 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff in-hardirq-R at: [] 0xffffffffffffffff } ... key at: [] fasync_lock+0x18/0x30 -> (&f->f_lock){--..} ops: 0 { initial-use at: [] __lock_acquire+0x79e/0x1697 [] lock_acquire+0x55/0x71 [] _spin_lock+0x31/0x3d [] fasync_helper+0xd6/0x110 [] locks_delete_lock+0x50/0x9f [] __posix_lock_file+0x326/0x549 [] vfs_lock_file+0x38/0x3a [] locks_remove_posix+0x91/0xb2 [] filp_close+0x56/0x68 [] sys_close+0xaa/0xe9 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff softirq-on-W at: [] __lock_acquire+0x785/0x1697 [] lock_acquire+0x55/0x71 [] _spin_lock+0x31/0x3d [] sys_fcntl+0x2aa/0x36c [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff hardirq-on-W at: [] __lock_acquire+0x75c/0x1697 [] lock_acquire+0x55/0x71 [] _spin_lock+0x31/0x3d [] sys_fcntl+0x2aa/0x36c [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff } ... key at: [] __key.20386+0x0/0x8 ... acquired at: [] __lock_acquire+0x1332/0x1697 [] lock_acquire+0x55/0x71 [] _spin_lock+0x31/0x3d [] fasync_helper+0xd6/0x110 [] locks_delete_lock+0x50/0x9f [] __posix_lock_file+0x326/0x549 [] vfs_lock_file+0x38/0x3a [] locks_remove_posix+0x91/0xb2 [] filp_close+0x56/0x68 [] sys_close+0xaa/0xe9 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff the second lock's dependencies: -> (&f->f_lock){--..} ops: 0 { initial-use at: [] __lock_acquire+0x79e/0x1697 [] lock_acquire+0x55/0x71 [] _spin_lock+0x31/0x3d [] fasync_helper+0xd6/0x110 [] locks_delete_lock+0x50/0x9f [] __posix_lock_file+0x326/0x549 [] vfs_lock_file+0x38/0x3a [] locks_remove_posix+0x91/0xb2 [] filp_close+0x56/0x68 [] sys_close+0xaa/0xe9 [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff softirq-on-W at: [] __lock_acquire+0x785/0x1697 [] lock_acquire+0x55/0x71 [] _spin_lock+0x31/0x3d [] sys_fcntl+0x2aa/0x36c [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff hardirq-on-W at: [] __lock_acquire+0x75c/0x1697 [] lock_acquire+0x55/0x71 [] _spin_lock+0x31/0x3d [] sys_fcntl+0x2aa/0x36c [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff } ... key at: [] __key.20386+0x0/0x8 stack backtrace: Pid: 0, comm: swapper Not tainted 2.6.29-Linus-03321-gbe0ea69 #55 Call Trace: [] print_irq_inversion_bug+0x175/0x184 [] check_usage_forwards+0x98/0xa1 [] mark_lock+0x5dd/0xa2b [] __lock_acquire+0x676/0x1697 [] ? __lock_acquire+0x79e/0x1697 [] lock_acquire+0x55/0x71 [] ? kill_fasync+0x2c/0x4e [] _read_lock+0x34/0x41 [] ? kill_fasync+0x2c/0x4e [] kill_fasync+0x2c/0x4e [] evdev_pass_event+0x6e/0x77 [] evdev_event+0x74/0xfd [] ? evdev_event+0x0/0xfd [] input_pass_event+0x64/0xcc [] ? input_pass_event+0x0/0xcc [] input_handle_event+0x339/0x345 [] input_event+0x63/0x7d [] alps_process_packet+0x3b7/0x4cc [] alps_process_byte+0x5b/0x6e [] psmouse_handle_byte+0x17/0x10d [] psmouse_interrupt+0x277/0x285 [] ? serio_interrupt+0x2b/0x83 [] serio_interrupt+0x47/0x83 [] i8042_interrupt+0x200/0x215 [] handle_IRQ_event+0x6b/0xa1 [] handle_edge_irq+0xeb/0x131 [] __irqentry_text_start+0x6d/0xd8 [] ret_from_intr+0x0/0xf [] ? tick_broadcast_oneshot_control+0x1f/0x102 [] ? default_idle+0x35/0x4f [] ? default_idle+0x33/0x4f [] ? c1e_idle+0xda/0x101 [] ? atomic_notifier_call_chain+0xf/0x11 [] ? cpu_idle+0x5c/0x9d [] ? rest_init+0x6b/0x6d