Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753008AbZGWIho (ORCPT ); Thu, 23 Jul 2009 04:37:44 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751516AbZGWIhn (ORCPT ); Thu, 23 Jul 2009 04:37:43 -0400 Received: from mx2.redhat.com ([66.187.237.31]:42212 "EHLO mx2.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751269AbZGWIhh (ORCPT ); Thu, 23 Jul 2009 04:37:37 -0400 Date: Thu, 23 Jul 2009 10:37:17 +0200 From: John Kacur To: linux-rt-users@vger.kernel.org, tglx@linutronix.de Cc: linux-kernel@vger.kernel.org, williams@redhat.com, peterz@infradead.org Subject: Re: irq lock inversion w/2.6.31-rc3-rtx Message-ID: <20090723083717.GA5140@tycho.redhat.com> MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="Nq2Wo0NMKNjxTN9z" Content-Disposition: inline User-Agent: Mutt/1.5.18 (2008-05-17) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 115499 Lines: 1925 --Nq2Wo0NMKNjxTN9z Content-Type: text/plain; charset=us-ascii Content-Disposition: inline I have a better traceback. (without the chars cut off at the end of a line) --Nq2Wo0NMKNjxTN9z Content-Type: text/plain; charset=us-ascii Content-Disposition: attachment; filename="lockinversion2.txt" [jkacur@alfred ~]$ su --login Password: [root@alfred ~]# minicom -c on Welcome to minicom 2.3 OPTIONS: I18n Compiled on Feb 26 2009, 00:28:27. Port /dev/ttyUSB0 Press CTRL-A Z for help on special keys metacity used greatest stack depth: 1336 bytes left fuse init (API version 7.12) ========================================================= [ INFO: possible irq lock inversion dependency detected ] 2.6.31-rc3-rt1 #1 --------------------------------------------------------- canberra-gtk-pl/3583 just changed the state of lock: ((raw_spinlock_t *)(&lock->wait_lock)){+...-.}, at: [] do_futex+0x68e/0x961 but this lock was taken by another, HARDIRQ-safe lock in the past: (&irq_desc_lock_class){-.....} and interrupts could create inverse lock ordering between them. other info that might help us debug this: 1 lock held by canberra-gtk-pl/3583: #0: (&futex_queues[i].lock){+.+...}, at: [] do_futex+0x5b7/0x961 the first lock's dependencies: -> ((raw_spinlock_t *)(&lock->wait_lock)){+...-.} ops: 15793743 { HARDIRQ-ON-W at: [] __lock_acquire+0x2fd/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] do_futex+0x68e/0x961 [] sys_futex+0x11d/0x14f [] system_call_fastpath+0x16/0x1b [] 0xffffffffffffffff IN-RECLAIM_FS-W at: [] __lock_acquire+0x361/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] rt_spin_lock_slowlock+0x42/0x2aa [] rt_spin_lock_fastlock+0x67/0x82 [] rt_spin_lock+0x2e/0x68 [] prepare_to_wait+0x2d/0x85 [] kswapd+0xfb/0x686 [] kthread+0xa6/0xae [] child_rip+0xa/0x20 [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] rt_spin_lock_slowlock+0x42/0x2aa [] rt_spin_lock_fastlock+0x67/0x82 [] rt_spin_lock+0x2e/0x68 [] free_pages_bulk+0x3b/0xda [] free_hot_cold_page+0x1eb/0x228 [] free_hot_page+0x1e/0x34 [] __free_pages+0x39/0x56 [] __free_pages_bootmem+0x91/0xa7 [] free_all_bootmem_core+0x102/0x1e5 [] free_all_bootmem_node+0x23/0x39 [] numa_free_all_bootmem+0x55/0x9f [] mem_init+0x38/0x187 [] start_kernel+0x20b/0x421 [] x86_64_start_reservations+0xb9/0xd4 [] x86_64_start_kernel+0xd0/0xeb [] 0xffffffffffffffff } ... key at: [] __key.17785+0x0/0x8 -> ((raw_spinlock_t *)(&p->pi_lock)){......} ops: 80807 { INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] __sched_setscheduler+0x17a/0x2a3 [] sched_setscheduler_nocheck+0x1e/0x34 [] kthread_create+0xf7/0x145 [] migration_call+0x55/0x4f7 [] migration_init+0x35/0x82 [] do_one_initcall+0x65/0x153 [] kernel_init+0x8e/0x289 [] child_rip+0xa/0x20 [] 0xffffffffffffffff } ... key at: [] __key.42870+0x0/0x8 -> ((raw_spinlock_t *)(&rq->lock)){-...-.} ops: 1242223 { IN-HARDIRQ-W at: [] __lock_acquire+0x282/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] scheduler_tick+0x55/0x280 [] update_process_times+0x59/0x80 [] tick_periodic+0x76/0x96 [] tick_handle_periodic+0x2e/0x94 [] timer_interrupt+0x2d/0x48 [] handle_irq_action+0x88/0xab [] handle_IRQ_event+0x90/0x189 [] handle_level_irq+0x8f/0x106 [] handle_irq+0x98/0xb7 [] do_IRQ+0x71/0xe6 [] ret_from_intr+0x0/0xf [] 0xffffffffffffffff IN-RECLAIM_FS-W at: [] __lock_acquire+0x361/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] task_rq_lock+0x51/0x9b [] set_cpus_allowed_ptr+0x2e/0x12e [] kswapd+0x8f/0x686 [] kthread+0xa6/0xae [] child_rip+0xa/0x20 [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] rq_attach_root+0x29/0xf6 [] sched_init+0x2cf/0x4b3 [] start_kernel+0x21a/0x421 [] x86_64_start_reservations+0xb9/0xd4 [] x86_64_start_kernel+0xd0/0xeb [] 0xffffffffffffffff } ... key at: [] __key.50609+0x0/0x8 -> ((raw_spinlock_t *)(&vec->lock)){-.....} ops: 608654 { IN-HARDIRQ-W at: [] __lock_acquire+0x282/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] cpupri_set+0x88/0x153 [] enqueue_task_rt+0x11a/0x292 [] enqueue_task+0x6a/0x8c [] activate_task+0x37/0x56 [] try_to_wake_up+0x191/0x2f3 [] wake_up_process+0x25/0x3b [] wakeup_softirqd+0x56/0x72 [] raise_softirq_irqoff+0x2c/0x42 [] raise_softirq+0x2c/0x62 [] run_local_timers+0x26/0x41 [] update_process_times+0x3f/0x80 [] tick_periodic+0x76/0x96 [] tick_handle_periodic+0x2e/0x94 [] smp_apic_timer_interrupt+0x94/0xbe [] apic_timer_interrupt+0x13/0x20 [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] cpupri_set+0xdd/0x153 [] rq_online_rt+0x79/0x94 [] set_rq_online+0x5b/0x7f [] rq_attach_root+0xb4/0xf6 [] sched_init+0x2cf/0x4b3 [] start_kernel+0x21a/0x421 [] x86_64_start_reservations+0xb9/0xd4 [] x86_64_start_kernel+0xd0/0xeb [] 0xffffffffffffffff } ... key at: [] __key.15528+0x0/0x10 ... acquired at: [] __lock_acquire+0xab4/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] cpupri_set+0xdd/0x153 [] rq_online_rt+0x79/0x94 [] set_rq_online+0x5b/0x7f [] rq_attach_root+0xb4/0xf6 [] sched_init+0x2cf/0x4b3 [] start_kernel+0x21a/0x421 [] x86_64_start_reservations+0xb9/0xd4 [] x86_64_start_kernel+0xd0/0xeb [] 0xffffffffffffffff -> ((raw_spinlock_t *)(&rt_b->rt_runtime_lock)){-.....} ops: 217 { IN-HARDIRQ-W at: [] __lock_acquire+0x282/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] enqueue_task_rt+0x1ae/0x292 [] enqueue_task+0x6a/0x8c [] activate_task+0x37/0x56 [] try_to_wake_up+0x191/0x2f3 [] wake_up_process+0x25/0x3b [] wakeup_softirqd+0x56/0x72 [] raise_softirq_irqoff+0x2c/0x42 [] raise_softirq+0x2c/0x62 [] run_local_timers+0x26/0x41 [] update_process_times+0x3f/0x80 [] tick_sched_timer+0x82/0xc2 [] __run_hrtimer+0x89/0xd5 [] hrtimer_interrupt+0x127/0x1a9 [] smp_apic_timer_interrupt+0x94/0xbe [] apic_timer_interrupt+0x13/0x20 [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] enqueue_task_rt+0x1ae/0x292 [] enqueue_task+0x6a/0x8c [] activate_task+0x37/0x56 [] try_to_wake_up+0x191/0x2f3 [] wake_up_process+0x25/0x3b [] migration_call+0xee/0x4f7 [] migration_init+0x57/0x82 [] do_one_initcall+0x65/0x153 [] kernel_init+0x8e/0x289 [] child_rip+0xa/0x20 [] 0xffffffffffffffff } ... key at: [] __key.41271+0x0/0x8 -> ((raw_spinlock_t *)(&cpu_base->lock)){-.....} ops: 474372 { IN-HARDIRQ-W at: [] __lock_acquire+0x282/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] hrtimer_run_queues+0x112/0x18f [] run_local_timers+0x1c/0x41 [] update_process_times+0x3f/0x80 [] tick_periodic+0x76/0x96 [] tick_handle_periodic+0x2e/0x94 [] smp_apic_timer_interrupt+0x94/0xbe [] apic_timer_interrupt+0x13/0x20 [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] lock_hrtimer_base+0x34/0x72 [] __hrtimer_start_range_ns+0x3b/0x21f [] enqueue_task_rt+0x1fd/0x292 [] enqueue_task+0x6a/0x8c [] activate_task+0x37/0x56 [] try_to_wake_up+0x191/0x2f3 [] wake_up_process+0x25/0x3b [] migration_call+0xee/0x4f7 [] migration_init+0x57/0x82 [] do_one_initcall+0x65/0x153 [] kernel_init+0x8e/0x289 [] child_rip+0xa/0x20 [] 0xffffffffffffffff } ... key at: [] __key.20973+0x0/0x8 ... acquired at: [] __lock_acquire+0xab4/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] lock_hrtimer_base+0x34/0x72 [] __hrtimer_start_range_ns+0x3b/0x21f [] enqueue_task_rt+0x1fd/0x292 [] enqueue_task+0x6a/0x8c [] activate_task+0x37/0x56 [] try_to_wake_up+0x191/0x2f3 [] wake_up_process+0x25/0x3b [] migration_call+0xee/0x4f7 [] migration_init+0x57/0x82 [] do_one_initcall+0x65/0x153 [] kernel_init+0x8e/0x289 [] child_rip+0xa/0x20 [] 0xffffffffffffffff -> ((raw_spinlock_t *)(&rt_rq->rt_runtime_lock)){-.....} ops: 356036 { IN-HARDIRQ-W at: [] __lock_acquire+0x282/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] update_curr_rt+0xd8/0x166 [] task_tick_rt+0x25/0xf1 [] scheduler_tick+0x131/0x280 [] update_process_times+0x59/0x80 [] tick_periodic+0x76/0x96 [] tick_handle_periodic+0x2e/0x94 [] smp_apic_timer_interrupt+0x94/0xbe [] apic_timer_interrupt+0x13/0x20 [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] update_curr_rt+0xd8/0x166 [] dequeue_task_rt+0x27/0xb4 [] dequeue_task+0xe0/0x102 [] deactivate_task+0x37/0x56 [] __schedule+0x1b8/0x8ef [] schedule+0x22/0x5c [] migration_thread+0x198/0x235 [] kthread+0xa6/0xae [] child_rip+0xa/0x20 [] 0xffffffffffffffff } ... key at: [] __key.50587+0x0/0x8 ... acquired at: [] __lock_acquire+0xab4/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] __enable_runtime+0x4b/0xa3 [] rq_online_rt+0x5d/0x94 [] set_rq_online+0x5b/0x7f [] migration_call+0x142/0x4f7 [] notifier_call_chain+0x40/0x7f [] raw_notifier_call_chain+0x22/0x38 [] _cpu_up+0xef/0x154 [] cpu_up+0x74/0x9f [] kernel_init+0xe4/0x289 [] child_rip+0xa/0x20 [] 0xffffffffffffffff ... acquired at: [] __lock_acquire+0xab4/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] enqueue_task_rt+0x1ae/0x292 [] enqueue_task+0x6a/0x8c [] activate_task+0x37/0x56 [] try_to_wake_up+0x191/0x2f3 [] wake_up_process+0x25/0x3b [] migration_call+0xee/0x4f7 [] migration_init+0x57/0x82 [] do_one_initcall+0x65/0x153 [] kernel_init+0x8e/0x289 [] child_rip+0xa/0x20 [] 0xffffffffffffffff ... acquired at: [] __lock_acquire+0xab4/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] update_curr_rt+0xd8/0x166 [] dequeue_task_rt+0x27/0xb4 [] dequeue_task+0xe0/0x102 [] deactivate_task+0x37/0x56 [] __schedule+0x1b8/0x8ef [] schedule+0x22/0x5c [] migration_thread+0x198/0x235 [] kthread+0xa6/0xae [] child_rip+0xa/0x20 [] 0xffffffffffffffff -> ((raw_spinlock_t *)(&rq->lock)/1){......} ops: 1243 { INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_nested+0x4e/0x99 [] double_rq_lock+0x5d/0xa0 [] double_lock_balance+0x40/0x62 [] push_rt_task+0xc8/0x20e [] switched_to_rt+0x32/0x84 [] check_class_changed+0x54/0x7e [] task_setprio+0x1a3/0x1d2 [] __rt_mutex_adjust_prio+0x2f/0x4a [] task_blocks_on_rt_mutex+0x12a/0x1a0 [] rt_spin_lock_slowlock+0xff/0x2aa [] rt_spin_lock_fastlock+0x67/0x82 [] rt_spin_lock+0x2e/0x68 [] _slab_irq_disable+0x4f/0x89 [] kfree+0x9d/0xeb [] release_tgcred_rcu+0x4c/0x67 [] rcu_process_callbacks+0x8c/0xb3 [] ksoftirqd+0x176/0x2bf [] kthread+0xa6/0xae [] child_rip+0xa/0x20 [] 0xffffffffffffffff } ... key at: [] __key.50609+0x1/0x8 ... acquired at: [] __lock_acquire+0xab4/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] update_curr_rt+0xd8/0x166 [] dequeue_task_rt+0x27/0xb4 [] dequeue_task+0xe0/0x102 [] deactivate_task+0x37/0x56 [] push_rt_task+0x18a/0x20e [] switched_to_rt+0x32/0x84 [] check_class_changed+0x54/0x7e [] task_setprio+0x1a3/0x1d2 [] __rt_mutex_adjust_prio+0x2f/0x4a [] task_blocks_on_rt_mutex+0x12a/0x1a0 [] rt_spin_lock_slowlock+0xff/0x2aa [] rt_spin_lock_fastlock+0x67/0x82 [] rt_spin_lock+0x2e/0x68 [] _slab_irq_disable+0x4f/0x89 [] kfree+0x9d/0xeb [] release_tgcred_rcu+0x4c/0x67 [] rcu_process_callbacks+0x8c/0xb3 [] ksoftirqd+0x176/0x2bf [] kthread+0xa6/0xae [] child_rip+0xa/0x20 [] 0xffffffffffffffff ... acquired at: [] __lock_acquire+0xab4/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] cpupri_set+0x88/0x153 [] enqueue_task_rt+0x11a/0x292 [] enqueue_task+0x6a/0x8c [] activate_task+0x37/0x56 [] push_rt_task+0x1a7/0x20e [] switched_to_rt+0x32/0x84 [] check_class_changed+0x54/0x7e [] task_setprio+0x1a3/0x1d2 [] __rt_mutex_adjust_prio+0x2f/0x4a [] task_blocks_on_rt_mutex+0x12a/0x1a0 [] rt_spin_lock_slowlock+0xff/0x2aa [] rt_spin_lock_fastlock+0x67/0x82 [] rt_spin_lock+0x2e/0x68 [] _slab_irq_disable+0x4f/0x89 [] kfree+0x9d/0xeb [] release_tgcred_rcu+0x4c/0x67 [] rcu_process_callbacks+0x8c/0xb3 [] ksoftirqd+0x176/0x2bf [] kthread+0xa6/0xae [] child_rip+0xa/0x20 [] 0xffffffffffffffff ... acquired at: [] __lock_acquire+0xab4/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_nested+0x4e/0x99 [] double_rq_lock+0x5d/0xa0 [] double_lock_balance+0x40/0x62 [] push_rt_task+0xc8/0x20e [] switched_to_rt+0x32/0x84 [] check_class_changed+0x54/0x7e [] task_setprio+0x1a3/0x1d2 [] __rt_mutex_adjust_prio+0x2f/0x4a [] task_blocks_on_rt_mutex+0x12a/0x1a0 [] rt_spin_lock_slowlock+0xff/0x2aa [] rt_spin_lock_fastlock+0x67/0x82 [] rt_spin_lock+0x2e/0x68 [] _slab_irq_disable+0x4f/0x89 [] kfree+0x9d/0xeb [] release_tgcred_rcu+0x4c/0x67 [] rcu_process_callbacks+0x8c/0xb3 [] ksoftirqd+0x176/0x2bf [] kthread+0xa6/0xae [] child_rip+0xa/0x20 [] 0xffffffffffffffff -> ((raw_spinlock_t *)(&sig->cputimer.lock)){-.....} ops: 3290 { IN-HARDIRQ-W at: [] __lock_acquire+0x282/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock+0x4b/0x94 [] account_group_exec_runtime+0x46/0x75 [] update_curr+0xd7/0xf6 [] check_preempt_wakeup+0x56/0x195 [] try_to_wake_up+0x28a/0x2f3 [] wake_up_process+0x25/0x3b [] wakeup_softirqd+0x56/0x72 [] raise_softirq_irqoff+0x2c/0x42 [] raise_softirq+0x2c/0x62 [] run_local_timers+0x26/0x41 [] update_process_times+0x3f/0x80 [] tick_sched_timer+0x82/0xc2 [] __run_hrtimer+0x89/0xd5 [] hrtimer_interrupt+0x127/0x1a9 [] smp_apic_timer_interrupt+0x94/0xbe [] apic_timer_interrupt+0x13/0x20 [] 0xffffffffffffffff INITIAL USE at: [] __lock_acquire+0x37a/0xc61 [] lock_acquire+0x10d/0x145 [] __spin_lock_irqsave+0x56/0xa4 [] thread_group_cputimer+0x3c/0xd9 [] posix_cpu_timers_exit_group+0x24/0x5e [] release_task+0xdd/0x468 [