All of lore.kernel.org
 help / color / mirror / Atom feed
* Re: [PATCH] usbhid: Fix lockdep unannotated irqs-off warning
@ 2016-03-07 15:59 Sedat Dilek
  2016-03-07 16:28 ` Sedat Dilek
  2016-03-07 16:41 ` Alan Stern
  0 siblings, 2 replies; 65+ messages in thread
From: Sedat Dilek @ 2016-03-07 15:59 UTC (permalink / raw)
  To: Alan Stern
  Cc: Steven Rostedt, Jiri Kosina, Tejun Heo, Lai Jiangshan,
	Benjamin Tissoires, Paul McKenney, Andy Lutomirski, LKML,
	USB list, Greg Kroah-Hartman, Peter Zijlstra, Ingo Molnar

[-- Attachment #1: Type: text/plain, Size: 6314 bytes --]

On Sun, Mar 6, 2016 at 6:23 PM, Alan Stern <stern@rowland.harvard.edu> wrote:
> On Sat, 5 Mar 2016, Sedat Dilek wrote:
>
>> On Fri, Mar 4, 2016 at 5:04 PM, Alan Stern <stern@rowland.harvard.edu> wrote:
>> > On Wed, 2 Mar 2016, Sedat Dilek wrote:
>> >
>> >> On 3/1/16, Alan Stern <stern@rowland.harvard.edu> wrote:
>> >> > On Tue, 1 Mar 2016, Sedat Dilek wrote:
>> >> >
>> >> >> On Tue, Oct 13, 2015 at 2:57 AM, Steven Rostedt <rostedt@goodmis.org>
>> >> >> wrote:
>> >> >> > On Sat, 3 Oct 2015 12:05:42 +0200
>> >> >> > Sedat Dilek <sedat.dilek@gmail.com> wrote:
>> >> >> >
>> >> >> >> So, at the beginning... dunno WTF is causing the problems - no
>> >> >> >> workaround for CLANG.
>> >> >> >
>> >> >> > Probably need to compile with gcc and with clang and look at the binary
>> >> >> > differences. Or at least what objdump shows.
>> >> >> >
>> >> >>
>> >> >> [ Hope to address this issue to the correct people - CCed some people
>> >> >> I taped on their nerves ]
>> >> >>
>> >> >> Not sure if I should open a new thread?
>> >> >> Please, some clear statements on this.
>> >> >> Thanks.
>> >> >>
>> >> >> The issue is still visible and alive.
>> >
>> > I think it would be worthwhile to doublecheck the time at which
>> > interrupts get disabled.  Sedat, please try your plug/unplug the USB
>> > mouse test with the patch below.
>> >
>> > Alan Stern
>> >
>> >
>> >
>> > Index: usb-4.4/drivers/hid/usbhid/hid-core.c
>> > ===================================================================
>> > --- usb-4.4.orig/drivers/hid/usbhid/hid-core.c
>> > +++ usb-4.4/drivers/hid/usbhid/hid-core.c
>> > @@ -1393,8 +1393,11 @@ static void usbhid_disconnect(struct usb
>> >
>> >  static void hid_cancel_delayed_stuff(struct usbhid_device *usbhid)
>> >  {
>> > +       if (raw_irqs_disabled())  pr_info("usbhid irqs disabled A\n");
>> >         del_timer_sync(&usbhid->io_retry);
>> > +       if (raw_irqs_disabled())  pr_info("usbhid irqs disabled B\n");
>> >         cancel_work_sync(&usbhid->reset_work);
>> > +       if (raw_irqs_disabled())  pr_info("usbhid irqs disabled C\n");
>> >  }
>> >
>> >  static void hid_cease_io(struct usbhid_device *usbhid)
>> >
>>
>> With your patch I get the dmesg attached.
>
>> [   22.234758] usbhid irqs disabled A
>> [   22.234857] usbhid irqs disabled B
>> [   22.234912] BUG: sleeping function called from invalid context atkernel/workqueue.c:2688
>
> That's a smoking gun.  It means everyone has been looking in the wrong
> place.  Can you provide an objdump listing of usbhid_close()?  The
> routine starts like this:
>
> void usbhid_close(struct hid_device *hid)
> {
>         struct usbhid_device *usbhid = hid->driver_data;
>
>         mutex_lock(&hid_open_mut);
>
>         /* protecting hid->open to make sure we don't restart
>          * data acquistion due to a resumption we no longer
>          * care about
>          */
>         spin_lock_irq(&usbhid->lock);
>         if (!--hid->open) {
>                 spin_unlock_irq(&usbhid->lock);
>                 hid_cancel_delayed_stuff(usbhid);
>
> It appears that the spin_unlock_irq() call isn't working.
>
> For extra thoroughness, try putting one of those raw_irqs_disabled()
> checks just before and one just after the spin_lock_irq() line above.
> Maybe also before the mutex_lock() line.
>
> Alan Stern
>

Hmm, we are there where I was looking at...

Please, read the reply of Jiri [1], we did some tweaking.
With CONFIG_FTRACE=n and CONFIG_PROVE_LOCKING=n !

*** Part one: ObjectDump of hid-core.o ***

$ objdump -D drivers/hid/usbhid/hid-core.o | awk '/<[^>]*>:$/ { p=0; }
/<usbhid_close>:/ { p=1; } { if (p) print $0; }' >
../objdump-D_hid-core_o_usbhid_close_$(uname -r).txt

$ cat ../objdump-D_hid-core_o_usbhid_close_4.4.4-1-iniza-small.txt
00000000000002e0 <usbhid_close>:
     2e0:       55                      push   %rbp
     2e1:       48 89 e5                mov    %rsp,%rbp
     2e4:       41 57                   push   %r15
     2e6:       41 56                   push   %r14
     2e8:       41 54                   push   %r12
     2ea:       53                      push   %rbx
     2eb:       49 89 ff                mov    %rdi,%r15
     2ee:       4d 8b b7 e8 1e 00 00    mov    0x1ee8(%r15),%r14
     2f5:       48 c7 c7 00 00 00 00    mov    $0x0,%rdi
     2fc:       31 f6                   xor    %esi,%esi
     2fe:       e8 00 00 00 00          callq  303 <usbhid_close+0x23>
     303:       49 8d 9e 88 28 00 00    lea    0x2888(%r14),%rbx
     30a:       48 89 df                mov    %rbx,%rdi
     30d:       e8 00 00 00 00          callq  312 <usbhid_close+0x32>
     312:       41 ff 8f e4 1d 00 00    decl   0x1de4(%r15)
     319:       9c                      pushfq
     31a:       41 5c                   pop    %r12
     31c:       48 89 df                mov    %rbx,%rdi
     31f:       e8 00 00 00 00          callq  324 <usbhid_close+0x44>
     324:       41 54                   push   %r12
     326:       9d                      popfq
     327:       75 23                   jne    34c <usbhid_close+0x6c>
     329:       4c 89 f7                mov    %r14,%rdi
     32c:       e8 3f 00 00 00          callq  370 <hid_cancel_delayed_stuff>
     331:       41 f6 87 b9 1d 00 00    testb  $0x4,0x1db9(%r15)
     338:       04
     339:       75 11                   jne    34c <usbhid_close+0x6c>
     33b:       49 8b 7e 18             mov    0x18(%r14),%rdi
     33f:       e8 00 00 00 00          callq  344 <usbhid_close+0x64>
     344:       49 8b 46 08             mov    0x8(%r14),%rax
     348:       80 60 28 f7             andb   $0xf7,0x28(%rax)
     34c:       48 c7 c7 00 00 00 00    mov    $0x0,%rdi
     353:       e8 00 00 00 00          callq  358 <usbhid_close+0x78>
     358:       5b                      pop    %rbx
     359:       41 5c                   pop    %r12
     35b:       41 5e                   pop    %r14
     35d:       41 5f                   pop    %r15
     35f:       5d                      pop    %rbp
     360:       c3                      retq
     361:       66 66 66 66 66 66 2e    data32 data32 data32 data32
data32 nopw %cs:0x0(%rax,%rax,1)
     368:       0f 1f 84 00 00 00 00
     36f:       00

*** Part two: Double-checking (after TV-adds) ***

- Sedat -

[1] https://marc.info/?l=linux-input&m=144359852905747&w=2

[-- Attachment #2: objdump-D_hid-core_o_usbhid_close_4.4.4-1-iniza-small.txt --]
[-- Type: text/plain, Size: 2126 bytes --]

00000000000002e0 <usbhid_close>:
     2e0:	55                   	push   %rbp
     2e1:	48 89 e5             	mov    %rsp,%rbp
     2e4:	41 57                	push   %r15
     2e6:	41 56                	push   %r14
     2e8:	41 54                	push   %r12
     2ea:	53                   	push   %rbx
     2eb:	49 89 ff             	mov    %rdi,%r15
     2ee:	4d 8b b7 e8 1e 00 00 	mov    0x1ee8(%r15),%r14
     2f5:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
     2fc:	31 f6                	xor    %esi,%esi
     2fe:	e8 00 00 00 00       	callq  303 <usbhid_close+0x23>
     303:	49 8d 9e 88 28 00 00 	lea    0x2888(%r14),%rbx
     30a:	48 89 df             	mov    %rbx,%rdi
     30d:	e8 00 00 00 00       	callq  312 <usbhid_close+0x32>
     312:	41 ff 8f e4 1d 00 00 	decl   0x1de4(%r15)
     319:	9c                   	pushfq 
     31a:	41 5c                	pop    %r12
     31c:	48 89 df             	mov    %rbx,%rdi
     31f:	e8 00 00 00 00       	callq  324 <usbhid_close+0x44>
     324:	41 54                	push   %r12
     326:	9d                   	popfq  
     327:	75 23                	jne    34c <usbhid_close+0x6c>
     329:	4c 89 f7             	mov    %r14,%rdi
     32c:	e8 3f 00 00 00       	callq  370 <hid_cancel_delayed_stuff>
     331:	41 f6 87 b9 1d 00 00 	testb  $0x4,0x1db9(%r15)
     338:	04 
     339:	75 11                	jne    34c <usbhid_close+0x6c>
     33b:	49 8b 7e 18          	mov    0x18(%r14),%rdi
     33f:	e8 00 00 00 00       	callq  344 <usbhid_close+0x64>
     344:	49 8b 46 08          	mov    0x8(%r14),%rax
     348:	80 60 28 f7          	andb   $0xf7,0x28(%rax)
     34c:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
     353:	e8 00 00 00 00       	callq  358 <usbhid_close+0x78>
     358:	5b                   	pop    %rbx
     359:	41 5c                	pop    %r12
     35b:	41 5e                	pop    %r14
     35d:	41 5f                	pop    %r15
     35f:	5d                   	pop    %rbp
     360:	c3                   	retq   
     361:	66 66 66 66 66 66 2e 	data32 data32 data32 data32 data32 nopw %cs:0x0(%rax,%rax,1)
     368:	0f 1f 84 00 00 00 00 
     36f:	00 


^ permalink raw reply	[flat|nested] 65+ messages in thread
* [PATCH] usbhid: Fix lockdep unannotated irqs-off warning
@ 2015-09-28  8:10 Sedat Dilek
  2015-09-28 11:33 ` Jiri Kosina
  0 siblings, 1 reply; 65+ messages in thread
From: Sedat Dilek @ 2015-09-28  8:10 UTC (permalink / raw)
  Cc: Sedat Dilek, Jiri Kosina, linux-input, Tejun Heo, Lai Jiangshan,
	Steven Rostedt, Paul McKenney

When compiling Linux v4.2+ and v4.3-rc2+ with a llvmlinux patchset
and CLANG v3.7 I see a BUG line like this:

[   24.705463] BUG: sleeping function called from invalid context at kernel/workqueue.c:2680
[   24.705576] in_atomic(): 0, irqs_disabled(): 1, pid: 1447, name: acpid

After some vital help from workqueue and hid folks it turned out to be
a problem in the hid area.

Jiri encouraged me to look into del_timer-sync()/cancel_work_sync().
So, I disassembled kernel/time/timer.o.
This looked good.

Both functions are called in hid_cancel_delayed_stuff().
Adding a might_sleep() on top of it showed hints towards lockdep and
unannotated irqs-off.

[   23.723807] WARNING: CPU: 0 PID: 1451 at kernel/locking/lockdep.c:3519 check_flags+0x6c/0x1b0()
[   23.723866] DEBUG_LOCKS_WARN_ON(current->hardirqs_enabled)
...
[   23.774719] possible reason: unannotated irqs-off.

Dealing with irqflags-tracing I enabled some helpful kernel-options:

CONFIG_LOCKDEP=y
CONFIG_DEBUG_LOCKDEP=y
CONFIG_TRACING=y
CONFIG_TRACE_IRQFLAGS=y
CONFIG_IRQSOFF_TRACER=y

The file irqflags-tracing.txt was helpful.
Steven Rostedt pointed me to the irqsoff section in ftrace.txt documentation.

Then, I tried to force to turn off the tracing of hardirqs in usbhid_close()
via trace_hardirqs_off() - line by line.
Finally, the spin_unlock_irq() within the if-statement looked like the culprit.

Looking through commits having a similiar issue, I replaced spin_{un}lock_irq()
with spin_{un}lock_bh() as this doesn't need interrupts disabled.

This fixed the issue for me.

Tested against Linux v4.3-rc3.

Still unsure why the same kernel built with GCC v4.9 does not show this.

Thanks to all involved people.

[1] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/irqflags-tracing.txt
[2] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/trace/ftrace.txt#n906

CC: Jiri Kosina <jikos@kernel.org>
CC: linux-input@vger.kernel.org
CC: Tejun Heo <tj@kernel.org>
CC: Lai Jiangshan <jiangshanlai@gmail.com>
CC: Steven Rostedt <rostedt@goodmis.org>
CC: Paul McKenney <paulmck@linux.vnet.ibm.com>

---
 drivers/hid/usbhid/hid-core.c | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c
index 36712e9f56c2..188f59348ec5 100644
--- a/drivers/hid/usbhid/hid-core.c
+++ b/drivers/hid/usbhid/hid-core.c
@@ -729,16 +729,16 @@ void usbhid_close(struct hid_device *hid)
 	 * data acquistion due to a resumption we no longer
 	 * care about
 	 */
-	spin_lock_irq(&usbhid->lock);
+	spin_lock_bh(&usbhid->lock);
 	if (!--hid->open) {
-		spin_unlock_irq(&usbhid->lock);
+		spin_unlock_bh(&usbhid->lock);
 		hid_cancel_delayed_stuff(usbhid);
 		if (!(hid->quirks & HID_QUIRK_ALWAYS_POLL)) {
 			usb_kill_urb(usbhid->urbin);
 			usbhid->intf->needs_remote_wakeup = 0;
 		}
 	} else {
-		spin_unlock_irq(&usbhid->lock);
+		spin_unlock_bh(&usbhid->lock);
 	}
 	mutex_unlock(&hid_open_mut);
 }
-- 
2.5.3


^ permalink raw reply related	[flat|nested] 65+ messages in thread

end of thread, other threads:[~2016-06-27 20:36 UTC | newest]

Thread overview: 65+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2016-03-07 15:59 [PATCH] usbhid: Fix lockdep unannotated irqs-off warning Sedat Dilek
2016-03-07 16:28 ` Sedat Dilek
2016-03-07 16:41 ` Alan Stern
2016-03-07 17:03   ` Steven Rostedt
2016-03-07 17:05   ` Jiri Kosina
2016-03-07 17:15     ` Sedat Dilek
2016-03-07 17:27       ` David Laight
2016-03-07 18:07         ` Alan Stern
2016-03-07 18:30           ` Linus Torvalds
2016-06-27 19:50             ` Sedat Dilek
2016-06-27 20:03               ` Sedat Dilek
2016-06-27 20:14               ` Linus Torvalds
2016-06-27 20:27                 ` Sedat Dilek
2016-06-27 20:36                   ` Linus Torvalds
2016-03-07 17:11   ` Steven Rostedt
2016-03-07 17:18   ` Sedat Dilek
2016-03-07 17:24     ` Jiri Kosina
2016-03-07 17:30       ` Steven Rostedt
2016-03-07 18:04         ` Andy Lutomirski
2016-03-07 19:10           ` Steven Rostedt
  -- strict thread matches above, loose matches on Subject: below --
2015-09-28  8:10 Sedat Dilek
2015-09-28 11:33 ` Jiri Kosina
2015-09-29  8:40   ` Sedat Dilek
2015-09-29  9:27     ` Jiri Kosina
2015-09-29 18:54       ` Sedat Dilek
2015-09-29 19:08         ` Steven Rostedt
2015-09-29 19:32           ` Sedat Dilek
     [not found]       ` <CA+icZUWH2vR_vpYu4hCS578U3ssmoiF0pLYUfM-Xo-57e8uN=g@mail.gmail.com>
2015-09-30  6:41         ` Sedat Dilek
2015-09-30  8:50           ` Steven Rostedt
2015-09-30  7:35         ` Jiri Kosina
2015-09-30  8:56           ` Steven Rostedt
2015-09-30  9:46             ` Sedat Dilek
2015-09-30 10:13               ` Steven Rostedt
2015-09-30 10:39                 ` Sedat Dilek
     [not found]                 ` <CA+icZUXSzScTmMgLZwPQq9RMH9cUsD5_iDxKTVuG0rrGqH-8Cw@mail.gmail.com>
2015-10-01  2:01                   ` Steven Rostedt
2015-10-01  5:34                     ` Sedat Dilek
2015-10-01  6:05                     ` Sedat Dilek
     [not found]                       ` <CA+icZUUyaHqHP2v52juhGhoTNS9xX7LT2YxkOppLz6f9Z+FBEA@mail.gmail.com>
     [not found]                         ` <CA+icZUWagGMVNs5gBPRBhYO0LsY2A1hK3KSLabp9ZpDVOTmtig@mail.gmail.com>
2015-10-13  0:57                           ` Steven Rostedt
2016-03-01 10:05                             ` Sedat Dilek
2016-03-01 15:07                               ` Steven Rostedt
2016-03-01 15:17                                 ` Peter Zijlstra
2016-03-02 15:00                                   ` Sedat Dilek
2016-03-02 15:17                                     ` Peter Zijlstra
2016-03-02 15:34                                       ` Sedat Dilek
2016-03-02 15:53                                       ` Sedat Dilek
2016-03-02 15:56                                         ` Steven Rostedt
2016-03-02 16:08                                           ` Sedat Dilek
2016-03-02 16:11                                             ` Sedat Dilek
2016-03-02 16:21                                               ` Sedat Dilek
2016-03-02 16:24                                         ` Peter Zijlstra
2016-03-02 16:35                                           ` Steven Rostedt
2016-03-02 16:42                                             ` Peter Zijlstra
2016-03-02 16:42                                           ` Sedat Dilek
2016-03-02 16:52                                             ` Sedat Dilek
2016-03-01 15:59                               ` Alan Stern
2016-03-02  6:25                                 ` Sedat Dilek
2016-03-04 16:04                                   ` Alan Stern
2016-03-05 22:30                                     ` Sedat Dilek
2016-03-06  8:51                                       ` Sedat Dilek
2016-03-06 17:23                                       ` Alan Stern
2016-03-02  6:36                                 ` Sedat Dilek
2016-03-02  8:34                                   ` Sedat Dilek
2016-03-02  8:37                                     ` Jiri Kosina
2016-03-02  9:11                                       ` Sedat Dilek
     [not found]     ` <CA+icZUX3tJvRor6CbOZFBecTAUZzyWzjLzJSEdb3c12yKRAT3g@mail.gmail.com>
2015-09-29 13:13       ` Steven Rostedt

This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.