From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756026Ab2GXUgX (ORCPT ); Tue, 24 Jul 2012 16:36:23 -0400 Received: from mx1.redhat.com ([209.132.183.28]:64364 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755294Ab2GXUgW (ORCPT ); Tue, 24 Jul 2012 16:36:22 -0400 Date: Tue, 24 Jul 2012 16:36:13 -0400 From: Dave Jones To: Linux Kernel Cc: Thomas Gleixner Subject: lockdep trace from posix timers Message-ID: <20120724203613.GA9637@redhat.com> Mail-Followup-To: Dave Jones , Linux Kernel , Thomas Gleixner MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Linus tree as of 5fecc9d8f59e765c2a48379dd7c6f5cf88c7d75a Dave ====================================================== [ INFO: HARDIRQ-safe -> HARDIRQ-unsafe lock order detected ] 3.5.0+ #122 Not tainted ------------------------------------------------------ trinity-child2/5327 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: blocked: (tasklist_lock){.+.+..}, instance: ffffffff81c05098, at: [] posix_cpu_timer_del+0x2b/0xe0 and this task is already holding: blocked: (&(&new_timer->it_lock)->rlock){-.-...}, instance: ffff880143bce170, at: [] __lock_timer+0x89/0x1f0 which would create a new lock dependency: (&(&new_timer->it_lock)->rlock){-.-...} -> (tasklist_lock){.+.+..} but this new dependency connects a HARDIRQ-irq-safe lock: (&(&new_timer->it_lock)->rlock){-.-...} ... which became HARDIRQ-irq-safe at: [] __lock_acquire+0x7e1/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_spin_lock_irqsave+0x7d/0xd0 [] posix_timer_fn+0x37/0xe0 [] __run_hrtimer+0x94/0x4c0 [] hrtimer_interrupt+0xf7/0x230 [] smp_apic_timer_interrupt+0x69/0x99 [] apic_timer_interrupt+0x6f/0x80 [] __generic_file_aio_write+0x239/0x450 [] generic_file_aio_write+0x73/0xe0 [] ext4_file_write+0xc2/0x280 [] do_sync_write+0xe6/0x120 [] vfs_write+0xaf/0x190 [] sys_write+0x4d/0x90 [] system_call_fastpath+0x1a/0x1f to a HARDIRQ-irq-unsafe lock: (&(&p->alloc_lock)->rlock){+.+...} ... which became HARDIRQ-irq-unsafe at: ... [] __lock_acquire+0x5e7/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_spin_lock+0x46/0x80 [] set_task_comm+0x32/0x180 [] kthreadd+0x38/0x2e0 [] kernel_thread_helper+0x4/0x10 other info that might help us debug this: Chain exists of: &(&new_timer->it_lock)->rlock --> tasklist_lock --> &(&p->alloc_lock)->rlock Possible interrupt unsafe locking scenario: CPU0 CPU1 ---- ---- lock(&(&p->alloc_lock)->rlock); local_irq_disable(); lock(&(&new_timer->it_lock)->rlock); lock(tasklist_lock); lock(&(&new_timer->it_lock)->rlock); *** DEADLOCK *** 1 lock on stack by trinity-child2/5327: #0: blocked: (&(&new_timer->it_lock)->rlock){-.-...}, instance: ffff880143bce170, at: [] __lock_timer+0x89/0x1f0 the dependencies between HARDIRQ-irq-safe lock and the holding lock: -> (&(&new_timer->it_lock)->rlock){-.-...} ops: 584 { IN-HARDIRQ-W at: [] __lock_acquire+0x7e1/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_spin_lock_irqsave+0x7d/0xd0 [] posix_timer_fn+0x37/0xe0 [] __run_hrtimer+0x94/0x4c0 [] hrtimer_interrupt+0xf7/0x230 [] smp_apic_timer_interrupt+0x69/0x99 [] apic_timer_interrupt+0x6f/0x80 [] __generic_file_aio_write+0x239/0x450 [] generic_file_aio_write+0x73/0xe0 [] ext4_file_write+0xc2/0x280 [] do_sync_write+0xe6/0x120 [] vfs_write+0xaf/0x190 [] sys_write+0x4d/0x90 [] system_call_fastpath+0x1a/0x1f IN-SOFTIRQ-W at: [] __lock_acquire+0x5ae/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_spin_lock_irqsave+0x7d/0xd0 [] posix_timer_fn+0x37/0xe0 [] __run_hrtimer+0x94/0x4c0 [] hrtimer_interrupt+0xf7/0x230 [] __hrtimer_peek_ahead_timers.part.27+0x2b/0x30 [] hrtimer_peek_ahead_timers+0x49/0xa0 [] run_hrtimer_softirq+0x31/0x40 [] __do_softirq+0xf0/0x400 [] run_ksoftirqd+0x13c/0x230 [] kthread+0xb7/0xc0 [] kernel_thread_helper+0x4/0x10 INITIAL USE at: [] __lock_acquire+0x306/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_spin_lock_irqsave+0x7d/0xd0 [] __lock_timer+0x89/0x1f0 [] sys_timer_delete+0x44/0x100 [] system_call_fastpath+0x1a/0x1f } ... key at: [] __key.29841+0x0/0x8 ... acquired at: [] check_irq_usage+0x5b/0xe0 [] __lock_acquire+0xd8a/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_read_lock+0x49/0x80 [] posix_cpu_timer_del+0x2b/0xe0 [] sys_timer_delete+0x26/0x100 [] system_call_fastpath+0x1a/0x1f the dependencies between the lock to be acquired and HARDIRQ-irq-unsafe lock: -> (&(&p->alloc_lock)->rlock){+.+...} ops: 1189942 { HARDIRQ-ON-W at: [] __lock_acquire+0x5e7/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_spin_lock+0x46/0x80 [] set_task_comm+0x32/0x180 [] kthreadd+0x38/0x2e0 [] kernel_thread_helper+0x4/0x10 SOFTIRQ-ON-W at: [] __lock_acquire+0x61c/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_spin_lock+0x46/0x80 [] set_task_comm+0x32/0x180 [] kthreadd+0x38/0x2e0 [] kernel_thread_helper+0x4/0x10 INITIAL USE at: [] __lock_acquire+0x306/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_spin_lock+0x46/0x80 [] set_task_comm+0x32/0x180 [] kthreadd+0x38/0x2e0 [] kernel_thread_helper+0x4/0x10 } ... key at: [] __key.45832+0x0/0x8 ... acquired at: [] lock_acquire+0xad/0x220 [] _raw_spin_lock+0x46/0x80 [] keyctl_session_to_parent+0xde/0x490 [] sys_keyctl+0x6d/0x1a0 [] system_call_fastpath+0x1a/0x1f -> (tasklist_lock){.+.+..} ops: 35423 { HARDIRQ-ON-R at: [] __lock_acquire+0x4ce/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_read_lock+0x49/0x80 [] do_wait+0xb2/0x360 [] sys_wait4+0x75/0xf0 [] wait_for_helper+0x82/0xb0 [] kernel_thread_helper+0x4/0x10 SOFTIRQ-ON-R at: [] __lock_acquire+0x61c/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_read_lock+0x49/0x80 [] do_wait+0xb2/0x360 [] sys_wait4+0x75/0xf0 [] wait_for_helper+0x82/0xb0 [] kernel_thread_helper+0x4/0x10 INITIAL USE at: [] __lock_acquire+0x306/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_write_lock_irq+0x5c/0xa0 [] copy_process.part.22+0x1051/0x1750 [] do_fork+0x140/0x4e0 [] kernel_thread+0x76/0x80 [] rest_init+0x26/0x154 [] start_kernel+0x3f8/0x405 [] x86_64_start_reservations+0x131/0x135 [] x86_64_start_kernel+0x148/0x157 } ... key at: [] tasklist_lock+0x18/0x80 ... acquired at: [] check_irq_usage+0x5b/0xe0 [] __lock_acquire+0xd8a/0x1ae0 [] lock_acquire+0xad/0x220 [] _raw_read_lock+0x49/0x80 [] posix_cpu_timer_del+0x2b/0xe0 [] sys_timer_delete+0x26/0x100 [] system_call_fastpath+0x1a/0x1f stack backtrace: Pid: 5327, comm: trinity-child2 Not tainted 3.5.0+ #122 Call Trace: [] check_usage+0x4e4/0x500 [] ? native_sched_clock+0x19/0x80 [] ? trace_hardirqs_off_caller+0x28/0xd0 [] ? native_sched_clock+0x19/0x80 [] check_irq_usage+0x5b/0xe0 [] __lock_acquire+0xd8a/0x1ae0 [] ? __lock_acquire+0x306/0x1ae0 [] ? trace_hardirqs_off_caller+0x28/0xd0 [] ? lock_release_non_nested+0x175/0x320 [] lock_acquire+0xad/0x220 [] ? posix_cpu_timer_del+0x2b/0xe0 [] _raw_read_lock+0x49/0x80 [] ? posix_cpu_timer_del+0x2b/0xe0 [] ? __lock_timer+0xd5/0x1f0 [] posix_cpu_timer_del+0x2b/0xe0 [] sys_timer_delete+0x26/0x100 [] system_call_fastpath+0x1a/0x1f