From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932116Ab3LIDR5 (ORCPT ); Sun, 8 Dec 2013 22:17:57 -0500 Received: from aserp1040.oracle.com ([141.146.126.69]:36250 "EHLO aserp1040.oracle.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1760305Ab3LIDRy (ORCPT ); Sun, 8 Dec 2013 22:17:54 -0500 Message-ID: <52A5363A.20801@oracle.com> Date: Sun, 08 Dec 2013 22:17:14 -0500 From: Sasha Levin User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:24.0) Gecko/20100101 Thunderbird/24.1.0 MIME-Version: 1.0 To: Ingo Molnar , Peter Zijlstra , tglx@linutronix.de, john.stultz@linaro.org CC: LKML Subject: Re: sched/timekeeping: lockdep spew References: <52A50490.4080705@oracle.com> In-Reply-To: <52A50490.4080705@oracle.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit X-Source-IP: ucsinet21.oracle.com [156.151.31.93] Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On 12/08/2013 06:45 PM, Sasha Levin wrote: > Hi all, > > I've stumbled on this spew inside a KVM tools guest running latest -next kernel: > If it helps, I'm getting another similar spew (different locks): [ 554.572415] ====================================================== [ 554.572851] [ INFO: possible circular locking dependency detected ] [ 554.573956] 3.13.0-rc2-next-20131206-sasha-00005-g8be2375-dirty #4054 Not tainted [ 554.575249] ------------------------------------------------------- [ 554.576575] swapper/16/0 is trying to acquire lock: [ 554.577110] (timekeeper_seq){----..}, at: [] start_bandwidth_timer+0x27/0x60 [ 554.578804] [ 554.578804] but task is already holding lock: [ 554.579961] (&rt_b->rt_runtime_lock){-.-...}, at: [] __enqueue_rt_entity+0x229/0x290 [ 554.581701] [ 554.581701] which lock already depends on the new lock. [ 554.581701] [ 554.581701] [ 554.581701] the existing dependency chain (in reverse order) is: [ 554.581701] -> #4 (&rt_b->rt_runtime_lock){-.-...}: [ 554.581701] [] validate_chain+0x6c3/0x7b0 [ 554.581701] [] __lock_acquire+0x4ad/0x580 [ 554.581701] [] lock_acquire+0x182/0x1d0 [ 554.581701] [] _raw_spin_lock+0x40/0x80 [ 554.581701] [] __enqueue_rt_entity+0x229/0x290 [ 554.581701] [] enqueue_rt_entity+0x6b/0x80 [ 554.581701] [] enqueue_task_rt+0x36/0xb0 [ 554.581701] [] enqueue_task+0x52/0x60 [ 554.581701] [] __sched_setscheduler+0x33b/0x3f0 [ 554.581701] [] sched_setscheduler_nocheck+0x10/0x20 [ 554.581701] [] rcu_cpu_kthread_setup+0x2b/0x30 [ 554.581701] [] smpboot_thread_fn+0x1ed/0x2c0 [ 554.581701] [] kthread+0x105/0x110 [ 554.581701] [] ret_from_fork+0x7c/0xb0 [ 554.581701] -> #3 (&rq->lock){-.-.-.}: [ 554.581701] [] validate_chain+0x6c3/0x7b0 [ 554.581701] [] __lock_acquire+0x4ad/0x580 [ 554.581701] [] lock_acquire+0x182/0x1d0 [ 554.581701] [] _raw_spin_lock+0x40/0x80 [ 554.581701] [] wake_up_new_task+0x149/0x270 [ 554.581701] [] do_fork+0x1ba/0x270 [ 554.581701] [] kernel_thread+0x26/0x30 [ 554.581701] [] rest_init+0x26/0x150 [ 554.581701] [] start_kernel+0x3b9/0x3c0 [ 554.581701] [] x86_64_start_reservations+0x2a/0x2c [ 554.581701] [] x86_64_start_kernel+0x186/0x195 [ 554.581701] -> #2 (&p->pi_lock){-.-.-.}: [ 554.581701] [] validate_chain+0x6c3/0x7b0 [ 554.581701] [] __lock_acquire+0x4ad/0x580 [ 554.581701] [] lock_acquire+0x182/0x1d0 [ 554.581701] [] _raw_spin_lock_irqsave+0x91/0xd0 [ 554.581701] [] try_to_wake_up+0x39/0x2a0 [ 554.581701] [] wake_up_process+0x3f/0x50 [ 554.581701] [] start_worker+0x2a/0x40 [ 554.581701] [] create_and_start_worker+0x4d/0x90 [ 554.581701] [] init_workqueues+0x192/0x3cb [ 554.581701] [] do_one_initcall+0xca/0x1e0 [ 554.581701] [] kernel_init_freeable+0x2b4/0x354 [ 554.581701] [] kernel_init+0xe/0x130 [ 554.581701] [] ret_from_fork+0x7c/0xb0 [ 554.581701] -> #1 (&(&pool->lock)->rlock){-.-...}: [ 554.581701] [] validate_chain+0x6c3/0x7b0 [ 554.581701] [] __lock_acquire+0x4ad/0x580 [ 554.581701] [] lock_acquire+0x182/0x1d0 [ 554.581701] [] _raw_spin_lock+0x40/0x80 [ 554.581701] [] __queue_work+0x1a9/0x3f0 [ 554.581701] [] queue_work_on+0x98/0x120 [ 554.581701] [] clock_was_set_delayed+0x21/0x30 [ 554.581701] [] do_adjtimex+0x111/0x160 [ 554.581701] [] compat_sys_adjtimex+0x41/0x70 [ 554.581701] [] ia32_sysret+0x0/0x5 [ 554.581701] -> #0 (timekeeper_seq){----..}: [ 554.581701] [] check_prev_add+0x13f/0x550 [ 554.581701] [] validate_chain+0x6c3/0x7b0 [ 554.581701] [] __lock_acquire+0x4ad/0x580 [ 554.581701] [] lock_acquire+0x182/0x1d0 [ 554.581701] [] ktime_get+0x9a/0x1b0 [ 554.581701] [] start_bandwidth_timer+0x27/0x60 [ 554.581701] [] __enqueue_rt_entity+0x23e/0x290 [ 554.581701] [] enqueue_rt_entity+0x6b/0x80 [ 554.581701] [] enqueue_task_rt+0x36/0xb0 [ 554.652241] can: request_module (can-proto-4) failed. [ 554.581701] [] enqueue_task+0x52/0x60 [ 554.581701] [] activate_task+0x22/0x30 [ 554.581701] [] ttwu_activate+0x21/0x50 [ 554.581701] [] T.2138+0x3c/0x60 [ 554.581701] [] sched_ttwu_pending+0x51/0x70 [ 554.581701] [] scheduler_ipi+0x142/0x210 [ 554.581701] [] smp_reschedule_interrupt+0x2a/0x30 [ 554.581701] [] reschedule_interrupt+0x72/0x80 [ 554.581701] [] default_idle+0x11d/0x260 [ 554.581701] [] arch_cpu_idle+0x18/0x50 [ 554.581701] [] cpu_idle_loop+0x351/0x460 [ 554.581701] [] cpu_startup_entry+0x70/0x80 [ 554.581701] [] start_secondary+0xf3/0x100 [ 554.581701] [ 554.581701] other info that might help us debug this: [ 554.581701] [ 554.581701] Chain exists of: timekeeper_seq --> &rq->lock --> &rt_b->rt_runtime_lock [ 554.581701] Possible unsafe locking scenario: [ 554.581701] [ 554.581701] CPU0 CPU1 [ 554.581701] ---- ---- [ 554.581701] lock(&rt_b->rt_runtime_lock); [ 554.581701] lock(&rq->lock); [ 554.581701] lock(&rt_b->rt_runtime_lock); [ 554.581701] lock(timekeeper_seq); [ 554.581701] [ 554.581701] *** DEADLOCK *** [ 554.581701] [ 554.678330] 2 locks held by swapper/16/0: [ 554.678330] #0: (&rq->lock){-.-.-.}, at: [] sched_ttwu_pending+0x34/0x70 [ 554.678330] #1: (&rt_b->rt_runtime_lock){-.-...}, at: [] __enqueue_rt_entity+0x229/0x290 [ 554.678330] [ 554.678330] stack backtrace: [ 554.678330] CPU: 16 PID: 0 Comm: swapper/16 Not tainted 3.13.0-rc2-next-20131206-sasha-00005-g8be2375-dirty #4054 [ 554.678330] 0000000000000000 ffff880fe5603ba8 ffffffff84391b37 0000000000000000 [ 554.678330] 0000000000000000 ffff880fe5603bf8 ffffffff811918d9 ffff880fe5603c18 [ 554.678330] ffffffff875f9d00 ffff880fe5603bf8 ffff880fcc543c10 ffff880fcc543c48 [ 554.678330] Call Trace: [ 554.678330] [] dump_stack+0x52/0x7f [ 554.678330] [] print_circular_bug+0x129/0x160 [ 554.678330] [] check_prev_add+0x13f/0x550 [ 554.678330] [] ? sched_clock_cpu+0x108/0x120 [ 554.678330] [] validate_chain+0x6c3/0x7b0 [ 554.678330] [] ? sched_clock_cpu+0x108/0x120 [ 554.678330] [] __lock_acquire+0x4ad/0x580 [ 554.678330] [] lock_acquire+0x182/0x1d0 [ 554.678330] [] ? start_bandwidth_timer+0x27/0x60 [ 554.678330] [] ? __lock_acquired+0x2a2/0x2e0 [ 554.678330] [] ktime_get+0x9a/0x1b0 [ 554.678330] [] ? start_bandwidth_timer+0x27/0x60 [ 554.678330] [] __enqueue_rt_entity+0x23e/0x290 [ 554.678330] [] enqueue_rt_entity+0x6b/0x80 [ 554.678330] [] enqueue_task_rt+0x36/0xb0 [ 554.678330] [] enqueue_task+0x52/0x60 [ 554.678330] [] ? sched_ttwu_pending+0x34/0x70 [ 554.678330] [] activate_task+0x22/0x30 [ 554.678330] [] ttwu_activate+0x21/0x50 [ 554.678330] [] T.2138+0x3c/0x60 [ 554.678330] [] sched_ttwu_pending+0x51/0x70 [ 554.678330] [] scheduler_ipi+0x142/0x210 [ 554.678330] [] ? kvm_guest_apic_eoi_write+0x1a/0x50 [ 554.678330] [] smp_reschedule_interrupt+0x2a/0x30 [ 554.678330] [] reschedule_interrupt+0x72/0x80 [ 554.678330] [] ? native_safe_halt+0x6/0x10 [ 554.678330] [] ? trace_hardirqs_on+0xd/0x10 [ 554.678330] [] default_idle+0x11d/0x260 [ 554.678330] [] arch_cpu_idle+0x18/0x50 [ 554.678330] [] cpu_idle_loop+0x351/0x460 [ 554.678330] [] cpu_startup_entry+0x70/0x80 [ 554.678330] [] start_secondary+0xf3/0x100