Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S933506AbXHYJnp (ORCPT ); Sat, 25 Aug 2007 05:43:45 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1759941AbXHYJnd (ORCPT ); Sat, 25 Aug 2007 05:43:33 -0400 Received: from xdsl-664.zgora.dialog.net.pl ([81.168.226.152]:2933 "EHLO tuxland.pl" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755498AbXHYJn2 (ORCPT ); Sat, 25 Aug 2007 05:43:28 -0400 From: Mariusz Kozlowski To: Jarek Poplawski Subject: Re: [PATCH 2.6.23-rc3-mm1] request_irq fix DEBUG_SHIRQ handling Re: 2.6.23-rc2-mm1: rtl8139 inconsistent lock state Date: Sat, 25 Aug 2007 11:43:08 +0200 User-Agent: KMail/1.9.7 Cc: Andrew Morton , netdev@vger.kernel.org, Jeff Garzik , David Woodhouse , Ingo Molnar , Thomas Gleixner , linux-kernel@vger.kernel.org References: <20070822133511.GH1684@ff.dom.local> In-Reply-To: <20070822133511.GH1684@ff.dom.local> MIME-Version: 1.0 Content-Type: text/plain; charset="iso-8859-1" Content-Transfer-Encoding: 7bit Content-Disposition: inline Message-Id: <200708251143.09425.m.kozlowski@tuxland.pl> Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 48378 Lines: 902 > > ================================= > > [ INFO: inconsistent lock state ] > > 2.6.23-rc2-mm1 #7 > > --------------------------------- > > inconsistent {in-hardirq-W} -> {hardirq-on-W} usage. > > ifconfig/5492 [HC0[0]:SC0[0]:HE1:SE1] takes: > > (&tp->lock){+...}, at: [] rtl8139_interrupt+0x27/0x46b [8139too] > > {in-hardirq-W} state was registered at: > > [] __lock_acquire+0x949/0x11ac > > [] lock_acquire+0x99/0xb2 > > [] _spin_lock+0x35/0x42 > > [] rtl8139_interrupt+0x27/0x46b [8139too] > > [] handle_IRQ_event+0x28/0x59 > > [] handle_level_irq+0xad/0x10b > > [] do_IRQ+0x93/0xd0 > > [] common_interrupt+0x2e/0x34 > ... > > other info that might help us debug this: > > 1 lock held by ifconfig/5492: > > #0: (rtnl_mutex){--..}, at: [] mutex_lock+0x1c/0x1f > > > > stack backtrace: > ... > > [] _spin_lock+0x35/0x42 > > [] rtl8139_interrupt+0x27/0x46b [8139too] > > [] free_irq+0x11b/0x146 > > [] rtl8139_close+0x8a/0x14a [8139too] > > [] dev_close+0x57/0x74 > ... > > It looks like this was possible after David's fix, which really > enabled running of the handler in free_irq, but before Andrew's patch > disabling local irqs for this time. > > So, this bug should be fixed, but IMHO similar problem is possible in > request_irq. And, I think, this is not only about lockdep complaining, > but real lockup possibility, because any locks in such a handler are > taken in another, not expected for them context, and could be > vulnerable (especially with softirqs, but probably hardirqs as well). > > Reported-by: Mariusz Kozlowski > Signed-off-by: Jarek Poplawski > > --- > > diff -Nurp 2.6.23-rc3-mm1-/kernel/irq/manage.c 2.6.23-rc3-mm1/kernel/irq/manage.c > --- 2.6.23-rc3-mm1-/kernel/irq/manage.c 2007-08-22 13:58:58.000000000 +0200 > +++ 2.6.23-rc3-mm1/kernel/irq/manage.c 2007-08-22 14:12:21.000000000 +0200 > @@ -546,14 +546,11 @@ int request_irq(unsigned int irq, irq_ha > * We do this before actually registering it, to make sure that > * a 'real' IRQ doesn't run in parallel with our fake > */ > - if (irqflags & IRQF_DISABLED) { > - unsigned long flags; > + unsigned long flags; > > - local_irq_save(flags); > - handler(irq, dev_id); > - local_irq_restore(flags); > - } else > - handler(irq, dev_id); > + local_irq_save(flags); > + handler(irq, dev_id); > + local_irq_restore(flags); > } > #endif I tested your patch and it still happens. Dmesg info from patched kernel attached. I coulnd't reproduce that on 2.6.23-rc3-mm1 - but on 2.6.23-rc2-mm2 it is easily reproducible. If you need more info, test some patches, etc. - just mail me. Pozdrawiam, Mariusz ========================================================= [ INFO: possible irq lock inversion dependency detected ] 2.6.23-rc2-mm2 #2 --------------------------------------------------------- runscript.sh/5065 just changed the state of lock: (_xmit_ETHER){-+..}, at: [] dev_watchdog+0x17/0xcc but this lock took another, soft-irq-unsafe lock in the past: (&tp->lock){--..} and interrupts could create inverse lock ordering between them. other info that might help us debug this: 1 lock held by runscript.sh/5065: #0: (&mm->mmap_sem){----}, at: [] do_page_fault+0x159/0x6f0 the first lock's dependencies: -> (_xmit_ETHER){-+..} ops: 21 { initial-use at: [] __lock_acquire+0x217/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_bh+0x3a/0x47 [] dev_set_rx_mode+0x14/0x3b [] dev_change_flags+0x68/0x190 [] devinet_ioctl+0x4af/0x652 [] inet_ioctl+0x56/0x71 [] sock_ioctl+0xa5/0x1d4 [] do_ioctl+0x22/0x71 [] vfs_ioctl+0x55/0x29e [] sys_ioctl+0x33/0x69 [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff in-softirq-W at: [] __lock_acquire+0x6f2/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock+0x35/0x42 [] dev_watchdog+0x17/0xcc [] run_timer_softirq+0x14b/0x1a9 [] __do_softirq+0x5b/0xb2 [] do_softirq+0x4d/0x4f [] irq_exit+0x48/0x4a [] do_IRQ+0x98/0xd0 [] common_interrupt+0x2e/0x34 [] find_lock_page+0x9b/0xa5 [] filemap_fault+0x188/0x4d9 [] __do_fault+0xb7/0x444 [] handle_mm_fault+0x18a/0x6fc [] do_page_fault+0x454/0x6f0 [] error_code+0x6a/0x70 [] 0xffffffff hardirq-on-W at: [] __lock_acquire+0x73e/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_bh+0x3a/0x47 [] dev_set_rx_mode+0x14/0x3b [] dev_change_flags+0x68/0x190 [] devinet_ioctl+0x4af/0x652 [] inet_ioctl+0x56/0x71 [] sock_ioctl+0xa5/0x1d4 [] do_ioctl+0x22/0x71 [] vfs_ioctl+0x55/0x29e [] sys_ioctl+0x33/0x69 [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff } ... key at: [] netdev_xmit_lock_key+0x8/0x1c0 -> (&tp->lock){--..} ops: 44 { initial-use at: [] __lock_acquire+0x217/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock+0x35/0x42 [] rtl8139_interrupt+0x27/0x469 [8139too] [] request_irq+0xd6/0xf8 [] rtl8139_open+0x2f/0x1e2 [8139too] [] dev_open+0x37/0x76 [] dev_change_flags+0x8e/0x190 [] devinet_ioctl+0x4af/0x652 [] inet_ioctl+0x56/0x71 [] sock_ioctl+0xa5/0x1d4 [] do_ioctl+0x22/0x71 [] vfs_ioctl+0x55/0x29e [] sys_ioctl+0x33/0x69 [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff softirq-on-W at: [] __lock_acquire+0x767/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock+0x35/0x42 [] rtl8139_interrupt+0x27/0x469 [8139too] [] free_irq+0x11b/0x146 [] rtl8139_close+0x8a/0x14a [8139too] [] dev_close+0x57/0x74 [] dev_change_flags+0x8e/0x190 [] devinet_ioctl+0x4af/0x652 [] inet_ioctl+0x56/0x71 [] sock_ioctl+0xa5/0x1d4 [] do_ioctl+0x22/0x71 [] vfs_ioctl+0x55/0x29e [] sys_ioctl+0x33/0x69 [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff hardirq-on-W at: [] __lock_acquire+0x73e/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock+0x35/0x42 [] rtl8139_interrupt+0x27/0x469 [8139too] [] free_irq+0x11b/0x146 [] rtl8139_close+0x8a/0x14a [8139too] [] dev_close+0x57/0x74 [] dev_change_flags+0x8e/0x190 [] devinet_ioctl+0x4af/0x652 [] inet_ioctl+0x56/0x71 [] sock_ioctl+0xa5/0x1d4 [] do_ioctl+0x22/0x71 [] vfs_ioctl+0x55/0x29e [] sys_ioctl+0x33/0x69 [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff } ... key at: [] __key.19796+0x0/0xffffd3c9 [8139too] ... acquired at: [] __lock_acquire+0x109b/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] rtl8139_set_rx_mode+0x1e/0x166 [8139too] [] __dev_set_rx_mode+0x24/0x85 [] dev_set_rx_mode+0x26/0x3b [] dev_open+0x5a/0x76 [] dev_change_flags+0x8e/0x190 [] devinet_ioctl+0x4af/0x652 [] inet_ioctl+0x56/0x71 [] sock_ioctl+0xa5/0x1d4 [] do_ioctl+0x22/0x71 [] vfs_ioctl+0x55/0x29e [] sys_ioctl+0x33/0x69 [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff -> (&priv->lock){++..} ops: 103 { initial-use at: [] __lock_acquire+0x217/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irq+0x3b/0x48 [] orinoco_init+0x8f5/0xbbd [orinoco] [] register_netdevice+0x13a/0x3f8 [] register_netdev+0x32/0x3f [] orinoco_cs_probe+0x368/0x3df [orinoco_cs] [] pcmcia_device_probe+0xc9/0x14c [pcmcia] [] driver_probe_device+0xa6/0x198 [] __driver_attach+0xa2/0xa4 [] bus_for_each_dev+0x43/0x61 [] driver_attach+0x19/0x1b [] bus_add_driver+0x7e/0x1a5 [] driver_register+0x45/0x75 [] pcmcia_register_driver+0xdb/0x12f [pcmcia] [] 0xde87c024 [] sys_init_module+0xc4/0x1622 [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff in-hardirq-W at: [] __lock_acquire+0x949/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] orinoco_interrupt+0x3f/0x1219 [orinoco] [] handle_IRQ_event+0x28/0x59 [] handle_level_irq+0xad/0x10b [] do_IRQ+0x93/0xd0 [] common_interrupt+0x2e/0x34 [] orinoco_get_wireless_stats+0xeb/0x140 [orinoco] [] get_wireless_stats+0x1a/0x21 [] wireless_seq_show+0x20/0x143 [] seq_read+0x1af/0x2b8 [] proc_reg_read+0x57/0x78 [] vfs_read+0xaa/0x147 [] sys_read+0x3d/0x7b [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff in-softirq-W at: [] __lock_acquire+0x6f2/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] orinoco_interrupt+0x3f/0x1219 [orinoco] [] handle_IRQ_event+0x28/0x59 [] handle_level_irq+0xad/0x10b [] do_IRQ+0x93/0xd0 [] common_interrupt+0x2e/0x34 [] do_softirq+0x4d/0x4f [] irq_exit+0x48/0x4a [] do_IRQ+0x98/0xd0 [] common_interrupt+0x2e/0x34 [] orinoco_get_wireless_stats+0xeb/0x140 [orinoco] [] get_wireless_stats+0x1a/0x21 [] wireless_seq_show+0x20/0x143 [] seq_read+0x1af/0x2b8 [] proc_reg_read+0x57/0x78 [] vfs_read+0xaa/0x147 [] sys_read+0x3d/0x7b [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff } ... key at: [] __key.20430+0x0/0xffffc9cd [orinoco] -> (lweventlist_lock){+...} ops: 8 { initial-use at: [] __lock_acquire+0x217/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] linkwatch_add_event+0x10/0x31 [] linkwatch_fire_event+0x35/0x37 [] netif_carrier_off+0x19/0x20 [] alloc_orinocodev+0x181/0x19c [orinoco] [] orinoco_cs_probe+0x1d/0x3df [orinoco_cs] [] pcmcia_device_probe+0xc9/0x14c [pcmcia] [] driver_probe_device+0xa6/0x198 [] __driver_attach+0xa2/0xa4 [] bus_for_each_dev+0x43/0x61 [] driver_attach+0x19/0x1b [] bus_add_driver+0x7e/0x1a5 [] driver_register+0x45/0x75 [] pcmcia_register_driver+0xdb/0x12f [pcmcia] [] 0xde87c024 [] sys_init_module+0xc4/0x1622 [] sysenter_past_esp+0x5f/0x99 [] 0xffffffff in-hardirq-W at: [] __lock_acquire+0x949/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] linkwatch_add_event+0x10/0x31 [] linkwatch_fire_event+0x35/0x37 [] netif_carrier_on+0x29/0x2b [] orinoco_interrupt+0x1067/0x1219 [orinoco] [] handle_IRQ_event+0x28/0x59 [] handle_level_irq+0xad/0x10b [] do_IRQ+0x93/0xd0 [] common_interrupt+0x2e/0x34 [] cpuidle_idle_call+0x74/0x99 [] cpu_idle+0x87/0x89 [] rest_init+0x60/0x62 [] start_kernel+0x23a/0x2c5 [<00000000>] 0x0 [] 0xffffffff } ... key at: [] lweventlist_lock+0x10/0x20 ... acquired at: [] __lock_acquire+0x109b/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] linkwatch_add_event+0x10/0x31 [] linkwatch_fire_event+0x35/0x37 [] netif_carrier_on+0x29/0x2b [] orinoco_interrupt+0x1067/0x1219 [orinoco] [] handle_IRQ_event+0x28/0x59 [] handle_level_irq+0xad/0x10b [] do_IRQ+0x93/0xd0 [] common_interrupt+0x2e/0x34 [] cpuidle_idle_call+0x74/0x99 [] cpu_idle+0x87/0x89 [] rest_init+0x60/0x62 [] start_kernel+0x23a/0x2c5 [<00000000>] 0x0 [] 0xffffffff -> (&cwq->lock){++..} ops: 4755 { initial-use at: [] __lock_acquire+0x217/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] __queue_work+0xf/0x2d [] queue_work+0x57/0x90 [] call_usermodehelper_exec+0xce/0xe1 [] kobject_uevent_env+0x34d/0x449 [] kobject_uevent+0xa/0xf [] kset_register+0x32/0x38 [] subsystem_register+0x8/0xa [] bus_register+0x65/0x1f3 [] platform_bus_init+0x23/0x38 [] driver_init+0x1c/0x31 [] kernel_init+0x5d/0x26b [] kernel_thread_helper+0x7/0x1c [] 0xffffffff in-hardirq-W at: [] __lock_acquire+0x949/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] __queue_work+0xf/0x2d [] queue_work+0x57/0x90 [] acpi_os_execute+0xae/0xcb [] acpi_ec_gpe_handler+0x4d/0x5e [] acpi_ev_gpe_dispatch+0x4b/0x115 [] acpi_ev_gpe_detect+0x9a/0xe1 [] acpi_ev_sci_xrupt_handler+0x15/0x1d [] acpi_irq+0xe/0x18 [] handle_IRQ_event+0x28/0x59 [] handle_level_irq+0xad/0x10b [] do_IRQ+0x93/0xd0 [] common_interrupt+0x2e/0x34 [] cpu_idle+0x87/0x89 [] rest_init+0x60/0x62 [] start_kernel+0x23a/0x2c5 [<00000000>] 0x0 [] 0xffffffff in-softirq-W at: [] __lock_acquire+0x6f2/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] __queue_work+0xf/0x2d [] delayed_work_timer_fn+0x24/0x28 [] run_timer_softirq+0x14b/0x1a9 [] __do_softirq+0x5b/0xb2 [] do_softirq+0x4d/0x4f [] irq_exit+0x48/0x4a [] do_IRQ+0x98/0xd0 [] common_interrupt+0x2e/0x34 [] _spin_unlock+0x16/0x4d [] _atomic_dec_and_lock+0x2e/0x50 [] dput+0x36/0x101 [] __link_path_walk+0x8de/0xe06 [] link_path_walk+0x5b/0xe0 [] path_walk+0x18/0x1a [] do_path_lookup+0x8f/0x21c [] __path_lookup_intent_open+0x44/0x99 [] path_lookup_open+0x21/0x27 [] open_exec+0x27/0xac [] do_execve+0x34/0x181 [] sys_execve+0x48/0x98 [] syscall_call+0x7/0xb [] 0xffffffff } ... key at: [] __key.11148+0x0/0x8 -> (&q->lock){++..} ops: 69175 { initial-use at: [] __lock_acquire+0x217/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irq+0x3b/0x48 [] wait_for_completion+0x24/0xb5 [] kthread_create+0x69/0xa8 [] cpu_callback+0x48/0xa3 [] spawn_ksoftirqd+0x1c/0x4e [] kernel_init+0x3c/0x26b [] kernel_thread_helper+0x7/0x1c [] 0xffffffff in-hardirq-W at: [] __lock_acquire+0x949/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] __wake_up+0x15/0x42 [] acpi_ec_gpe_handler+0x26/0x5e [] acpi_ev_gpe_dispatch+0x4b/0x115 [] acpi_ev_gpe_detect+0x9a/0xe1 [] acpi_ev_sci_xrupt_handler+0x15/0x1d [] acpi_irq+0xe/0x18 [] handle_IRQ_event+0x28/0x59 [] handle_level_irq+0xad/0x10b [] do_IRQ+0x93/0xd0 [] common_interrupt+0x2e/0x34 [] cpu_idle+0x87/0x89 [] rest_init+0x60/0x62 [] start_kernel+0x23a/0x2c5 [<00000000>] 0x0 [] 0xffffffff in-softirq-W at: [] __lock_acquire+0x6f2/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] complete+0x15/0x4b [] wakeme_after_rcu+0xb/0xd [] __rcu_process_callbacks+0x69/0x1cf [] rcu_process_callbacks+0x12/0x23 [] tasklet_action+0x3b/0x7b [] __do_softirq+0x5b/0xb2 [] do_softirq+0x4d/0x4f [] irq_exit+0x48/0x4a [] do_IRQ+0x98/0xd0 [] common_interrupt+0x2e/0x34 [] cpu_idle+0x87/0x89 [] rest_init+0x60/0x62 [] start_kernel+0x23a/0x2c5 [<00000000>] 0x0 [] 0xffffffff } ... key at: [] __key.11466+0x0/0x8 -> (&rq->rq_lock_key){++..} ops: 212030 { initial-use at: [] __lock_acquire+0x217/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock_irqsave+0x3e/0x4e [] init_idle+0x40/0x6d [] sched_init+0x169/0x17c [] start_kernel+0xd5/0x2c5 [<00000000>] 0x0 [] 0xffffffff in-hardirq-W at: [] __lock_acquire+0x949/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock+0x35/0x42 [] scheduler_tick+0x20/0x192 [] update_process_times+0x43/0x62 [] tick_periodic+0x24/0x75 [] tick_handle_periodic+0x18/0x7a [] timer_interrupt+0xe/0x15 [] handle_IRQ_event+0x28/0x59 [] handle_level_irq+0xad/0x10b [] do_IRQ+0x93/0xd0 [] common_interrupt+0x2e/0x34 [] setup_irq+0xf2/0x20d [] time_init_hook+0x19/0x1b [] hpet_time_init+0xd/0x15 [] start_kernel+0x1d5/0x2c5 [<00000000>] 0x0 [] 0xffffffff in-softirq-W at: [] __lock_acquire+0x6f2/0x11ac [] lock_acquire+0x99/0xb2 [] _spin_lock+0x35/0x42 [] scheduler_tick+0x20/0x192 [] update_process_times+0x43/0x62 [] tick_periodic+0x24/0x75 [] tick_handle_periodic+0x18/0x7a [] timer_interrupt+0xe/0x15 [] handle_IRQ_event+0x28/0x59 [] handle_level_irq+0xad/0x10b [] do_IRQ+0x93/0xd0 [] common_interrupt+0x2e/0x34 [] do_softirq+0x4d/0x4f [] irq_exit+0x48/0x4a [] do_IRQ+0x98/0xd0 [] common_interrupt+0x2e/0x34 [] acpi_ex_system_io_space_handler+0x3f/0x45 [] acpi_ev_address_space_dispatch+0x12f/0x170 [] acpi_ex_access_region+0x1a7/0x1b9 [] acpi_ex_field_datum_io+0x111/0x198 [