| Message ID | alpine.LNX.2.00.1509291117280.30132@pobox.suse.cz (mailing list archive) |
|---|---|
| State | New, archived |
| Delegated to: | Jiri Kosina |
| Headers | show |
On Tue, Sep 29, 2015 at 11:27 AM, Jiri Kosina <jikos@kernel.org> wrote: > On Tue, 29 Sep 2015, Sedat Dilek wrote: > >> Did you look at the step-by-step moving of trace_hardirqs_off() and >> the corresponding dmesg-logs? >> What helps is a trace_hardirqs_off() before spin_unlock_irq() in the >> if-statement. >> So, yes "IRQs are enabled" but tracing does not like it. > > I so far fail to make any sense out of this behavior. > >> > Therefore ... >> > >> > [ ... snip ... ] >> >> 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); >> > >> > I still don't understand how this should be improving anything. I believe >> > spin_unlock_irq() should just re-enable interrupts, because we've been >> > called with them enabled as well. >> >> Is spin_lock_bh() not an appropriate replacement? > > No, it's not. Plus, before we gain understanding why exactly is the > warning being issued, I am not making any random changes to the code. > >> > Now if you are able to see how usbhid_close() can be called with IRQs >> > off, that would be a completely different story. But if that's not the >> > case, the warning is bogus, and gcc-compiled kernels are right about not >> > issuing it. >> >> Again, I am new to tracing. >> Steven encouraged me to look at the lockdep hints in dmesg - not ftrace [1]. >> >> "Actually, if you are looking for where interrupts were disabled last >> before triggering the "sleeping function called from invalid context", >> lockdep, not ftrace, would be your better bet. >> >> Enable lockdep with CONFIG_PROVE_LOCKING. It will give you better >> information about where the last irq was disabled." >> >> Here, I have CONFIG_PROVE_LOCKING=y. >> >> I am doing a new kernel-build with the might_sleep() on top of >> hid_cancel_delayed_stuff() which showed some lockdep/irqsoff hints in >> dmesg-log. > > Yes. That dmesg doesn't still make any sense. It tells us that IRQs got > enabled during spin_unlock_irq() (I believe it's the very one in > usbhid_close(), but we'll see), and then it bugs because it thinks they > are enabled. > > Actually, could you please run with the attached patch (you need lockdep > enabled for it to build) and send me your dmesg? Ideally both from > gcc-compiled kernel and llvm-compiled kernel as well. > > diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c > index 36712e9..aaae42e 100644 > --- a/drivers/hid/usbhid/hid-core.c > +++ b/drivers/hid/usbhid/hid-core.c > @@ -38,6 +38,8 @@ > #include <linux/hidraw.h> > #include "usbhid.h" > > +#include <linux/lockdep.h> > + > /* > * Version Information > */ > @@ -725,6 +727,9 @@ void usbhid_close(struct hid_device *hid) > > mutex_lock(&hid_open_mut); > > + if(WARN_ON(irqs_disabled())) > + print_irqtrace_events(current); > + > /* protecting hid->open to make sure we don't restart > * data acquistion due to a resumption we no longer > * care about > > -- > This breaks my build when CONFIG_USB_HID=m... find .tmp_versions -name '*.mod' | xargs -r grep -h '\.ko$' | sort -u | sed 's/\.ko$/.o/' | scripts/mod/modpost -m -a -o ./Module.symvers -S -s -T - ERROR: "print_irqtrace_events" [drivers/hid/usbhid/usbhid.ko] undefined! make[3]: *** [__modpost] Error 1 make[2]: *** [modules] Error 2 make[1]: *** [bindeb-pkg] Error 2 make: *** [bindeb-pkg] Error 2 - Sedat - -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, 30 Sep 2015, Sedat Dilek wrote: > > diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c > > index 36712e9..aaae42e 100644 > > --- a/drivers/hid/usbhid/hid-core.c > > +++ b/drivers/hid/usbhid/hid-core.c > > @@ -38,6 +38,8 @@ > > #include <linux/hidraw.h> > > #include "usbhid.h" > > > > +#include <linux/lockdep.h> > > + > > /* > > * Version Information > > */ > > @@ -725,6 +727,9 @@ void usbhid_close(struct hid_device *hid) > > > > mutex_lock(&hid_open_mut); > > > > + if(WARN_ON(irqs_disabled())) > > + print_irqtrace_events(current); > > + > > /* protecting hid->open to make sure we don't restart > > * data acquistion due to a resumption we no longer > > * care about > > > > -- > > "-7" CLANG-compiled and "-8" GCC-compiled. So, my warning didn't trigger in neither of the kernels. That directly implies that usbbhid_close() is being called with IRQs enabled, and therefore once it calls hid_cancel_delayed_stuff(), they are enabled again. That makes the previous warnings invalid, and I would dare to blame compiler on that. Now, in this case, clang apparently got it right (because the original warning didn't trigger) in usbhid_close(), but moved the bug elsewhere somehow. Now the warning looks like this: > BUG: sleeping function called from invalid context at kernel/workqueue.c:2678 > in_atomic(): 0, irqs_disabled(): 1, pid: 1474, name: acpid So again, IRQs disabled. > 3 locks held by acpid/1474: > #0: (&evdev->mutex){+.+...}, at: [<ffffffff8174c98c>] evdev_release+0xbc/0xf0 > #1: (&dev->mutex#2){+.+...}, at: [<ffffffff817440a7>] input_close_device+0x27/0x70 > #2: (hid_open_mut){+.+...}, at: [<ffffffffa0056388>] usbhid_close+0x28/0xf0 [usbhid] No spinlock held, so all _irqsave() / _irqrestore() pairs have been executed. > irq event stamp: 3332 > hardirqs last enabled at (3331): [<ffffffff8192ccd2>] _raw_spin_unlock_irq+0x32/0x60 > hardirqs last disabled at (3332): [<ffffffff81122127>] del_timer_sync+0x37/0x110 del_timer_sync() is being blamed to be the one leaking IRQs disabled. The only two things that this function does (even if you look at all functions that could be potentially inlined into it) wrt. IRQs are (1) local_irq_save(flags); lock_map_acquire(&timer->lockdep_map); lock_map_release(&timer->lockdep_map); local_irq_restore(flags); (2) lock_timer_base() calls spin_lock_irqsave() and spin_unlock_irqrestore() in pairs in a loop, but it's guaranteed to return with IRQs disabled, and corresponding spin_unlock_irqrestore() is then perfomed in the callee (try_to_del_timer_sync()) In either case, there is no IRQ state leakage. Therefore I would dare to blame compiler on getting it wrong here as well. The generated assembly really needs to be inspected to see how does clang manage to leak the IRQ state (probably some incorrect reordering, i.e. not respecting the "memory" clobber while fiddling with flags). [ ... snip a lot of stuff ... ] > What shall I do... play with lockdep (print_irqtrace_events) in > del_timer_sync()? I'd suggest showing this to clang folks. Thanks,
On Wed, 30 Sep 2015 09:35:23 +0200 (CEST) Jiri Kosina <jikos@kernel.org> wrote: > [ ... snip a lot of stuff ... ] > > What shall I do... play with lockdep (print_irqtrace_events) in > > del_timer_sync()? Also, do you have PARAVIRT enabled by chance? -- Steve > > I'd suggest showing this to clang folks. > > Thanks, > -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Sep 30, 2015 at 10:56 AM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Wed, 30 Sep 2015 09:35:23 +0200 (CEST) > Jiri Kosina <jikos@kernel.org> wrote: > > >> [ ... snip a lot of stuff ... ] >> > What shall I do... play with lockdep (print_irqtrace_events) in >> > del_timer_sync()? > > Also, do you have PARAVIRT enabled by chance? > Yes. CONFIG_PARAVIRT=y Is that the corresponding indicator in dmesg-log? [ 0.000000] Booting paravirtualized kernel on bare hardware What is your suspicion, Lt. Columbo? - Sedat - > -- Steve > >> >> I'd suggest showing this to clang folks. >> >> Thanks, >> > -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, 30 Sep 2015 11:46:31 +0200 Sedat Dilek <sedat.dilek@gmail.com> wrote: > On Wed, Sep 30, 2015 at 10:56 AM, Steven Rostedt <rostedt@goodmis.org> wrote: > > On Wed, 30 Sep 2015 09:35:23 +0200 (CEST) > > Jiri Kosina <jikos@kernel.org> wrote: > > > > > >> [ ... snip a lot of stuff ... ] > >> > What shall I do... play with lockdep (print_irqtrace_events) in > >> > del_timer_sync()? > > > > Also, do you have PARAVIRT enabled by chance? > > > > Yes. > > CONFIG_PARAVIRT=y > > Is that the corresponding indicator in dmesg-log? > > [ 0.000000] Booting paravirtualized kernel on bare hardware > > What is your suspicion, Lt. Columbo? > Heh, I loved that show. Can you see if you still have the issue if you disable that. PARAVIRT adds a bit of magic when run on baremetal. See arch/x86/kernel/alterative.c. On boot up, things like disabling interrupts, which are originally compiled to perform a function call, that on a virtual machine would do hypervisor calls into the host, and on baremetal does the real code. But that alterative.c file will do live patching of the code to not do the function call but instead do the real work in place (if it can). Something tells me that with clang, things are not as they're expected, and perhaps the modification isn't working. -- Steve -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Wed, Sep 30, 2015 at 12:13 PM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Wed, 30 Sep 2015 11:46:31 +0200 > Sedat Dilek <sedat.dilek@gmail.com> wrote: > >> On Wed, Sep 30, 2015 at 10:56 AM, Steven Rostedt <rostedt@goodmis.org> wrote: >> > On Wed, 30 Sep 2015 09:35:23 +0200 (CEST) >> > Jiri Kosina <jikos@kernel.org> wrote: >> > >> > >> >> [ ... snip a lot of stuff ... ] >> >> > What shall I do... play with lockdep (print_irqtrace_events) in >> >> > del_timer_sync()? >> > >> > Also, do you have PARAVIRT enabled by chance? >> > >> >> Yes. >> >> CONFIG_PARAVIRT=y >> >> Is that the corresponding indicator in dmesg-log? >> >> [ 0.000000] Booting paravirtualized kernel on bare hardware >> >> What is your suspicion, Lt. Columbo? >> > > Heh, I loved that show. > > Can you see if you still have the issue if you disable that. PARAVIRT > adds a bit of magic when run on baremetal. See > arch/x86/kernel/alterative.c. On boot up, things like disabling > interrupts, which are originally compiled to perform a function call, > that on a virtual machine would do hypervisor calls into the host, and > on baremetal does the real code. But that alterative.c file will do > live patching of the code to not do the function call but instead do > the real work in place (if it can). > > Something tells me that with clang, things are not as they're expected, > and perhaps the modification isn't working. > LOL, there is a LLVM(Linux) bug reported in that area - that's why arch_hweight() is disabled etc. I have the bug-no not at hand. I am not in front of my machine right now. - sed@ CSI Tuebingen/Germany - -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, 1 Oct 2015 00:37:52 +0200 Sedat Dilek <sedat.dilek@gmail.com> wrote: > No, that did not help. > > $ dmesg | grep BUG: > [ 24.491708] BUG: sleeping function called from invalid context at > kernel/workqueue.c:2678 > > $ grep -i parav /boot/config-$(uname -r) > # CONFIG_PARAVIRT is not set Hmm, is this SMP or UP? -- Steve -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
On Thu, Oct 1, 2015 at 4:01 AM, Steven Rostedt <rostedt@goodmis.org> wrote: > On Thu, 1 Oct 2015 00:37:52 +0200 > Sedat Dilek <sedat.dilek@gmail.com> wrote: > >> No, that did not help. >> >> $ dmesg | grep BUG: >> [ 24.491708] BUG: sleeping function called from invalid context at >> kernel/workqueue.c:2678 >> >> $ grep -i parav /boot/config-$(uname -r) >> # CONFIG_PARAVIRT is not set > > Hmm, is this SMP or UP? > Es Em Pee... $ grep SMP /boot/config-4.3.0-rc3-11-llvmlinux-amd64 | grep ^CONFIG CONFIG_X86_64_SMP=y CONFIG_GENERIC_SMP_IDLE_THREAD=y CONFIG_SMP=y CONFIG_PM_SLEEP_SMP=y $ grep -i smp dmesg_4.3.0-rc3-11-llvmlinux-amd64.txt [ 0.000000] Linux version 4.3.0-rc3-11-llvmlinux-amd64 (sedat.dilek@gmail.com@fambox) (clang version 3.7.0 (tags/RELEASE_370/final)) #1 SMP Thu Oct 1 00:09:12 CEST 2015 [ 0.000000] found SMP MP-table at [mem 0x000f00e0-0x000f00ef] mapped at [ffff8800000f00e0] [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] smpboot: Allowing 8 CPUs, 4 hotplug CPUs [ 0.031211] Freeing SMP alternatives memory: 24K (ffffffff821e3000 - ffffffff821e9000) [ 0.184518] smpboot: CPU0: Intel(R) Core(TM) i5-2467M CPU @ 1.60GHz (family: 0x6, model: 0x2a, stepping: 0x7) [ 0.186815] x86: Booting SMP configuration: [ 0.195749] smpboot: Total of 4 processors activated (12771.39 BogoMIPS) - Sedat - -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
I was thinking of disabling trace or ftrace and fell over some ftrace patches in llvmlinux. Comments? - Sedat - [1] http://git.linuxfoundation.org/?p=llvmlinux.git;a=blob;f=arch/x86_64/patches/ARCHIVE/0033-Various-fixes-in-arch-x86-include-asm.patch [2] http://git.linuxfoundation.org/?p=llvmlinux.git;a=blob;f=arch/arm/patches/ftrace.patch -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
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. -- Steve -- To unsubscribe from this list: send the line "unsubscribe linux-input" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html
diff --git a/drivers/hid/usbhid/hid-core.c b/drivers/hid/usbhid/hid-core.c index 36712e9..aaae42e 100644 --- a/drivers/hid/usbhid/hid-core.c +++ b/drivers/hid/usbhid/hid-core.c @@ -38,6 +38,8 @@ #include <linux/hidraw.h> #include "usbhid.h" +#include <linux/lockdep.h> + /* * Version Information */ @@ -725,6 +727,9 @@ void usbhid_close(struct hid_device *hid) mutex_lock(&hid_open_mut); + if(WARN_ON(irqs_disabled())) + print_irqtrace_events(current); + /* protecting hid->open to make sure we don't restart * data acquistion due to a resumption we no longer * care about