On Tue, 4 Nov 2014, Sebastian Andrzej Siewior wrote: > I have two musb instances running in OTG. One instance is in device mode, > the other in host mode. I enable remote wakeup for both ports > (echo 1 > /sys/…/power/wakeup). On leaving suspend I see that the root-hub > is resumed twice. I added a printk to hub_activate to see the device > name and active-type + a WARN_ON(type == HUB_RESUME) and I see: > > |echo standby > /sys/power/state > | PM: Syncing filesystems ... done. > | PM: Preparing system for standby sleep > | Freezing user space processes ... (elapsed 0.001 seconds) done. > | Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done. > | PM: Entering standby sleep > | Suspending console(s) (use no_console_suspend to debug) > | PM: suspend of devices complete after 6.608 msecs > | PM: late suspend of devices complete after 0.890 msecs > | PM: noirq suspend of devices complete after 1.086 msecs > | PM: Successfully put all powerdomains to target state > | PM: Wakeup source UART > | PM: noirq resume of devices complete after 16.454 msecs > | PM: early resume of devices complete after 0.684 msecs > | hub_activate(1024) usb1 4 > | ------------[ cut here ]------------ > | WARNING: CPU: 0 PID: 761 at drivers/usb/core/hub.c:1025 hub_activate+0x4a4/0x4dc() > | CPU: 0 PID: 761 Comm: kworker/u2:2 Not tainted 3.14.23+ #287 > | Workqueue: events_unbound async_run_entry_fn > | [<c0013cdc>] (unwind_backtrace) from [<c00113f8>] (show_stack+0x10/0x14) > | [<c00113f8>] (show_stack) from [<c003fec0>] (warn_slowpath_common+0x68/0x88) > | [<c003fec0>] (warn_slowpath_common) from [<c003fefc>] (warn_slowpath_null+0x1c/0x24) > | [<c003fefc>] (warn_slowpath_null) from [<c043c588>] (hub_activate+0x4a4/0x4dc) > | [<c043c588>] (hub_activate) from [<c043c624>] (hub_resume+0x14/0x1c) > | [<c043c624>] (hub_resume) from [<c0446d54>] (usb_resume_interface.isra.2+0x100/0x140) > | [<c0446d54>] (usb_resume_interface.isra.2) from [<c0446e00>] (usb_resume_both+0x6c/0x13c) > | [<c0446e00>] (usb_resume_both) from [<c04476f4>] (usb_resume+0x14/0x60) > | [<c04476f4>] (usb_resume) from [<c0439cc8>] (usb_dev_resume+0xc/0x10) > | [<c0439cc8>] (usb_dev_resume) from [<c0391a9c>] (dpm_run_callback+0x34/0x70) > | [<c0391a9c>] (dpm_run_callback) from [<c0391b90>] (device_resume+0xb8/0x21c) > | [<c0391b90>] (device_resume) from [<c0391d0c>] (async_resume+0x18/0x44) > | [<c0391d0c>] (async_resume) from [<c005f42c>] (async_run_entry_fn+0x40/0x170) > | [<c005f42c>] (async_run_entry_fn) from [<c0054bf4>] (process_one_work+0x128/0x3b4) > | [<c0054bf4>] (process_one_work) from [<c0054fc0>] (worker_thread+0x10c/0x364) > | [<c0054fc0>] (worker_thread) from [<c005a534>] (kthread+0xbc/0xd8) > | [<c005a534>] (kthread) from [<c000e538>] (ret_from_fork+0x14/0x3c) > | ---[ end trace 005fc846a215a40c ]--- > | PM: Finishing wakeup. > | Restarting tasks ... > | hub_activate(1024) usb1 4 > | ------------[ cut here ]------------ > | WARNING: CPU: 0 PID: 372 at drivers/usb/core/hub.c:1025 hub_activate+0x4a4/0x4dc() > | CPU: 0 PID: 372 Comm: khubd Tainted: G W 3.14.23+ #287 > | [<c0013cdc>] (unwind_backtrace) from [<c00113f8>] (show_stack+0x10/0x14) > | [<c00113f8>] (show_stack) from [<c003fec0>] (warn_slowpath_common+0x68/0x88) > | [<c003fec0>] (warn_slowpath_common) from [<c003fefc>] (warn_slowpath_null+0x1c/0x24) > | [<c003fefc>] (warn_slowpath_null) from [<c043c588>] (hub_activate+0x4a4/0x4dc) > | [<c043c588>] (hub_activate) from [<c043c624>] (hub_resume+0x14/0x1c) > | [<c043c624>] (hub_resume) from [<c0446d54>] (usb_resume_interface.isra.2+0x100/0x140) > | [<c0446d54>] (usb_resume_interface.isra.2) from [<c0446e00>] (usb_resume_both+0x6c/0x13c) > | [<c0446e00>] (usb_resume_both) from [<c0447bec>] (usb_runtime_resume+0x10/0x14) > | [<c0447bec>] (usb_runtime_resume) from [<c0394468>] (rpm_callback+0x9c/0xb8) > | [<c0394468>] (rpm_callback) from [<c0395370>] (rpm_resume+0x330/0x560) > | [<c0395370>] (rpm_resume) from [<c0395238>] (rpm_resume+0x1f8/0x560) > | [<c0395238>] (rpm_resume) from [<c039579c>] (__pm_runtime_resume+0x18/0x40) > | [<c039579c>] (__pm_runtime_resume) from [<c0446510>] (usb_autopm_get_interface+0x18/0x5c) > | [<c0446510>] (usb_autopm_get_interface) from [<c043ecb4>] (hub_thread+0xf4/0x10c4) > | [<c043ecb4>] (hub_thread) from [<c005a534>] (kthread+0xbc/0xd8) > | [<c005a534>] (kthread) from [<c000e538>] (ret_from_fork+0x14/0x3c) > | ---[ end trace 005fc846a215a40e ]--- > | done. > | ------------[ cut here ]------------ > | WARNING: CPU: 0 PID: 372 at drivers/usb/core/urb.c:339 usb_submit_urb+0x494/0x4c8() > | URB ddd59f80 submitted while active > | CPU: 0 PID: 372 Comm: khubd Tainted: G W 3.14.23+ #287 > | [<c0013cdc>] (unwind_backtrace) from [<c00113f8>] (show_stack+0x10/0x14) > | [<c00113f8>] (show_stack) from [<c003fec0>] (warn_slowpath_common+0x68/0x88) > | [<c003fec0>] (warn_slowpath_common) from [<c003ff74>] (warn_slowpath_fmt+0x30/0x40) > | [<c003ff74>] (warn_slowpath_fmt) from [<c0443ec8>] (usb_submit_urb+0x494/0x4c8) > | [<c0443ec8>] (usb_submit_urb) from [<c043c308>] (hub_activate+0x224/0x4dc) > | [<c043c308>] (hub_activate) from [<c043c624>] (hub_resume+0x14/0x1c) > | [<c043c624>] (hub_resume) from [<c0446d54>] (usb_resume_interface.isra.2+0x100/0x140) > | [<c0446d54>] (usb_resume_interface.isra.2) from [<c0446e00>] (usb_resume_both+0x6c/0x13c) > | [<c0446e00>] (usb_resume_both) from [<c0447bec>] (usb_runtime_resume+0x10/0x14) > | [<c0447bec>] (usb_runtime_resume) from [<c0394468>] (rpm_callback+0x9c/0xb8) > | [<c0394468>] (rpm_callback) from [<c0395370>] (rpm_resume+0x330/0x560) > | [<c0395370>] (rpm_resume) from [<c0395238>] (rpm_resume+0x1f8/0x560) > | [<c0395238>] (rpm_resume) from [<c039579c>] (__pm_runtime_resume+0x18/0x40) > | [<c039579c>] (__pm_runtime_resume) from [<c0446510>] (usb_autopm_get_interface+0x18/0x5c) > | [<c0446510>] (usb_autopm_get_interface) from [<c043ecb4>] (hub_thread+0xf4/0x10c4) > | [<c043ecb4>] (hub_thread) from [<c005a534>] (kthread+0xbc/0xd8) > | [<c005a534>] (kthread) from [<c000e538>] (ret_from_fork+0x14/0x3c) > | ---[ end trace 005fc846a215a40f ]--- > | hub 1-0:1.0: activate --> -16 > > and I see the core resumes both hubs twice (I omitted usb2 here, the > call chain is the same) and the second resume leads to the real WARN_ON() > "URB X submitted while active". > The logic for the status hub is that it should be enqueued upon completion > so a second enqueue (which is dropped with -EBUSY) shouldn't do any harm > since it is still active from the last time. > Anyway, this does not look preety. Is there something that musb might do > wrong or is simply the second resume somehow bogus or should there been > a suspend in between which had to kill that URB? The last guess is probably correct. The only way you should ever get two resumes in a row like that is if there is a runtime suspend in between. Notice that the resumes occurred in two different threads: The first was in the async_run_entry_fn workqueue thread (part of system suspend/resume) and the second was in khubd (a runtime resume). The intervening runtime suspend should have killed the status URB, so it should not have been active when the runtime resume occurred. Now, maybe something went wrong somewhere. Perhaps the kernel thought that after the system resume, the root hub was still in runtime suspend. If that's true, we need to find out why and fix it. Alan Stern -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
