On Sun, Mar 6, 2016 at 6:23 PM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
> On Sat, 5 Mar 2016, Sedat Dilek wrote:
>
>> On Fri, Mar 4, 2016 at 5:04 PM, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
>> > On Wed, 2 Mar 2016, Sedat Dilek wrote:
>> >
>> >> On 3/1/16, Alan Stern <stern@xxxxxxxxxxxxxxxxxxx> wrote:
>> >> > On Tue, 1 Mar 2016, Sedat Dilek wrote:
>> >> >
>> >> >> On Tue, Oct 13, 2015 at 2:57 AM, Steven Rostedt <rostedt@xxxxxxxxxxx>
>> >> >> wrote:
>> >> >> > On Sat, 3 Oct 2015 12:05:42 +0200
>> >> >> > Sedat Dilek <sedat.dilek@xxxxxxxxx> 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
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
