From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753447AbZIAU4T (ORCPT ); Tue, 1 Sep 2009 16:56:19 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751842AbZIAU4S (ORCPT ); Tue, 1 Sep 2009 16:56:18 -0400 Received: from mx1.redhat.com ([209.132.183.28]:64069 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751774AbZIAU4R (ORCPT ); Tue, 1 Sep 2009 16:56:17 -0400 Subject: INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected for kmemleak_lock From: Eric Paris To: linux-kernel@vger.kernel.org Cc: catalin.marinas@arm.com Content-Type: text/plain Date: Tue, 01 Sep 2009 16:55:45 -0400 Message-Id: <1251838545.2158.67.camel@dhcp231-106.rdu.redhat.com> Mime-Version: 1.0 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org I wrote a multithreaded inotify syscall pounder intended to create files, destroy files, create watches, and destroy watches with the maximum number of races possible. Instead after letting it run a while I came upon this! And then my system started to crash in all sorts of fun and glorious ways (kmem_cache_alloc bugs/panics/whatever) -Eric [ 2235.913737] ====================================================== [ 2235.914084] [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ] [ 2235.914084] 2.6.31-rc8-next-20090901 #64 [ 2235.914084] ------------------------------------------------------ [ 2235.914084] syscall_thrash/2516 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: [ 2235.914084] (kthread_create_lock){+.+...}, at: [] kthread_create+0x73/0x180 [ 2235.914084] [ 2235.914084] and this task is already holding: [ 2235.914084] (kmemleak_lock){..----}, at: [] create_object+0x161/0x2e0 [ 2235.914084] which would create a new lock dependency: [ 2235.914084] (kmemleak_lock){..----} -> (kthread_create_lock){+.+...} [ 2235.914084] [ 2235.914084] but this new dependency connects a HARDIRQ-irq-safe lock: [ 2235.914084] (shost->host_lock){-.-.-.} [ 2235.914084] ... which became HARDIRQ-irq-safe at: [ 2235.914084] [] __lock_acquire+0x623/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock_irqsave+0x6a/0xc0 [ 2235.914084] [] scsi_eh_scmd_add+0x50/0xf0 [ 2235.914084] [] scsi_times_out+0x93/0xc0 [ 2235.914084] [] blk_rq_timed_out+0x25/0x90 [ 2235.914084] [] blk_abort_request+0x34/0x60 [ 2235.914084] [] ata_qc_schedule_eh+0x59/0x90 [ 2235.914084] [] ata_qc_complete+0x1a7/0x210 [ 2235.914084] [] ata_hsm_qc_complete+0xe5/0x180 [ 2235.914084] [] ata_sff_hsm_move+0x1d9/0x730 [ 2235.914084] [] ata_sff_host_intr+0xea/0x1b0 [ 2235.914084] [] ata_sff_interrupt+0xba/0x100 [ 2235.914084] [] handle_IRQ_event+0x70/0x200 [ 2235.914084] [] handle_edge_irq+0xf0/0x1e0 [ 2235.914084] [] handle_irq+0x55/0xc0 [ 2235.914084] [] do_IRQ+0x7a/0x100 [ 2235.914084] [] ret_from_intr+0x0/0x16 [ 2235.914084] [ 2235.914084] to a HARDIRQ-irq-unsafe lock: [ 2235.914084] (kthread_create_lock){+.+...} [ 2235.914084] ... which became HARDIRQ-irq-unsafe at: [ 2235.914084] ... [] __lock_acquire+0x5c0/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock+0x4b/0xa0 [ 2235.914084] [] kthread_create+0x73/0x180 [ 2235.914084] [] migration_call+0x255/0x650 [ 2235.914084] [] migration_init+0x33/0x80 [ 2235.914084] [] do_one_initcall+0x40/0x1b0 [ 2235.914084] [] kernel_init+0xec/0x2e0 [ 2235.914084] [] child_rip+0xa/0x20 [ 2235.914084] [ 2235.914084] other info that might help us debug this: [ 2235.914084] [ 2235.914084] 1 lock held by syscall_thrash/2516: [ 2235.914084] #0: (kmemleak_lock){..----}, at: [] create_object+0x161/0x2e0 [ 2235.914084] [ 2235.914084] the dependencies between HARDIRQ-irq-safe lock and the holding lock: [ 2235.914084] -> (shost->host_lock){-.-.-.} ops: 31846 { [ 2235.914084] IN-HARDIRQ-W at: [ 2235.914084] [] __lock_acquire+0x623/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock_irqsave+0x6a/0xc0 [ 2235.914084] [] scsi_eh_scmd_add+0x50/0xf0 [ 2235.914084] [] scsi_times_out+0x93/0xc0 [ 2235.914084] [] blk_rq_timed_out+0x25/0x90 [ 2235.914084] [] blk_abort_request+0x34/0x60 [ 2235.914084] [] ata_qc_schedule_eh+0x59/0x90 [ 2235.914084] [] ata_qc_complete+0x1a7/0x210 [ 2235.914084] [] ata_hsm_qc_complete+0xe5/0x180 [ 2235.914084] [] ata_sff_hsm_move+0x1d9/0x730 [ 2235.914084] [] ata_sff_host_intr+0xea/0x1b0 [ 2235.914084] [] ata_sff_interrupt+0xba/0x100 [ 2235.914084] [] handle_IRQ_event+0x70/0x200 [ 2235.914084] [] handle_edge_irq+0xf0/0x1e0 [ 2235.914084] [] handle_irq+0x55/0xc0 [ 2235.914084] [] do_IRQ+0x7a/0x100 [ 2235.914084] [] ret_from_intr+0x0/0x16 [ 2235.914084] IN-SOFTIRQ-W at: [ 2235.914084] [] __lock_acquire+0x533/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock_irqsave+0x6a/0xc0 [ 2235.914084] [] scsi_device_unbusy+0x45/0x100 [ 2235.914084] [] scsi_finish_command+0x40/0x140 [ 2235.914084] [] scsi_softirq_done+0x15d/0x190 [ 2235.914084] [] blk_done_softirq+0x95/0xc0 [ 2235.914084] [] __do_softirq+0xf4/0x280 [ 2235.914084] [] call_softirq+0x1c/0x30 [ 2235.914084] [] do_softirq+0xa6/0xf0 [ 2235.914084] [] irq_exit+0xb7/0xd0 [ 2235.914084] [] do_IRQ+0x83/0x100 [ 2235.914084] [] ret_from_intr+0x0/0x16 [ 2235.914084] IN-RECLAIM_FS-W at: [ 2235.914084] [] __lock_acquire+0x4b8/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock_irqsave+0x6a/0xc0 [ 2235.914084] [] scsi_device_unbusy+0x45/0x100 [ 2235.914084] [] scsi_finish_command+0x40/0x140 [ 2235.914084] [] scsi_softirq_done+0x15d/0x190 [ 2235.914084] [] blk_done_softirq+0x95/0xc0 [ 2235.914084] [] __do_softirq+0xf4/0x280 [ 2235.914084] [] call_softirq+0x1c/0x30 [ 2235.914084] [] do_softirq+0xa6/0xf0 [ 2235.914084] [] irq_exit+0xb7/0xd0 [ 2235.914084] [] do_IRQ+0x83/0x100 [ 2235.914084] [] ret_from_intr+0x0/0x16 [ 2235.914084] INITIAL USE at: [ 2235.914084] [] __lock_acquire+0x2f0/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock_irqsave+0x6a/0xc0 [ 2235.914084] [] scsi_scan_host+0x11a/0x280 [ 2235.914084] [] mptspi_probe+0x3ea/0x450 [mptspi] [ 2235.914084] [] local_pci_probe+0x25/0x40 [ 2235.914084] [] pci_device_probe+0x121/0x130 [ 2235.914084] [] driver_probe_device+0xab/0x290 [ 2235.914084] [] __driver_attach+0xa6/0xb0 [ 2235.914084] [] bus_for_each_dev+0x6d/0xb0 [ 2235.914084] [] driver_attach+0x2f/0x50 [ 2235.914084] [] bus_add_driver+0x235/0x360 [ 2235.914084] [] driver_register+0x79/0x180 [ 2235.914084] [] __pci_register_driver+0x76/0x100 [ 2235.914084] [] 0xffffffffa00be0d8 [ 2235.914084] [] do_one_initcall+0x40/0x1b0 [ 2235.914084] [] sys_init_module+0x108/0x260 [ 2235.914084] [] system_call_fastpath+0x16/0x1b [ 2235.914084] } [ 2235.914084] ... key at: [] __key.30665+0x0/0x8 [ 2235.914084] ... acquired at: [ 2235.914084] [] validate_chain+0xcec/0x13a0 [ 2235.914084] [] __lock_acquire+0x3a7/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _write_lock_irqsave+0x6a/0xc0 [ 2235.914084] [] __delete_object+0x29/0xf0 [ 2235.914084] [] delete_object_full+0x2f/0x60 [ 2235.914084] [] kmemleak_free+0x4d/0xc0 [ 2235.914084] [] kfree+0x180/0x220 [ 2235.914084] [] mptspi_target_destroy+0x2c/0x60 [mptspi] [ 2235.914084] [] scsi_target_destroy+0x79/0xe0 [ 2235.914084] [] scsi_target_reap+0xeb/0x100 [ 2235.914084] [] __scsi_scan_target+0xb6/0x740 [ 2235.914084] [] scsi_scan_channel+0x99/0xb0 [ 2235.914084] [] scsi_scan_host_selected+0xef/0x1a0 [ 2235.914084] [] do_scsi_scan_host+0xa2/0xb0 [ 2235.914084] [] do_scan_async+0x2c/0x1a0 [ 2235.914084] [] kthread+0xac/0xc0 [ 2235.914084] [] child_rip+0xa/0x20 [ 2235.914084] [ 2235.914084] -> (kmemleak_lock){..----} ops: 55874890 { [ 2235.914084] IN-SOFTIRQ-W at: [ 2235.914084] [] __lock_acquire+0x533/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _write_lock_irqsave+0x6a/0xc0 [ 2235.914084] [] __delete_object+0x29/0xf0 [ 2235.914084] [] delete_object_full+0x2f/0x60 [ 2235.914084] [] kmemleak_free+0x4d/0xc0 [ 2235.914084] [] kfree+0x180/0x220 [ 2235.914084] [] selinux_cred_free+0x2b/0x50 [ 2235.914084] [] security_cred_free+0x24/0x40 [ 2235.914084] [] put_cred_rcu+0x30/0xb0 [ 2235.914084] [] __rcu_process_callbacks+0x18a/0x320 [ 2235.914084] [] rcu_process_callbacks+0x47/0x90 [ 2235.914084] [] __do_softirq+0xf4/0x280 [ 2235.914084] [] call_softirq+0x1c/0x30 [ 2235.914084] [] do_softirq+0xa6/0xf0 [ 2235.914084] [] irq_exit+0xb7/0xd0 [ 2235.914084] [] smp_apic_timer_interrupt+0x7d/0xd0 [ 2235.914084] [] apic_timer_interrupt+0x13/0x20 [ 2235.914084] IN-SOFTIRQ-R at: [ 2235.914084] [] __lock_acquire+0x533/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _read_lock_irqsave+0x6d/0xc0 [ 2235.914084] [] find_and_get_object+0x5e/0x120 [ 2235.914084] [] delete_object_full+0x1f/0x60 [ 2235.914084] [] kmemleak_free+0x4d/0xc0 [ 2235.914084] [] kfree+0x180/0x220 [ 2235.914084] [] selinux_cred_free+0x2b/0x50 [ 2235.914084] [] security_cred_free+0x24/0x40 [ 2235.914084] [] put_cred_rcu+0x30/0xb0 [ 2235.914084] [] __rcu_process_callbacks+0x18a/0x320 [ 2235.914084] [] rcu_process_callbacks+0x47/0x90 [ 2235.914084] [] __do_softirq+0xf4/0x280 [ 2235.914084] [] call_softirq+0x1c/0x30 [ 2235.914084] [] do_softirq+0xa6/0xf0 [ 2235.914084] [] irq_exit+0xb7/0xd0 [ 2235.914084] [] smp_apic_timer_interrupt+0x7d/0xd0 [ 2235.914084] [] apic_timer_interrupt+0x13/0x20 [ 2235.914084] IN-RECLAIM_FS-W at: [ 2235.914084] [] __lock_acquire+0x4b8/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _write_lock_irqsave+0x6a/0xc0 [ 2235.914084] [] __delete_object+0x29/0xf0 [ 2235.914084] [] delete_object_full+0x2f/0x60 [ 2235.914084] [] kmemleak_free+0x4d/0xc0 [ 2235.914084] [] kmem_cache_free+0x14c/0x1f0 [ 2235.914084] [] file_free_rcu+0x46/0x70 [ 2235.914084] [] __rcu_process_callbacks+0x18a/0x320 [ 2235.914084] [] rcu_process_callbacks+0x47/0x90 [ 2235.914084] [] __do_softirq+0xf4/0x280 [ 2235.914084] [] call_softirq+0x1c/0x30 [ 2235.914084] [] do_softirq+0xa6/0xf0 [ 2235.914084] [] irq_exit+0xb7/0xd0 [ 2235.914084] [] smp_apic_timer_interrupt+0x7d/0xd0 [ 2235.914084] [] apic_timer_interrupt+0x13/0x20 [ 2235.914084] IN-RECLAIM_FS-R at: [ 2235.914084] [] __lock_acquire+0x4b8/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _read_lock_irqsave+0x6d/0xc0 [ 2235.914084] [] find_and_get_object+0x5e/0x120 [ 2235.914084] [] delete_object_full+0x1f/0x60 [ 2235.914084] [] kmemleak_free+0x4d/0xc0 [ 2235.914084] [] kmem_cache_free+0x14c/0x1f0 [ 2235.914084] [] file_free_rcu+0x46/0x70 [ 2235.914084] [] __rcu_process_callbacks+0x18a/0x320 [ 2235.914084] [] rcu_process_callbacks+0x47/0x90 [ 2235.914084] [] __do_softirq+0xf4/0x280 [ 2235.914084] [] call_softirq+0x1c/0x30 [ 2235.914084] [] do_softirq+0xa6/0xf0 [ 2235.914084] [] irq_exit+0xb7/0xd0 [ 2235.914084] [] smp_apic_timer_interrupt+0x7d/0xd0 [ 2235.914084] [] apic_timer_interrupt+0x13/0x20 [ 2235.914084] INITIAL USE at: [ 2235.914084] [] __lock_acquire+0x2f0/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _read_lock_irqsave+0x6d/0xc0 [ 2235.914084] [] find_and_get_object+0x5e/0x120 [ 2235.914084] [] kmemleak_free_part+0x68/0x160 [ 2235.914084] [] kmemleak_init+0x279/0x300 [ 2235.914084] [] start_kernel+0x2de/0x4a0 [ 2235.914084] [] x86_64_start_reservations+0xc1/0x100 [ 2235.914084] [] x86_64_start_kernel+0x108/0x150 [ 2235.914084] } [ 2235.914084] ... key at: [] kmemleak_lock+0x18/0x40 [ 2235.914084] ... acquired at: [ 2235.914084] [] check_irq_usage+0x6b/0x100 [ 2235.914084] [] validate_chain+0x8e5/0x13a0 [ 2235.914084] [] __lock_acquire+0x3a7/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock+0x4b/0xa0 [ 2235.914084] [] kthread_create+0x73/0x180 [ 2235.914084] [] kmemleak_cleanup+0x2c/0x70 [ 2235.914084] [] kmemleak_disable+0x6a/0x80 [ 2235.914084] [] create_object+0x1c1/0x2e0 [ 2235.914084] [] kmemleak_alloc+0x6e/0xf0 [ 2235.914084] [] kmem_cache_alloc+0x153/0x200 [ 2235.914084] [] sys_inotify_add_watch+0x1dc/0x3a0 [ 2235.914084] [] system_call_fastpath+0x16/0x1b [ 2235.914084] [ 2235.914084] [ 2235.914084] the dependencies between the lock to be acquired and HARDIRQ-irq-unsafe lock: [ 2235.914084] -> (kthread_create_lock){+.+...} ops: 167 { [ 2235.914084] HARDIRQ-ON-W at: [ 2235.914084] [] __lock_acquire+0x5c0/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock+0x4b/0xa0 [ 2235.914084] [] kthread_create+0x73/0x180 [ 2235.914084] [] migration_call+0x255/0x650 [ 2235.914084] [] migration_init+0x33/0x80 [ 2235.914084] [] do_one_initcall+0x40/0x1b0 [ 2235.914084] [] kernel_init+0xec/0x2e0 [ 2235.914084] [] child_rip+0xa/0x20 [ 2235.914084] SOFTIRQ-ON-W at: [ 2235.914084] [] __lock_acquire+0x5e7/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock+0x4b/0xa0 [ 2235.914084] [] kthread_create+0x73/0x180 [ 2235.914084] [] migration_call+0x255/0x650 [ 2235.914084] [] migration_init+0x33/0x80 [ 2235.914084] [] do_one_initcall+0x40/0x1b0 [ 2235.914084] [] kernel_init+0xec/0x2e0 [ 2235.914084] [] child_rip+0xa/0x20 [ 2235.914084] INITIAL USE at: [ 2235.914084] [] __lock_acquire+0x2f0/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock+0x4b/0xa0 [ 2235.914084] [] kthread_create+0x73/0x180 [ 2235.914084] [] migration_call+0x255/0x650 [ 2235.914084] [] migration_init+0x33/0x80 [ 2235.914084] [] do_one_initcall+0x40/0x1b0 [ 2235.914084] [] kernel_init+0xec/0x2e0 [ 2235.914084] [] child_rip+0xa/0x20 [ 2235.914084] } [ 2235.914084] ... key at: [] kthread_create_lock+0x18/0x40 [ 2235.914084] ... acquired at: [ 2235.914084] [] check_irq_usage+0x6b/0x100 [ 2235.914084] [] validate_chain+0x8e5/0x13a0 [ 2235.914084] [] __lock_acquire+0x3a7/0x6d0 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] _spin_lock+0x4b/0xa0 [ 2235.914084] [] kthread_create+0x73/0x180 [ 2235.914084] [] kmemleak_cleanup+0x2c/0x70 [ 2235.914084] [] kmemleak_disable+0x6a/0x80 [ 2235.914084] [] create_object+0x1c1/0x2e0 [ 2235.914084] [] kmemleak_alloc+0x6e/0xf0 [ 2235.914084] [] kmem_cache_alloc+0x153/0x200 [ 2235.914084] [] sys_inotify_add_watch+0x1dc/0x3a0 [ 2235.914084] [] system_call_fastpath+0x16/0x1b [ 2235.914084] [ 2235.914084] [ 2235.914084] stack backtrace: [ 2235.914084] Pid: 2516, comm: syscall_thrash Not tainted 2.6.31-rc8-next-20090901 #64 [ 2235.914084] Call Trace: [ 2235.914084] [] check_usage+0x472/0x580 [ 2235.914084] [] check_irq_usage+0x6b/0x100 [ 2235.914084] [] validate_chain+0x8e5/0x13a0 [ 2235.914084] [] ? vprintk+0x1b9/0x5a0 [ 2235.914084] [] __lock_acquire+0x3a7/0x6d0 [ 2235.914084] [] ? kthread_create+0x73/0x180 [ 2235.914084] [] ? kthread_create+0x73/0x180 [ 2235.914084] [] lock_acquire+0xc0/0x170 [ 2235.914084] [] ? kthread_create+0x73/0x180 [ 2235.914084] [] _spin_lock+0x4b/0xa0 [ 2235.914084] [] ? kthread_create+0x73/0x180 [ 2235.914084] [] ? __init_waitqueue_head+0x4d/0x80 [ 2235.914084] [] kthread_create+0x73/0x180 [ 2235.914084] [] ? kmemleak_cleanup_thread+0x0/0x100 [ 2235.914084] [] ? dump_trace+0x13d/0x320 [ 2235.914084] [] ? show_trace_log_lvl+0x64/0x90 [ 2235.914084] [] ? show_trace+0x23/0x40 [ 2235.914084] [] kmemleak_cleanup+0x2c/0x70 [ 2235.914084] [] kmemleak_disable+0x6a/0x80 [ 2235.914084] [] create_object+0x1c1/0x2e0 [ 2235.914084] [] ? mark_shadow+0x61/0xf0 [ 2235.914084] [] kmemleak_alloc+0x6e/0xf0 [ 2235.914084] [] kmem_cache_alloc+0x153/0x200 [ 2235.914084] [] sys_inotify_add_watch+0x1dc/0x3a0 [ 2235.914084] [] ? trace_hardirqs_on_caller+0x14d/0x1e0 [ 2235.914084] [] system_call_fastpath+0x16/0x1b