From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755436AbYKMXlY (ORCPT ); Thu, 13 Nov 2008 18:41:24 -0500 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1752686AbYKMXlP (ORCPT ); Thu, 13 Nov 2008 18:41:15 -0500 Received: from ogre.sisk.pl ([217.79.144.158]:35930 "EHLO ogre.sisk.pl" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751715AbYKMXlP (ORCPT ); Thu, 13 Nov 2008 18:41:15 -0500 From: "Rafael J. Wysocki" To: Matt Mackall Subject: Re: 2.6.28-rc4: inconsistent lock state durin s2ram Date: Fri, 14 Nov 2008 00:45:47 +0100 User-Agent: KMail/1.9.9 Cc: Linux Kernel Mailing List , Ingo Molnar , Peter Zijlstra References: <1226616324.3343.58.camel@calx> In-Reply-To: <1226616324.3343.58.camel@calx> MIME-Version: 1.0 Content-Type: text/plain; charset="iso-8859-15" Content-Transfer-Encoding: 7bit Content-Disposition: inline Message-Id: <200811140045.48068.rjw@sisk.pl> Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Thursday, 13 of November 2008, Matt Mackall wrote: > Just noticed this while looking to see if my iwlagn regression was still > around (doesn't seem to be): Is this reproducible? It seems to be related to the scheduler. > [112342.899610] SMP alternatives: switching to UP code > [112343.045933] > [112343.045935] ================================= > [112343.045937] [ INFO: inconsistent lock state ] > [112343.045941] 2.6.28-rc4 #40 > [112343.045943] --------------------------------- > [112343.045945] inconsistent {in-hardirq-W} -> {hardirq-on-W} usage. > [112343.045949] ksoftirqd/0/4 [HC0[0]:SC1[1]:HE1:SE0] takes: > [112343.045951] (&rq->lock){++..}, at: [] > sched_rt_period_timer+0xb9/0x1c7 > [112343.045961] {in-hardirq-W} state was registered at: > [112343.045963] [] 0xffffffffffffffff > [112343.045969] irq event stamp: 4112884 > [112343.045972] hardirqs last enabled at (4112884): > [] _spin_unlock_irq+0x24/0x2e > [112343.045978] hardirqs last disabled at (4112883): > [] _spin_lock_irq+0x15/0x41 > [112343.045983] softirqs last enabled at (4112876): > [] call_softirq+0x1c/0x28 > [112343.045989] softirqs last disabled at (4112881): > [] call_softirq+0x1c/0x28 > [112343.045994] > [112343.045995] other info that might help us debug this: > [112343.045997] no locks held by ksoftirqd/0/4. > [112343.045999] > [112343.046000] stack backtrace: > [112343.046003] Pid: 4, comm: ksoftirqd/0 Not tainted 2.6.28-rc4 #40 > [112343.046006] Call Trace: > [112343.046008] [] print_usage_bug+0x1a3/0x1b2 > [112343.046019] [] save_stack_trace+0x22/0x3e > [112343.046023] [] mark_lock+0x5a9/0x91f > [112343.046028] [] __lock_acquire+0x6c2/0x14b2 > [112343.046032] [] lock_acquire+0x8d/0xba > [112343.046037] [] sched_rt_period_timer+0xb9/0x1c7 > [112343.046041] [] _spin_lock+0x29/0x36 > [112343.046045] [] sched_rt_period_timer+0xb9/0x1c7 > [112343.046050] [] __next_cpu+0x19/0x26 > [112343.046054] [] sched_rt_period_timer+0xb9/0x1c7 > [112343.046058] [] _spin_unlock_irq+0x24/0x2e > [112343.046063] [] sched_rt_period_timer+0x0/0x1c7 > [112343.046068] [] run_hrtimer_pending+0x61/0x10b > [112343.046073] [] __do_softirq+0x8e/0x163 > [112343.046077] [] call_softirq+0x1c/0x28 > [112343.046079] [] do_softirq+0x45/0xa5 > [112343.046086] [] ksoftirqd+0x56/0xcc > [112343.046090] [] ksoftirqd+0x0/0xcc > [112343.046095] [] kthread+0x47/0x73 > [112343.046101] [] trace_hardirqs_on_thunk+0x3a/0x3f > [112343.046105] [] child_rip+0xa/0x11 > [112343.046109] [] restore_args+0x0/0x30 > [112343.046114] [] kthreadd+0x187/0x1ac > [112343.046118] [] kthread+0x0/0x73 > [112343.046122] [] child_rip+0x0/0x11 > -- Everyone knows that debugging is twice as hard as writing a program in the first place. So if you're as clever as you can be when you write it, how will you ever debug it? --- Brian Kernighan