Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S966304Ab3HIJqP (ORCPT ); Fri, 9 Aug 2013 05:46:15 -0400 Received: from h1446028.stratoserver.net ([85.214.92.142]:51181 "EHLO mail.ahsoftware.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S965287Ab3HIJqN (ORCPT ); Fri, 9 Aug 2013 05:46:13 -0400 Message-ID: <5204BA2E.8000100@ahsoftware.de> Date: Fri, 09 Aug 2013 11:45:18 +0200 From: Alexander Holler User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:17.0) Gecko/20130625 Thunderbird/17.0.7 MIME-Version: 1.0 To: rtc-linux@googlegroups.com CC: Andrew Morton , linux-kernel@vger.kernel.org, Alessandro Zummo , Andrew de los Reyes , Jiri Kosina Subject: Re: [rtc-linux] Re: [PATCH 2/2 RESEND] rtc: rtc-hid-sensor-time: enable HID input processing early References: <1375382342-25454-1-git-send-email-holler@ahsoftware.de> <1375382342-25454-2-git-send-email-holler@ahsoftware.de> <20130808151106.7ccaedd4ea3d4e5faa6aa220@linux-foundation.org> In-Reply-To: <20130808151106.7ccaedd4ea3d4e5faa6aa220@linux-foundation.org> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 9589 Lines: 233 Am 09.08.2013 00:11, schrieb Andrew Morton: > On Thu, 1 Aug 2013 20:39:02 +0200 Alexander Holler wrote: > >> Enable the processing of HID input records before the RTC will be registered, >> in order to allow the RTC register function to read clock. Without doing >> that the clock can only be read after the probe function has finished. >> >> Signed-off-by: Alexander Holler >> --- >> drivers/rtc/rtc-hid-sensor-time.c | 7 +++++++ >> 1 file changed, 7 insertions(+) >> >> diff --git a/drivers/rtc/rtc-hid-sensor-time.c b/drivers/rtc/rtc-hid-sensor-time.c >> index 1ab3d13..1006a62 100644 >> --- a/drivers/rtc/rtc-hid-sensor-time.c >> +++ b/drivers/rtc/rtc-hid-sensor-time.c >> @@ -279,11 +279,18 @@ static int hid_time_probe(struct platform_device *pdev) >> return ret; >> } >> >> + /* >> + * Enable HID input processing early in order to be able to read the >> + * clock already in devm_rtc_device_register(). >> + */ >> + hid_device_io_start(hsdev->hdev); >> + >> time_state->rtc = devm_rtc_device_register(&pdev->dev, >> "hid-sensor-time", &hid_time_rtc_ops, >> THIS_MODULE); >> >> if (IS_ERR_OR_NULL(time_state->rtc)) { >> + hid_device_io_stop(hsdev->hdev); >> ret = time_state->rtc ? PTR_ERR(time_state->rtc) : -ENODEV; >> time_state->rtc = NULL; >> sensor_hub_remove_callback(hsdev, HID_USAGE_SENSOR_TIME); > > Shouldn't now there be a hid_device_io_stop() in hid_time_remove()? That isn't how I understood the commit message to commit c849a6143bec520aff2a6646518b0d041402428b which introduced that functionality in 3.10. But maybe I'm wrong. I haven't looked at the underlying code and haven't tested that (very unlikely) error path with the new change I made. > Also, hid_device_io_start() does a weird up() on a > downed-by-someone-else semaphore. Where was that down() performed in > this case? Uh, don't know, as already said, I haven't looked at the underlying code. But I will now do and will enable all mutex/semaphore debug options I find. I have to admit, I didn't have tested the change with debug options enabled, so if the kernel doesn't cry on wierd uo()'s without debug options enabled, I would have missed that. > Also, your changelog implies that the kernel is already doing this > hid_device_io_start(), only it does it too late. If that is the case > then will the existing-before-this-patch call to hid_device_io_start() > generate the "io already started" warning? No, hid_device_io_start() was introduced especially for such cases. I need it because devm_rtc_device_register() might want to read the clock, but without hid_device_io_start() that only is possible after probe finished (therefor not during devm_rtc_device_register()). Some time later ... With several debug options enabled I've got (once) the below backtrace with the error path enabled (time_state->rtc = NULL instead of time_state->rtc = rtc_device_register()). [ 8.007975] rtc_hid_sensor_time HID-SENSOR-2000a0.0: milliseconds supported [ 8.015499] rtc_hid_sensor_time HID-SENSOR-2000a0.0: rtc device register failed! (...) [ 65.551939] ================================= [ 65.556343] [ INFO: inconsistent lock state ] To add some more explanations for the trace (below in full without times): The device I use does send the time around once every minute as an hid input report and this just might have happened here, causing the lock warning. What makes me wonder here is that hid-sensor-hub seems to receive the input report even after hid_device_io_stop() was called and the probe function for the hid device in question (rtc-hid-sensor-time) failed with a rc of -ENODEV. I've added the HID maintainer and the author of the above mentioned commit to cc. I will need some time (hopefully this weekend) to have a deeper look at what goes wrong there. Unfortunatley rtc-hid-sensor-time currently seems to be the only user of hid_device_io_stop(), so I might have hit a bug or did use it wrong. But nevertheless, the non-error-path does work as expected, at least I haven't seen a problem until now. Regards, Alexander Holler ---------- ================================= [ INFO: inconsistent lock state ] 3.10.5-dockstar-00038-g03242d1-dirty #408 Not tainted --------------------------------- inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage. swapper/0 [HC1[1]:SC0[0]:HE0:SE1] takes: (&(&sd->dyn_callback_lock)->rlock){?.+...}, at: [] sensor_hub_raw_event+0x10c/0x204 {HARDIRQ-ON-W} state was registered at: [] __lock_acquire+0x630/0x18f0 [] lock_acquire+0x64/0x78 [] _raw_spin_lock+0x40/0x50 [] sensor_hub_register_callback+0x2c/0xc4 [] hid_time_probe+0x2f8/0x36c [] platform_drv_probe+0x14/0x18 [] driver_probe_device+0xb4/0x210 [] bus_for_each_drv+0x48/0x8c [] device_attach+0x68/0x8c [] bus_probe_device+0x28/0xa0 [] device_add+0x3d8/0x594 [] platform_device_add+0x130/0x1c0 [] mfd_add_device+0x1d0/0x23c [] mfd_add_devices+0x7c/0xac [] sensor_hub_probe+0x2a0/0x364 [] hid_device_probe+0x90/0x128 [] driver_probe_device+0xb4/0x210 [] bus_for_each_drv+0x48/0x8c [] device_attach+0x68/0x8c [] bus_probe_device+0x28/0xa0 [] device_add+0x3d8/0x594 [] hid_add_device+0x244/0x29c [] usbhid_probe+0x368/0x448 [] usb_probe_interface+0x13c/0x1e0 [] driver_probe_device+0xb4/0x210 [] bus_for_each_drv+0x48/0x8c [] device_attach+0x68/0x8c [] bus_probe_device+0x28/0xa0 [] device_add+0x3d8/0x594 [] usb_set_configuration+0x610/0x6bc [] generic_probe+0x3c/0x74 [] usb_probe_device+0x24/0x3c [] driver_probe_device+0xb4/0x210 [] bus_for_each_drv+0x48/0x8c [] device_attach+0x68/0x8c [] bus_probe_device+0x28/0xa0 [] device_add+0x3d8/0x594 [] usb_new_device+0x1dc/0x304 [] hub_thread+0x9c4/0xf70 [] kthread+0xa0/0xb0 [] ret_from_fork+0x14/0x34 irq event stamp: 139814 hardirqs last enabled at (139811): [] cpuidle_enter_state+0x50/0x100 hardirqs last disabled at (139812): [] __irq_svc+0x34/0xa0 softirqs last enabled at (139814): [] irq_enter+0x44/0x64 softirqs last disabled at (139813): [] irq_enter+0x38/0x64 might help us debug this: Possible unsafe locking scenario: CPU0 ---- lock(&(&sd->dyn_callback_lock)->rlock); lock(&(&sd->dyn_callback_lock)->rlock); ** 1 lock held by swapper/0: #0: (&(&sd->lock)->rlock){-.....}, at: [] sensor_hub_raw_event+0x40/0x204 : CPU: 0 PID: 0 Comm: swapper Not tainted 3.10.5-dockstar-00038-g03242d1-dirty #408 [] (unwind_backtrace+0x0/0xe0) from [] (show_stack+0x10/0x14) [] (show_stack+0x10/0x14) from [] (print_usage_bug.part.25+0x21c/0x284) [] (print_usage_bug.part.25+0x21c/0x284) from [] (mark_lock+0x438/0x65c) [] (mark_lock+0x438/0x65c) from [] (__lock_acquire+0x5b4/0x18f0) [] (__lock_acquire+0x5b4/0x18f0) from [] (lock_acquire+0x64/0x78) [] (lock_acquire+0x64/0x78) from [] (_raw_spin_lock+0x40/0x50) [] (_raw_spin_lock+0x40/0x50) from [] (sensor_hub_raw_event+0x10c/0x204) [] (sensor_hub_raw_event+0x10c/0x204) from [] (hid_input_report+0x148/0x170) [] (hid_input_report+0x148/0x170) from [] (hid_irq_in+0x98/0x228) [] (hid_irq_in+0x98/0x228) from [] (usb_hcd_giveback_urb+0x94/0xf0) [] (usb_hcd_giveback_urb+0x94/0xf0) from [] (ehci_urb_done+0x6c/0x78) [] (ehci_urb_done+0x6c/0x78) from [] (qh_completions+0x310/0x394) [] (qh_completions+0x310/0x394) from [] (ehci_work+0x14c/0x780) [] (ehci_work+0x14c/0x780) from [] (ehci_irq+0x21c/0x248) [] (ehci_irq+0x21c/0x248) from [] (usb_hcd_irq+0x38/0x6c) [] (usb_hcd_irq+0x38/0x6c) from [] (handle_irq_event_percpu+0x2c/0x1a4) [] (handle_irq_event_percpu+0x2c/0x1a4) from [] (handle_irq_event+0x3c/0x5c) [] (handle_irq_event+0x3c/0x5c) from [] (handle_level_irq+0xd0/0xe8) [] (handle_level_irq+0xd0/0xe8) from [] (generic_handle_irq+0x20/0x30) [] (generic_handle_irq+0x20/0x30) from [] (handle_IRQ+0x60/0x84) [] (handle_IRQ+0x60/0x84) from [] (__irq_svc+0x38/0xa0) [] (__irq_svc+0x38/0xa0) from [] (cpuidle_enter_state+0x60/0x100) [] (cpuidle_enter_state+0x60/0x100) from [] (cpuidle_idle_call+0xdc/0x144) [] (cpuidle_idle_call+0xdc/0x144) from [] (arch_cpu_idle+0x8/0x44) [] (arch_cpu_idle+0x8/0x44) from [] (cpu_startup_entry+0x80/0xec) [] (cpu_startup_entry+0x80/0xec) from [] (start_kernel+0x29c/0x2e4) ---------- -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/