From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
	id S1754511AbcCAPRK (ORCPT <rfc822;w@1wt.eu>);
	Tue, 1 Mar 2016 10:17:10 -0500
Received: from casper.infradead.org ([85.118.1.10]:34992 "EHLO
	casper.infradead.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
	with ESMTP id S1754481AbcCAPRH (ORCPT
	<rfc822;linux-kernel@vger.kernel.org>);
	Tue, 1 Mar 2016 10:17:07 -0500
Date: Tue, 1 Mar 2016 16:17:00 +0100
From: Peter Zijlstra <peterz@infradead.org>
To: Steven Rostedt <rostedt@goodmis.org>
Cc: Sedat Dilek <sedat.dilek@gmail.com>, Jiri Kosina <jikos@kernel.org>,
        Tejun Heo <tj@kernel.org>, Lai Jiangshan <jiangshanlai@gmail.com>,
        Benjamin Tissoires <benjamin.tissoires@redhat.com>,
        Paul McKenney <paulmck@linux.vnet.ibm.com>,
        Andy Lutomirski <luto@kernel.org>, LKML <linux-kernel@vger.kernel.org>,
        linux-usb@vger.kernel.org,
        Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        Alan Stern <stern@rowland.harvard.edu>, Felipe Balbi <balbi@ti.com>,
        Ingo Molnar <mingo@redhat.com>
Subject: Re: [PATCH] usbhid: Fix lockdep unannotated irqs-off warning
Message-ID: <20160301151700.GU6356@twins.programming.kicks-ass.net>
References: <CA+icZUUnoD8_=Wm+OM2pN0ZS-rwqjLHtTw5xCWe5epNqSTZSiQ@mail.gmail.com>
 <20150930061351.06f06abd@gandalf.local.home>
 <CA+icZUXSzScTmMgLZwPQq9RMH9cUsD5_iDxKTVuG0rrGqH-8Cw@mail.gmail.com>
 <20150930220153.7a75c4fc@grimm.local.home>
 <CA+icZUV7pxXoApuLdc7Z=kMHiKG=diHNqsnR5-MHpER=XkjQVQ@mail.gmail.com>
 <CA+icZUUyaHqHP2v52juhGhoTNS9xX7LT2YxkOppLz6f9Z+FBEA@mail.gmail.com>
 <CA+icZUWagGMVNs5gBPRBhYO0LsY2A1hK3KSLabp9ZpDVOTmtig@mail.gmail.com>
 <20151012205755.7ad86f4c@grimm.local.home>
 <CA+icZUUCNAUDVqg1D-brJtZ2_QRxW_2s+jv0T5MPpCE9Y-auvg@mail.gmail.com>
 <20160301100740.759440b7@gandalf.local.home>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <20160301100740.759440b7@gandalf.local.home>
User-Agent: Mutt/1.5.21 (2012-12-30)
Sender: linux-kernel-owner@vger.kernel.org
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

On Tue, Mar 01, 2016 at 10:07:40AM -0500, Steven Rostedt wrote:
> On Tue, 1 Mar 2016 11:05:42 +0100
> Sedat Dilek <sedat.dilek@gmail.com> wrote:
> 
> 
> > [ FACT #3: TEST-CASE #2 ]
> > 
> > The most reliable test-case is to simply unplug my external Logitech
> > USB mouse - saw this by accident.
> > YES, it was so simple.
> 
> Just to clarify, this happens on gcc and clang?

Just clang from what I gather.

> > --- dmesg_4.5.0-rc6-2-llvmlinux-amd64.txt       2016-02-29
> > 21:23:56.399691975 +0100
> > +++ dmesg_4.5.0-rc6-2-llvmlinux-amd64_usbmouse-unplugged.txt
> > 2016-02-29 21:28:14.401832240 +0100
> > @@ -832,3 +832,75 @@
> >  [   66.529779] PPP BSD Compression module registered
> >  [   66.563013] PPP Deflate Compression module registered
> >  [   66.978977] usb 2-1.5: USB disconnect, device number 4
> > +[  321.937369] usb 2-1.4: USB disconnect, device number 3
> > +[  321.950810] BUG: sleeping function called from invalid context at
> > kernel/workqueue.c:2785
> > +[  321.950816] in_atomic(): 0, irqs_disabled(): 1, pid: 44, name: kworker/2:1
> > +[  321.950819] 9 locks held by kworker/2:1/44:
> > +[  321.950820]  #0:  ("usb_hub_wq"){.+.+.+}, at: [<ffffffff810a7c5f>]
> > process_one_work+0x30f/0x8d0
> > +[  321.950830]  #1:  ((&hub->events)){+.+.+.}, at:
> > [<ffffffff810a7c8c>] process_one_work+0x33c/0x8d0
> > +[  321.950836]  #2:  (&dev->mutex){......}, at: [<ffffffff816fb0e0>]
> > hub_event+0x50/0x15b0
> > +[  321.950844]  #3:  (&dev->mutex){......}, at: [<ffffffff816f686f>]
> > usb_disconnect+0x5f/0x2c0
> > +[  321.950849]  #4:  (&dev->mutex){......}, at: [<ffffffff816245a2>]
> > device_release_driver+0x22/0x40
> > +[  321.950856]  #5:  (&dev->mutex){......}, at: [<ffffffff816245a2>]
> > device_release_driver+0x22/0x40
> > +[  321.950862]  #6:  (input_mutex){+.+.+.}, at: [<ffffffff8175171a>]
> > __input_unregister_device+0x9a/0x190
> > +[  321.950869]  #7:  (&dev->mutex#2){+.+...}, at:
> > [<ffffffff8174fe27>] input_close_device+0x27/0x70
> > +[  321.950875]  #8:  (hid_open_mut){+.+...}, at: [<ffffffffa0057388>]
> > usbhid_close+0x28/0xb0 [usbhid]
> > +[  321.950883] irq event stamp: 47770
> > +[  321.950885] hardirqs last  enabled at (47769):
> > [<ffffffff819426a2>] _raw_spin_unlock_irq+0x32/0x60
> > +[  321.950889] hardirqs last disabled at (47770):
> > [<ffffffff81115bdc>] del_timer_sync+0x3c/0x110
> 
> According to lockdep, interrupts were last disabled in del_timer_sync,
> and they were never enabled. The numbers in parenthesis show the order
> of events. _raw_spin_unlock_irq() at 47769, then del_timer_sync at
> 47770.
> 
> But why did they not get enabled again? We have:
> 
> 	local_irq_save(flags);
> 	lock_map_acquire(&timer->lockdep_map);
> 	lock_map_release(&timer->lockdep_map);
> 	local_irq_restore(flags);
> 
> If this caused an issue, then you would have a lockdep splat. But
> perhaps something corrupted "flags", and interrupts were not re-enabled?

Right, most odd. Sedat, could you provide objdump -D of the relevant
sections of vmlinux ?