From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754120AbcCAPHq (ORCPT ); Tue, 1 Mar 2016 10:07:46 -0500 Received: from smtprelay0074.hostedemail.com ([216.40.44.74]:38900 "EHLO smtprelay.hostedemail.com" rhost-flags-OK-OK-OK-FAIL) by vger.kernel.org with ESMTP id S1753513AbcCAPHp (ORCPT ); Tue, 1 Mar 2016 10:07:45 -0500 X-Session-Marker: 726F737465647440676F6F646D69732E6F7267 X-Spam-Summary: 2,0,0,,d41d8cd98f00b204,rostedt@goodmis.org,:::::::::::::::::::::::::::,RULES_HIT:2:41:355:379:541:599:800:960:968:973:988:989:1260:1277:1311:1313:1314:1345:1359:1437:1515:1516:1518:1535:1593:1594:1605:1730:1747:1777:1792:2198:2199:2393:2553:2559:2562:2731:3138:3139:3140:3141:3142:3622:3865:3866:3867:3868:3870:3871:3872:3873:4050:4120:4321:4605:5007:6119:6261:6742:7514:7875:7903:8660:9163:10004:10848:10967:11026:11232:11658:11914:12043:12296:12438:12517:12519:12555:12740:13148:13230:13439:13548:13870:13972:14659:21080:30029:30034:30054:30056:30064:30090:30091,0,RBL:none,CacheIP:none,Bayesian:0.5,0.5,0.5,Netcheck:none,DomainCache:0,MSF:not bulk,SPF:fn,MSBL:0,DNSBL:none,Custom_rules:0:0:0,LFtime:2,LUA_SUMMARY:none X-HE-Tag: bread18_7d6d3bc075e0d X-Filterd-Recvd-Size: 9229 Date: Tue, 1 Mar 2016 10:07:40 -0500 From: Steven Rostedt To: Sedat Dilek Cc: Jiri Kosina , Tejun Heo , Lai Jiangshan , Benjamin Tissoires , Paul McKenney , Andy Lutomirski , LKML , linux-usb@vger.kernel.org, Greg Kroah-Hartman , Alan Stern , Felipe Balbi , Peter Zijlstra , Ingo Molnar Subject: Re: [PATCH] usbhid: Fix lockdep unannotated irqs-off warning Message-ID: <20160301100740.759440b7@gandalf.local.home> In-Reply-To: References: <1443427804-2957-1-git-send-email-sedat.dilek@gmail.com> <20150930045655.1c52eecd@gandalf.local.home> <20150930061351.06f06abd@gandalf.local.home> <20150930220153.7a75c4fc@grimm.local.home> <20151012205755.7ad86f4c@grimm.local.home> X-Mailer: Claws Mail 3.13.2 (GTK+ 2.24.29; x86_64-pc-linux-gnu) MIME-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org On Tue, 1 Mar 2016 11:05:42 +0100 Sedat Dilek 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? > > --- 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: [] > process_one_work+0x30f/0x8d0 > +[ 321.950830] #1: ((&hub->events)){+.+.+.}, at: > [] process_one_work+0x33c/0x8d0 > +[ 321.950836] #2: (&dev->mutex){......}, at: [] > hub_event+0x50/0x15b0 > +[ 321.950844] #3: (&dev->mutex){......}, at: [] > usb_disconnect+0x5f/0x2c0 > +[ 321.950849] #4: (&dev->mutex){......}, at: [] > device_release_driver+0x22/0x40 > +[ 321.950856] #5: (&dev->mutex){......}, at: [] > device_release_driver+0x22/0x40 > +[ 321.950862] #6: (input_mutex){+.+.+.}, at: [] > __input_unregister_device+0x9a/0x190 > +[ 321.950869] #7: (&dev->mutex#2){+.+...}, at: > [] input_close_device+0x27/0x70 > +[ 321.950875] #8: (hid_open_mut){+.+...}, at: [] > usbhid_close+0x28/0xb0 [usbhid] > +[ 321.950883] irq event stamp: 47770 > +[ 321.950885] hardirqs last enabled at (47769): > [] _raw_spin_unlock_irq+0x32/0x60 > +[ 321.950889] hardirqs last disabled at (47770): > [] 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? > +[ 321.950894] softirqs last enabled at (47112): > [] __do_softirq+0x5a2/0x610 > +[ 321.950898] softirqs last disabled at (47097): > [] irq_exit+0x9c/0x120 > +[ 321.950903] CPU: 2 PID: 44 Comm: kworker/2:1 Not tainted > 4.5.0-rc6-2-llvmlinux-amd64 #1 > +[ 321.950905] Hardware name: SAMSUNG ELECTRONICS CO., LTD. > 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH, BIOS 13XK 03/28/2013 > +[ 321.950908] Workqueue: usb_hub_wq hub_event > +[ 321.950911] ffff8800d3326948 0000000000000092 0000000000000000 > ffff8800d4347568 > +[ 321.950915] ffffffff814ba7d4 ffff8800d43474f8 ffff8800d4340cc0 > ffff8800d4347568 > +[ 321.950919] ffffffff810e28fd 0000000000000092 0000000000000096 > ffff8800d43475a8 > +[ 321.950923] Call Trace: > +[ 321.950927] [] dump_stack+0xa4/0xf0 > +[ 321.950931] [] ? print_irqtrace_events+0xcd/0xe0 > +[ 321.950936] [] ___might_sleep+0x295/0x2b0 > +[ 321.950939] [] __might_sleep+0x4f/0xc0 This triggered on the might_sleep() in start_flush_work() because something left interrupts enable. Just strange. -- Steve > +[ 321.950943] [] start_flush_work+0x2f/0x2a0 > +[ 321.950946] [] flush_work+0x5c/0x80 > +[ 321.950949] [] ? flush_work+0x1a/0x80 > +[ 321.950953] [] ? trace_hardirqs_off+0xd/0x10 > +[ 321.950956] [] ? try_to_grab_pending+0x4a/0x260 > +[ 321.950960] [] __cancel_work_timer+0x197/0x290 > +[ 321.950963] [] ? try_to_del_timer_sync+0xad/0xc0 > +[ 321.950966] [] cancel_work_sync+0x18/0x20 > +[ 321.950970] [] usbhid_close+0x75/0xb0 [usbhid] > +[ 321.950977] [] hidinput_close+0x31/0x40 [hid] > +[ 321.950982] [] ? hidinput_open+0x40/0x40 [hid] > +[ 321.950985] [] input_close_device+0x48/0x70 > +[ 321.950988] [] evdev_cleanup+0xd5/0xe0 > +[ 321.950990] [] evdev_disconnect+0x2c/0x60 > +[ 321.950993] [] __input_unregister_device+0xbe/0x190 > +[ 321.950996] [] input_unregister_device+0x4a/0x80 > +[ 321.951001] [] hidinput_disconnect+0x8f/0xc0 [hid] > +[ 321.951007] [] hid_device_remove+0xb0/0x130 [hid] > +[ 321.951010] [] __device_release_driver+0xfd/0x190 > +[ 321.951014] [] device_release_driver+0x2a/0x40 > +[ 321.951017] [] bus_remove_device+0x153/0x190 > +[ 321.951020] [] device_del+0x1db/0x2b0 > +[ 321.951025] [] hid_destroy_device+0x2c/0x60 [hid] > +[ 321.951029] [] usbhid_disconnect+0x67/0x90 [usbhid] > +[ 321.951033] [] usb_unbind_interface+0xbf/0x2b0 > +[ 321.951037] [] __device_release_driver+0xfd/0x190 > +[ 321.951040] [] device_release_driver+0x2a/0x40 > +[ 321.951043] [] bus_remove_device+0x153/0x190 > +[ 321.951046] [] device_del+0x1db/0x2b0 > +[ 321.951048] [] ? device_unregister+0x2c/0x40 > +[ 321.951051] [] usb_disable_device+0x10b/0x3b0 > +[ 321.951054] [] usb_disconnect+0xf4/0x2c0 > +[ 321.951057] [] hub_event+0xbad/0x15b0 > +[ 321.951060] [] ? _raw_spin_unlock_irq+0x32/0x60 > +[ 321.951063] [] process_one_work+0x4be/0x8d0 > +[ 321.951065] [] ? process_one_work+0x33c/0x8d0 > +[ 321.951068] [] worker_thread+0x5cb/0x750 > +[ 321.951071] [] ? destroy_worker+0x110/0x110 > +[ 321.951074] [] kthread+0x115/0x120 > +[ 321.951077] [] ? trace_hardirqs_on+0xd/0x10 > +[ 321.951080] [] ? flush_kthread_worker+0x80/0x80 > +[ 321.951084] [] ret_from_fork+0x3f/0x70 > +[ 321.951087] [] ? flush_kthread_worker+0x80/0x80 >