* `ohci_rh_resume()` called during `usb_dev_suspend()`
@ 2018-07-23 23:19 Paul Menzel
2018-07-24 14:21 ` Alan Stern
0 siblings, 1 reply; 4+ messages in thread
From: Paul Menzel @ 2018-07-23 23:19 UTC (permalink / raw)
To: Alan Stern; +Cc: linux-usb, linux-kernel
[-- Attachment #1: Type: text/plain, Size: 2542 bytes --]
Dear Linux folks,
Profiling the suspend to and resume/wake-up from ACPI S3 with
`sleepgraph.py` on an ASRock E350M1, I noticed that resume methods are
called during suspend.
Here is an excerpt from the callgraph.
> 600.376906 | 0) kworker-81 | | /* device_pm_callback_start: usb usb5, parent: 0000:00:14.5, type [suspend] */
> 600.376909 | 0) kworker-81 | | usb_dev_suspend() {
> 600.376911 | 0) kworker-81 | | usb_suspend() {
> 600.376913 | 0) kworker-81 | | __pm_runtime_resume() {
> 600.376915 | 0) kworker-81 | | _cond_resched() {
> 600.376917 | 0) kworker-81 | 0.565 us | rcu_all_qs();
> 600.376921 | 0) kworker-81 | 4.034 us | } /* _cond_resched */
> 600.376922 | 0) kworker-81 | 0.505 us | _raw_spin_lock_irqsave();
> 600.376926 | 0) kworker-81 | | rpm_resume() {
> 600.376928 | 0) kworker-81 | 0.573 us | _raw_spin_lock();
> 600.376934 | 0) kworker-81 | 0.706 us | rpm_resume();
> 600.376937 | 0) kworker-81 | 0.556 us | _raw_spin_lock();
> 600.376942 | 0) kworker-81 | 0.721 us | __rpm_get_callback();
> 600.376946 | 0) kworker-81 | 0.564 us | dev_pm_disable_wake_irq_check();
> 600.376949 | 0) kworker-81 | | rpm_callback() {
> 600.376952 | 0) kworker-81 | | __rpm_callback() {
> 600.376954 | 0) kworker-81 | | usb_runtime_resume() {
> 600.376956 | 0) kworker-81 | | usb_resume_both() {
> 600.376959 | 0) kworker-81 | | generic_resume() {
> 600.376960 | 0) kworker-81 | | hcd_bus_resume() {
> 600.376963 | 0) kworker-81 | | ohci_bus_resume [ohci_hcd]() {
> 600.376964 | 0) kworker-81 | 0.588 us | _raw_spin_lock_irq();
> 600.376968 | 0) kworker-81 | | ohci_rh_resume [ohci_hcd]() {
> 600.377043 | 0) kworker-81 | | msleep() {
Please find the full callgraph and the HTML output attached.
Is that expected?
Kind regards,
Paul
[1]: https://01.org/suspendresume
[-- Attachment #2: kodi_mem.html.7z --]
[-- Type: application/x-7z-compressed, Size: 41725 bytes --]
[-- Attachment #3: kodi_mem_ftrace-ohci.txt --]
[-- Type: text/plain, Size: 35634 bytes --]
600.376906 | 0) kworker-81 | | /* device_pm_callback_start: usb usb5, parent: 0000:00:14.5, type [suspend] */
600.376909 | 0) kworker-81 | | usb_dev_suspend() {
600.376911 | 0) kworker-81 | | usb_suspend() {
600.376913 | 0) kworker-81 | | __pm_runtime_resume() {
600.376915 | 0) kworker-81 | | _cond_resched() {
600.376917 | 0) kworker-81 | 0.565 us | rcu_all_qs();
600.376921 | 0) kworker-81 | 4.034 us | } /* _cond_resched */
600.376922 | 0) kworker-81 | 0.505 us | _raw_spin_lock_irqsave();
600.376926 | 0) kworker-81 | | rpm_resume() {
600.376928 | 0) kworker-81 | 0.573 us | _raw_spin_lock();
600.376934 | 0) kworker-81 | 0.706 us | rpm_resume();
600.376937 | 0) kworker-81 | 0.556 us | _raw_spin_lock();
600.376942 | 0) kworker-81 | 0.721 us | __rpm_get_callback();
600.376946 | 0) kworker-81 | 0.564 us | dev_pm_disable_wake_irq_check();
600.376949 | 0) kworker-81 | | rpm_callback() {
600.376952 | 0) kworker-81 | | __rpm_callback() {
600.376954 | 0) kworker-81 | | usb_runtime_resume() {
600.376956 | 0) kworker-81 | | usb_resume_both() {
600.376959 | 0) kworker-81 | | generic_resume() {
600.376960 | 0) kworker-81 | | hcd_bus_resume() {
600.376963 | 0) kworker-81 | | ohci_bus_resume [ohci_hcd]() {
600.376964 | 0) kworker-81 | 0.588 us | _raw_spin_lock_irq();
600.376968 | 0) kworker-81 | | ohci_rh_resume [ohci_hcd]() {
600.377043 | 0) kworker-81 | | msleep() {
600.377044 | 0) kworker-81 | 0.591 us | __msecs_to_jiffies();
600.377048 | 0) kworker-81 | | schedule_timeout() {
0) kworker-81 => kworker-434
1) sleepgr-779 => kworker-81
600.380611 | 1) kworker-81 | 3561.688 us | } /* schedule_timeout */
600.380613 | 1) kworker-81 | 3569.619 us | } /* msleep */
600.380625 | 1) kworker-81 | | msleep() {
600.380626 | 1) kworker-81 | 0.250 us | __msecs_to_jiffies();
600.380628 | 1) kworker-81 | | schedule_timeout() {
1) kworker-81 => kworker-434
0) kworker-787 => kworker-81
600.386557 | 0) kworker-81 | 5927.651 us | } /* schedule_timeout */
600.386560 | 0) kworker-81 | 5934.355 us | } /* msleep */
600.386565 | 0) kworker-81 | | msleep() {
600.386567 | 0) kworker-81 | 0.490 us | __msecs_to_jiffies();
600.386570 | 0) kworker-81 | | schedule_timeout() {
0) kworker-81 => kworker-434
0) kworker-434 => kworker-81
600.394208 | 0) kworker-81 | 7636.340 us | } /* schedule_timeout */
600.394211 | 0) kworker-81 | 7644.604 us | } /* msleep */
600.394212 | 0) kworker-81 | 0.687 us | _raw_spin_lock_irq();
600.394217 | 0) kworker-81 | 17247.00 us | } /* ohci_rh_resume [ohci_hcd] */
600.394218 | 0) kworker-81 | | usb_hcd_poll_rh_status() {
600.394220 | 0) kworker-81 | | ohci_hub_status_data [ohci_hcd]() {
600.394221 | 0) kworker-81 | 0.543 us | _raw_spin_lock_irqsave();
600.394301 | 0) kworker-81 | 65.859 us | _raw_spin_unlock_irqrestore();
600.394371 | 0) kworker-81 | 150.044 us | } /* ohci_hub_status_data [ohci_hcd] */
600.394373 | 0) kworker-81 | 153.600 us | } /* usb_hcd_poll_rh_status */
600.394375 | 0) kworker-81 | 17410.75 us | } /* ohci_bus_resume [ohci_hcd] */
600.394376 | 0) kworker-81 | 0.597 us | _raw_spin_lock_irq();
600.394380 | 0) kworker-81 | | usb_set_device_state() {
600.394382 | 0) kworker-81 | 0.499 us | _raw_spin_lock_irqsave();
600.394386 | 0) kworker-81 | 0.532 us | _raw_spin_unlock_irqrestore();
600.394389 | 0) kworker-81 | 7.880 us | } /* usb_set_device_state */
600.394391 | 0) kworker-81 | 1.164 us | usb_hub_find_child();
600.394395 | 0) kworker-81 | 0.621 us | usb_hub_find_child();
600.394399 | 0) kworker-81 | 0.514 us | usb_hub_find_child();
600.394403 | 0) kworker-81 | 17440.77 us | } /* hcd_bus_resume */
600.394404 | 0) kworker-81 | 17444.37 us | } /* generic_resume */
600.394406 | 0) kworker-81 | | usb_resume_interface.isra.4() {
600.394408 | 0) kworker-81 | | hub_resume() {
600.394410 | 0) kworker-81 | | hub_activate() {
600.394412 | 0) kworker-81 | | hub_ext_port_status() {
600.394413 | 0) kworker-81 | | mutex_lock() {
600.394415 | 0) kworker-81 | 0.695 us | _cond_resched();
600.394419 | 0) kworker-81 | 4.112 us | } /* mutex_lock */
600.394421 | 0) kworker-81 | | usb_control_msg() {
600.394422 | 0) kworker-81 | 22.651 us | kmem_cache_alloc_trace();
600.394449 | 0) kworker-81 | 24.147 us | usb_alloc_urb();
600.394477 | 0) kworker-81 | 486.801 us | usb_start_wait_urb();
600.394968 | 0) kworker-81 | 3.343 us | kfree();
600.394975 | 0) kworker-81 | 553.075 us | } /* usb_control_msg */
600.394977 | 0) kworker-81 | 0.558 us | mutex_unlock();
600.394981 | 0) kworker-81 | 567.881 us | } /* hub_ext_port_status */
600.394984 | 0) kworker-81 | | hub_ext_port_status() {
600.394985 | 0) kworker-81 | | mutex_lock() {
600.394987 | 0) kworker-81 | 0.722 us | _cond_resched();
600.394991 | 0) kworker-81 | 4.213 us | } /* mutex_lock */
600.394993 | 0) kworker-81 | | usb_control_msg() {
600.394994 | 0) kworker-81 | 21.092 us | kmem_cache_alloc_trace();
600.395019 | 0) kworker-81 | 20.009 us | usb_alloc_urb();
600.395042 | 0) kworker-81 | | usb_start_wait_urb() {
0) kworker-81 => kworker-434
0) kworker-787 => kworker-81
600.396526 | 0) kworker-81 | 1481.933 us | } /* usb_start_wait_urb */
600.396528 | 0) kworker-81 | 3.372 us | kfree();
600.396534 | 0) kworker-81 | 1540.251 us | } /* usb_control_msg */
600.396536 | 0) kworker-81 | 0.520 us | mutex_unlock();
600.396540 | 0) kworker-81 | 1555.112 us | } /* hub_ext_port_status */
600.396542 | 0) kworker-81 | | usb_submit_urb() {
600.396545 | 0) kworker-81 | 0.526 us | usb_urb_ep_type_check();
600.396549 | 0) kworker-81 | | usb_hcd_submit_urb() {
600.396550 | 0) kworker-81 | 0.510 us | usb_get_urb();
600.396554 | 0) kworker-81 | 0.585 us | _raw_spin_lock_irqsave();
600.396558 | 0) kworker-81 | 0.891 us | usb_hcd_link_urb_to_ep();
600.396562 | 0) kworker-81 | 0.511 us | _raw_spin_unlock_irqrestore();
600.396566 | 0) kworker-81 | 15.791 us | } /* usb_hcd_submit_urb */
600.396568 | 0) kworker-81 | 23.948 us | } /* usb_submit_urb */
600.396571 | 0) kworker-81 | | kick_hub_wq.part.9() {
600.396573 | 0) kworker-81 | 0.701 us | usb_autopm_get_interface_no_resume();
600.396577 | 0) kworker-81 | | queue_work_on() {
600.396579 | 0) kworker-81 | 10.675 us | __queue_work();
600.396593 | 0) kworker-81 | 14.645 us | } /* queue_work_on */
600.396595 | 0) kworker-81 | 22.325 us | } /* kick_hub_wq.part.9 */
600.396597 | 0) kworker-81 | 2185.388 us | } /* hub_activate */
600.396599 | 0) kworker-81 | 2189.006 us | } /* hub_resume */
600.396600 | 0) kworker-81 | 2192.768 us | } /* usb_resume_interface.isra.4 */
600.396602 | 0) kworker-81 | 19644.93 us | } /* usb_resume_both */
600.396604 | 0) kworker-81 | 19648.63 us | } /* usb_runtime_resume */
600.396606 | 0) kworker-81 | 0.558 us | _raw_spin_lock_irq();
600.396610 | 0) kworker-81 | 19657.32 us | } /* __rpm_callback */
600.396612 | 0) kworker-81 | 19661.36 us | } /* rpm_callback */
600.396615 | 0) kworker-81 | | __wake_up() {
600.396616 | 0) kworker-81 | | __wake_up_common_lock() {
600.396618 | 0) kworker-81 | 0.514 us | _raw_spin_lock_irqsave();
600.396621 | 0) kworker-81 | 0.709 us | __wake_up_common();
600.396625 | 0) kworker-81 | 0.547 us | _raw_spin_unlock_irqrestore();
600.396629 | 0) kworker-81 | 11.214 us | } /* __wake_up_common_lock */
600.396631 | 0) kworker-81 | 14.627 us | } /* __wake_up */
600.396633 | 0) kworker-81 | | rpm_idle() {
600.396634 | 0) kworker-81 | 0.801 us | rpm_check_suspend_allowed();
600.396639 | 0) kworker-81 | 4.396 us | } /* rpm_idle */
600.396640 | 0) kworker-81 | 0.661 us | __pm_runtime_idle();
600.396644 | 0) kworker-81 | 0.522 us | _raw_spin_lock_irq();
600.396648 | 0) kworker-81 | 19720.92 us | } /* rpm_resume */
600.396650 | 0) kworker-81 | 0.579 us | _raw_spin_unlock_irqrestore();
600.396654 | 0) kworker-81 | 19739.29 us | } /* __pm_runtime_resume */
600.396656 | 0) kworker-81 | | usb_suspend_both() {
600.396658 | 0) kworker-81 | | hub_suspend() {
600.396661 | 0) kworker-81 | | hub_quiesce() {
600.396662 | 0) kworker-81 | | usb_kill_urb() {
600.396664 | 0) kworker-81 | | _cond_resched() {
600.396666 | 0) kworker-81 | 0.540 us | rcu_all_qs();
600.396670 | 0) kworker-81 | 4.762 us | } /* _cond_resched */
600.396672 | 0) kworker-81 | | usb_hcd_unlink_urb() {
600.396674 | 0) kworker-81 | 0.567 us | _raw_spin_lock_irqsave();
600.396678 | 0) kworker-81 | | usb_get_dev() {
600.396680 | 0) kworker-81 | 0.585 us | get_device();
600.396684 | 0) kworker-81 | 4.349 us | } /* usb_get_dev */
600.396685 | 0) kworker-81 | 0.617 us | _raw_spin_unlock_irqrestore();
600.396689 | 0) kworker-81 | | unlink1() {
600.396691 | 0) kworker-81 | 0.573 us | _raw_spin_lock_irqsave();
600.396695 | 0) kworker-81 | | usb_hcd_unlink_urb_from_ep() {
600.396697 | 0) kworker-81 | 0.490 us | _raw_spin_lock();
600.396701 | 0) kworker-81 | 4.046 us | } /* usb_hcd_unlink_urb_from_ep */
600.396702 | 0) kworker-81 | | usb_hcd_giveback_urb() {
600.396704 | 0) kworker-81 | 0.478 us | _raw_spin_lock();
600.396708 | 0) kworker-81 | | __tasklet_hi_schedule() {
600.396709 | 0) kworker-81 | | __tasklet_schedule_common() {
600.396711 | 0) kworker-81 | 0.489 us | __raise_softirq_irqoff();
600.396715 | 0) kworker-81 | | wakeup_softirqd() {
600.396717 | 0) kworker-81 | | wake_up_process() {
600.396718 | 0) kworker-81 | 6.689 us | try_to_wake_up();
600.396728 | 0) kworker-81 | 10.227 us | } /* wake_up_process */
600.396730 | 0) kworker-81 | 13.870 us | } /* wakeup_softirqd */
600.396732 | 0) kworker-81 | 21.150 us | } /* __tasklet_schedule_common */
600.396734 | 0) kworker-81 | 24.620 us | } /* __tasklet_hi_schedule */
600.396735 | 0) kworker-81 | 31.807 us | } /* usb_hcd_giveback_urb */
600.396737 | 0) kworker-81 | 0.558 us | _raw_spin_unlock_irqrestore();
600.396741 | 0) kworker-81 | 50.480 us | } /* unlink1 */
600.396743 | 0) kworker-81 | | usb_put_dev() {
600.396744 | 0) kworker-81 | 0.620 us | put_device();
600.396748 | 0) kworker-81 | 4.316 us | } /* usb_put_dev */
600.396750 | 0) kworker-81 | 76.464 us | } /* usb_hcd_unlink_urb */
600.396752 | 0) kworker-81 | | _cond_resched() {
600.396754 | 0) kworker-81 | 0.493 us | rcu_all_qs();
600.396757 | 0) kworker-81 | 3.960 us | } /* _cond_resched */
600.396759 | 0) kworker-81 | 0.561 us | init_wait_entry();
600.396763 | 0) kworker-81 | | prepare_to_wait_event() {
600.396764 | 0) kworker-81 | 0.733 us | _raw_spin_lock_irqsave();
600.396768 | 0) kworker-81 | 0.582 us | _raw_spin_unlock_irqrestore();
600.396772 | 0) kworker-81 | 7.802 us | } /* prepare_to_wait_event */
600.396774 | 0) kworker-81 | | schedule() {
600.396776 | 0) kworker-81 | | rcu_note_context_switch() {
600.396777 | 0) kworker-81 | 0.495 us | rcu_sched_qs();
600.396781 | 0) kworker-81 | 4.024 us | } /* rcu_note_context_switch */
600.396783 | 0) kworker-81 | 0.493 us | _raw_spin_lock();
600.396786 | 0) kworker-81 | 0.923 us | update_rq_clock();
600.396790 | 0) kworker-81 | | deactivate_task() {
600.396793 | 0) kworker-81 | | dequeue_task_fair() {
600.396795 | 0) kworker-81 | | dequeue_entity() {
600.396796 | 0) kworker-81 | | update_curr() {
600.396798 | 0) kworker-81 | 0.528 us | update_min_vruntime();
600.396802 | 0) kworker-81 | 0.537 us | cpuacct_charge();
600.396805 | 0) kworker-81 | 7.724 us | } /* update_curr */
600.396807 | 0) kworker-81 | 0.600 us | __update_load_avg_se.isra.21();
600.396811 | 0) kworker-81 | 0.591 us | __update_load_avg_cfs_rq.isra.22();
600.396815 | 0) kworker-81 | 0.561 us | clear_buddies();
600.396818 | 0) kworker-81 | 0.608 us | account_entity_dequeue();
600.396822 | 0) kworker-81 | 0.531 us | update_cfs_group();
600.396825 | 0) kworker-81 | 29.358 us | } /* dequeue_entity */
600.396827 | 0) kworker-81 | 0.469 us | hrtick_update();
600.396832 | 0) kworker-81 | 37.247 us | } /* dequeue_task_fair */
600.396834 | 0) kworker-81 | 41.369 us | } /* deactivate_task */
600.396835 | 0) kworker-81 | | wq_worker_sleeping() {
600.396837 | 0) kworker-81 | 0.507 us | kthread_data();
600.396842 | 0) kworker-81 | 4.026 us | } /* wq_worker_sleeping */
600.396844 | 0) kworker-81 | | pick_next_task_fair() {
600.396846 | 0) kworker-81 | 0.490 us | check_cfs_rq_runtime();
600.396849 | 0) kworker-81 | | pick_next_entity() {
600.396851 | 0) kworker-81 | 0.508 us | clear_buddies();
600.396855 | 0) kworker-81 | 4.061 us | } /* pick_next_entity */
600.396857 | 0) kworker-81 | | put_prev_entity() {
600.396859 | 0) kworker-81 | 0.483 us | check_cfs_rq_runtime();
600.396863 | 0) kworker-81 | 4.064 us | } /* put_prev_entity */
600.396864 | 0) kworker-81 | | set_next_entity() {
600.396867 | 0) kworker-81 | 0.606 us | __update_load_avg_se.isra.21();
600.396870 | 0) kworker-81 | 0.556 us | __update_load_avg_cfs_rq.isra.22();
600.396874 | 0) kworker-81 | 8.356 us | } /* set_next_entity */
600.396876 | 0) kworker-81 | 30.584 us | } /* pick_next_task_fair */
600.396879 | 0) kworker-81 | 0.501 us | enter_lazy_tlb();
0) kworker-81 => kworker-434
0) kworker-434 => kworker-81
600.397304 | 0) kworker-81 | | finish_task_switch() {
600.397307 | 0) kworker-81 | ==========> |
600.397307 | 0) kworker-81 | | smp_apic_timer_interrupt() {
600.397309 | 0) kworker-81 | | irq_enter() {
600.397310 | 0) kworker-81 | | rcu_irq_enter() {
600.397312 | 0) kworker-81 | 0.555 us | rcu_nmi_enter();
600.397316 | 0) kworker-81 | 4.100 us | } /* rcu_irq_enter */
600.397318 | 0) kworker-81 | 0.760 us | irqtime_account_irq();
600.397322 | 0) kworker-81 | 11.439 us | } /* irq_enter */
600.397323 | 0) kworker-81 | | hrtimer_interrupt() {
600.397325 | 0) kworker-81 | 0.508 us | _raw_spin_lock_irqsave();
600.397329 | 0) kworker-81 | 0.837 us | ktime_get_update_offsets_now();
600.397332 | 0) kworker-81 | | __hrtimer_run_queues() {
600.397334 | 0) kworker-81 | 0.516 us | __next_base();
600.397338 | 0) kworker-81 | 0.867 us | __remove_hrtimer();
600.397341 | 0) kworker-81 | 0.540 us | _raw_spin_unlock_irqrestore();
600.397345 | 0) kworker-81 | | tick_sched_timer() {
600.397347 | 0) kworker-81 | 0.688 us | ktime_get();
600.397351 | 0) kworker-81 | | tick_sched_do_timer() {
600.397352 | 0) kworker-81 | 5.011 us | tick_do_update_jiffies64.part.5();
600.397361 | 0) kworker-81 | 8.903 us | } /* tick_sched_do_timer */
600.397363 | 0) kworker-81 | | tick_sched_handle() {
600.397364 | 0) kworker-81 | 9.874 us | update_process_times();
600.397377 | 0) kworker-81 | 0.537 us | profile_tick();
600.397381 | 0) kworker-81 | 17.055 us | } /* tick_sched_handle */
600.397383 | 0) kworker-81 | 0.605 us | hrtimer_forward();
600.397386 | 0) kworker-81 | 39.630 us | } /* tick_sched_timer */
600.397388 | 0) kworker-81 | 0.529 us | _raw_spin_lock_irq();
600.397391 | 0) kworker-81 | 0.917 us | enqueue_hrtimer();
600.397395 | 0) kworker-81 | 0.529 us | __next_base();
600.397399 | 0) kworker-81 | 0.517 us | __next_base();
600.397402 | 0) kworker-81 | 0.531 us | __next_base();
600.397406 | 0) kworker-81 | 72.143 us | } /* __hrtimer_run_queues */
600.397407 | 0) kworker-81 | | __hrtimer_get_next_event() {
600.397409 | 0) kworker-81 | | __hrtimer_next_event_base() {
600.397411 | 0) kworker-81 | 0.522 us | __next_base();
600.397414 | 0) kworker-81 | 3.678 us | } /* __hrtimer_next_event_base */
600.397416 | 0) kworker-81 | | __hrtimer_next_event_base() {
600.397417 | 0) kworker-81 | 0.505 us | __next_base();
600.397420 | 0) kworker-81 | 0.504 us | __next_base();
600.397424 | 0) kworker-81 | 0.505 us | __next_base();
600.397427 | 0) kworker-81 | 0.510 us | __next_base();
600.397430 | 0) kworker-81 | 13.422 us | } /* __hrtimer_next_event_base */
600.397432 | 0) kworker-81 | 23.157 us | } /* __hrtimer_get_next_event */
600.397433 | 0) kworker-81 | 0.525 us | _raw_spin_unlock_irqrestore();
600.397437 | 0) kworker-81 | | tick_program_event() {
600.397438 | 0) kworker-81 | | clockevents_program_event() {
600.397440 | 0) kworker-81 | 0.680 us | ktime_get();
600.397444 | 0) kworker-81 | 0.695 us | lapic_next_event();
600.397448 | 0) kworker-81 | 7.802 us | } /* clockevents_program_event */
600.397449 | 0) kworker-81 | 11.130 us | } /* tick_program_event */
600.397451 | 0) kworker-81 | 125.887 us | } /* hrtimer_interrupt */
600.397452 | 0) kworker-81 | | irq_exit() {
600.397454 | 0) kworker-81 | 0.804 us | irqtime_account_irq();
600.397458 | 0) kworker-81 | | do_softirq_own_stack() {
600.397460 | 0) kworker-81 | | call_on_stack() {
600.397462 | 0) kworker-81 | | __do_softirq() {
600.397464 | 0) kworker-81 | 0.766 us | irqtime_account_irq();
600.397467 | 0) kworker-81 | 1.262 us | run_timer_softirq();
600.397472 | 0) kworker-81 | 0.484 us | rcu_bh_qs();
600.397475 | 0) kworker-81 | 0.855 us | irqtime_account_irq();
600.397479 | 0) kworker-81 | 15.082 us | } /* __do_softirq */
600.397480 | 0) kworker-81 | 18.533 us | } /* call_on_stack */
600.397482 | 0) kworker-81 | 23.118 us | } /* do_softirq_own_stack */
600.397484 | 0) kworker-81 | 0.502 us | idle_cpu();
600.397487 | 0) kworker-81 | | rcu_irq_exit() {
600.397489 | 0) kworker-81 | 0.528 us | rcu_nmi_exit();
600.397492 | 0) kworker-81 | 3.782 us | } /* rcu_irq_exit */
600.397494 | 0) kworker-81 | 40.070 us | } /* irq_exit */
600.397496 | 0) kworker-81 | 187.073 us | } /* smp_apic_timer_interrupt */
600.397496 | 0) kworker-81 | <========== |
600.397498 | 0) kworker-81 | 192.165 us | } /* finish_task_switch */
600.397500 | 0) kworker-81 | 724.625 us | } /* schedule */
600.397501 | 0) kworker-81 | | prepare_to_wait_event() {
600.397503 | 0) kworker-81 | 0.534 us | _raw_spin_lock_irqsave();
600.397506 | 0) kworker-81 | 0.544 us | _raw_spin_unlock_irqrestore();
600.397510 | 0) kworker-81 | 7.472 us | } /* prepare_to_wait_event */
600.397512 | 0) kworker-81 | | finish_wait() {
600.397513 | 0) kworker-81 | 0.505 us | _raw_spin_lock_irqsave();
600.397517 | 0) kworker-81 | 0.522 us | _raw_spin_unlock_irqrestore();
600.397520 | 0) kworker-81 | 7.139 us | } /* finish_wait */
600.397522 | 0) kworker-81 | 857.975 us | } /* usb_kill_urb */
600.397524 | 0) kworker-81 | 861.707 us | } /* hub_quiesce */
600.397526 | 0) kworker-81 | 865.786 us | } /* hub_suspend */
600.397528 | 0) kworker-81 | | generic_suspend() {
600.397529 | 0) kworker-81 | | hcd_bus_suspend() {
600.397531 | 0) kworker-81 | | ohci_bus_suspend [ohci_hcd]() {
600.397533 | 0) kworker-81 | 0.617 us | _raw_spin_lock_irq();
600.397537 | 0) kworker-81 | | ohci_rh_suspend [ohci_hcd]() {
600.397540 | 0) kworker-81 | 0.985 us | update_done_list [ohci_hcd]();
600.397544 | 0) kworker-81 | 0.959 us | ohci_work.part.13 [ohci_hcd]();
600.397554 | 0) kworker-81 | 15.217 us | } /* ohci_rh_suspend [ohci_hcd] */
600.397555 | 0) kworker-81 | | del_timer_sync() {
600.397557 | 0) kworker-81 | | try_to_del_timer_sync() {
600.397559 | 0) kworker-81 | | lock_timer_base() {
600.397560 | 0) kworker-81 | 0.563 us | _raw_spin_lock_irqsave();
600.397564 | 0) kworker-81 | 3.844 us | } /* lock_timer_base */
600.397565 | 0) kworker-81 | 0.546 us | detach_if_pending();
600.397568 | 0) kworker-81 | 0.499 us | _raw_spin_unlock_irqrestore();
600.397572 | 0) kworker-81 | 13.834 us | } /* try_to_del_timer_sync */
600.397574 | 0) kworker-81 | 17.070 us | } /* del_timer_sync */
600.397576 | 0) kworker-81 | 42.649 us | } /* ohci_bus_suspend [ohci_hcd] */
600.397577 | 0) kworker-81 | | usb_set_device_state() {
600.397579 | 0) kworker-81 | 0.490 us | _raw_spin_lock_irqsave();
600.397582 | 0) kworker-81 | 0.576 us | _raw_spin_unlock_irqrestore();
600.397586 | 0) kworker-81 | 7.235 us | } /* usb_set_device_state */
600.397588 | 0) kworker-81 | | usb_phy_roothub_suspend() {
600.397589 | 0) kworker-81 | 0.478 us | usb_phy_roothub_power_off();
600.397593 | 0) kworker-81 | 3.791 us | } /* usb_phy_roothub_suspend */
600.397595 | 0) kworker-81 | 63.831 us | } /* hcd_bus_suspend */
600.397596 | 0) kworker-81 | 67.338 us | } /* generic_suspend */
600.397598 | 0) kworker-81 | | usb_hcd_flush_endpoint() {
600.397600 | 0) kworker-81 | | _cond_resched() {
600.397601 | 0) kworker-81 | 0.487 us | rcu_all_qs();
600.397605 | 0) kworker-81 | 3.954 us | } /* _cond_resched */
600.397607 | 0) kworker-81 | 0.653 us | _raw_spin_lock_irq();
600.397611 | 0) kworker-81 | 11.733 us | } /* usb_hcd_flush_endpoint */
600.397613 | 0) kworker-81 | | usb_hcd_flush_endpoint() {
600.397614 | 0) kworker-81 | | _cond_resched() {
600.397616 | 0) kworker-81 | 0.492 us | rcu_all_qs();
600.397619 | 0) kworker-81 | 3.690 us | } /* _cond_resched */
600.397621 | 0) kworker-81 | 0.499 us | _raw_spin_lock_irq();
600.397624 | 0) kworker-81 | 10.322 us | } /* usb_hcd_flush_endpoint */
600.397626 | 0) kworker-81 | 0.555 us | usb_hcd_flush_endpoint();
600.397629 | 0) kworker-81 | | usb_hcd_flush_endpoint() {
600.397631 | 0) kworker-81 | | _cond_resched() {
600.397632 | 0) kworker-81 | 0.496 us | rcu_all_qs();
600.397636 | 0) kworker-81 | 3.955 us | } /* _cond_resched */
600.397637 | 0) kworker-81 | 0.520 us | _raw_spin_lock_irq();
600.397641 | 0) kworker-81 | 10.904 us | } /* usb_hcd_flush_endpoint */
600.397643 | 0) kworker-81 | 0.520 us | usb_hcd_flush_endpoint();
600.397646 | 0) kworker-81 | 0.510 us | usb_hcd_flush_endpoint();
600.397649 | 0) kworker-81 | 0.513 us | usb_hcd_flush_endpoint();
600.397652 | 0) kworker-81 | 0.514 us | usb_hcd_flush_endpoint();
600.397655 | 0) kworker-81 | 0.520 us | usb_hcd_flush_endpoint();
600.397659 | 0) kworker-81 | 0.513 us | usb_hcd_flush_endpoint();
600.397662 | 0) kworker-81 | 0.519 us | usb_hcd_flush_endpoint();
600.397665 | 0) kworker-81 | 0.535 us | usb_hcd_flush_endpoint();
600.397668 | 0) kworker-81 | 0.505 us | usb_hcd_flush_endpoint();
600.397672 | 0) kworker-81 | 0.514 us | usb_hcd_flush_endpoint();
600.397675 | 0) kworker-81 | 0.511 us | usb_hcd_flush_endpoint();
600.397678 | 0) kworker-81 | 0.514 us | usb_hcd_flush_endpoint();
600.397682 | 0) kworker-81 | 0.511 us | usb_hcd_flush_endpoint();
600.397685 | 0) kworker-81 | 0.514 us | usb_hcd_flush_endpoint();
600.397688 | 0) kworker-81 | 0.511 us | usb_hcd_flush_endpoint();
600.397691 | 0) kworker-81 | 0.514 us | usb_hcd_flush_endpoint();
600.397694 | 0) kworker-81 | 0.510 us | usb_hcd_flush_endpoint();
600.397699 | 0) kworker-81 | 0.514 us | usb_hcd_flush_endpoint();
600.397702 | 0) kworker-81 | 0.517 us | usb_hcd_flush_endpoint();
600.397706 | 0) kworker-81 | 0.490 us | usb_hcd_flush_endpoint();
600.397710 | 0) kworker-81 | 0.511 us | usb_hcd_flush_endpoint();
600.397713 | 0) kworker-81 | 0.513 us | usb_hcd_flush_endpoint();
600.397716 | 0) kworker-81 | 0.546 us | usb_hcd_flush_endpoint();
600.397719 | 0) kworker-81 | 0.510 us | usb_hcd_flush_endpoint();
600.397722 | 0) kworker-81 | 0.543 us | usb_hcd_flush_endpoint();
600.397726 | 0) kworker-81 | 0.510 us | usb_hcd_flush_endpoint();
600.397729 | 0) kworker-81 | 0.536 us | usb_hcd_flush_endpoint();
600.397732 | 0) kworker-81 | 0.494 us | usb_hcd_flush_endpoint();
600.397736 | 0) kworker-81 | 1078.699 us | } /* usb_suspend_both */
600.397738 | 0) kworker-81 | 20825.76 us | } /* usb_suspend */
600.397740 | 0) kworker-81 | 20829.27 us | } /* usb_dev_suspend */
600.397742 | 0) kworker-81 | 0.543 us | dev_driver_string();
600.397746 | 0) kworker-81 | 0.514 us | dev_driver_string();
600.397749 | 0) kworker-81 | | /* device_pm_callback_end: usb usb5, err=0 */
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: `ohci_rh_resume()` called during `usb_dev_suspend()`
2018-07-23 23:19 `ohci_rh_resume()` called during `usb_dev_suspend()` Paul Menzel
@ 2018-07-24 14:21 ` Alan Stern
2018-07-24 14:30 ` Paul Menzel
0 siblings, 1 reply; 4+ messages in thread
From: Alan Stern @ 2018-07-24 14:21 UTC (permalink / raw)
To: Paul Menzel; +Cc: linux-usb, linux-kernel
On Tue, 24 Jul 2018, Paul Menzel wrote:
> Dear Linux folks,
>
>
> Profiling the suspend to and resume/wake-up from ACPI S3 with
> `sleepgraph.py` on an ASRock E350M1, I noticed that resume methods are
> called during suspend.
>
> Here is an excerpt from the callgraph.
>
> > 600.376906 | 0) kworker-81 | | /* device_pm_callback_start: usb usb5, parent: 0000:00:14.5, type [suspend] */
> > 600.376909 | 0) kworker-81 | | usb_dev_suspend() {
> > 600.376911 | 0) kworker-81 | | usb_suspend() {
> > 600.376913 | 0) kworker-81 | | __pm_runtime_resume() {
> > 600.376915 | 0) kworker-81 | | _cond_resched() {
> > 600.376917 | 0) kworker-81 | 0.565 us | rcu_all_qs();
> > 600.376921 | 0) kworker-81 | 4.034 us | } /* _cond_resched */
> > 600.376922 | 0) kworker-81 | 0.505 us | _raw_spin_lock_irqsave();
> > 600.376926 | 0) kworker-81 | | rpm_resume() {
> > 600.376928 | 0) kworker-81 | 0.573 us | _raw_spin_lock();
> > 600.376934 | 0) kworker-81 | 0.706 us | rpm_resume();
> > 600.376937 | 0) kworker-81 | 0.556 us | _raw_spin_lock();
> > 600.376942 | 0) kworker-81 | 0.721 us | __rpm_get_callback();
> > 600.376946 | 0) kworker-81 | 0.564 us | dev_pm_disable_wake_irq_check();
> > 600.376949 | 0) kworker-81 | | rpm_callback() {
> > 600.376952 | 0) kworker-81 | | __rpm_callback() {
> > 600.376954 | 0) kworker-81 | | usb_runtime_resume() {
> > 600.376956 | 0) kworker-81 | | usb_resume_both() {
> > 600.376959 | 0) kworker-81 | | generic_resume() {
> > 600.376960 | 0) kworker-81 | | hcd_bus_resume() {
> > 600.376963 | 0) kworker-81 | | ohci_bus_resume [ohci_hcd]() {
> > 600.376964 | 0) kworker-81 | 0.588 us | _raw_spin_lock_irq();
> > 600.376968 | 0) kworker-81 | | ohci_rh_resume [ohci_hcd]() {
> > 600.377043 | 0) kworker-81 | | msleep() {
>
> Please find the full callgraph and the HTML output attached.
>
> Is that expected?
I can't tell exactly what's happening from your callgraph and HTML, but
yes, in general it is expected.
The reason is because some devices have different wakeup settings for
runtime suspend and system suspend: A device that is enabled for wakeup
signalling during runtime suspend often is not enabled for wakeup
during system suspend.
As a result, the device's wakeup setting has to be changed when the
system goes to sleep, and to do that, we have to wake the device up
temporarily if it is already in runtime suspend.
Alan Stern
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: `ohci_rh_resume()` called during `usb_dev_suspend()`
2018-07-24 14:21 ` Alan Stern
@ 2018-07-24 14:30 ` Paul Menzel
2018-07-24 14:59 ` Alan Stern
0 siblings, 1 reply; 4+ messages in thread
From: Paul Menzel @ 2018-07-24 14:30 UTC (permalink / raw)
To: Alan Stern; +Cc: linux-usb, linux-kernel
[-- Attachment #1: Type: text/plain, Size: 3694 bytes --]
Dear Alan,
Thank you for your quick response.
On 07/24/18 16:21, Alan Stern wrote:
> On Tue, 24 Jul 2018, Paul Menzel wrote:
>> Profiling the suspend to and resume/wake-up from ACPI S3 with
>> `sleepgraph.py` on an ASRock E350M1, I noticed that resume methods are
>> called during suspend.
>>
>> Here is an excerpt from the callgraph.
>>
>>> 600.376906 | 0) kworker-81 | | /* device_pm_callback_start: usb usb5, parent: 0000:00:14.5, type [suspend] */
>>> 600.376909 | 0) kworker-81 | | usb_dev_suspend() {
>>> 600.376911 | 0) kworker-81 | | usb_suspend() {
>>> 600.376913 | 0) kworker-81 | | __pm_runtime_resume() {
>>> 600.376915 | 0) kworker-81 | | _cond_resched() {
>>> 600.376917 | 0) kworker-81 | 0.565 us | rcu_all_qs();
>>> 600.376921 | 0) kworker-81 | 4.034 us | } /* _cond_resched */
>>> 600.376922 | 0) kworker-81 | 0.505 us | _raw_spin_lock_irqsave();
>>> 600.376926 | 0) kworker-81 | | rpm_resume() {
>>> 600.376928 | 0) kworker-81 | 0.573 us | _raw_spin_lock();
>>> 600.376934 | 0) kworker-81 | 0.706 us | rpm_resume();
>>> 600.376937 | 0) kworker-81 | 0.556 us | _raw_spin_lock();
>>> 600.376942 | 0) kworker-81 | 0.721 us | __rpm_get_callback();
>>> 600.376946 | 0) kworker-81 | 0.564 us | dev_pm_disable_wake_irq_check();
>>> 600.376949 | 0) kworker-81 | | rpm_callback() {
>>> 600.376952 | 0) kworker-81 | | __rpm_callback() {
>>> 600.376954 | 0) kworker-81 | | usb_runtime_resume() {
>>> 600.376956 | 0) kworker-81 | | usb_resume_both() {
>>> 600.376959 | 0) kworker-81 | | generic_resume() {
>>> 600.376960 | 0) kworker-81 | | hcd_bus_resume() {
>>> 600.376963 | 0) kworker-81 | | ohci_bus_resume [ohci_hcd]() {
>>> 600.376964 | 0) kworker-81 | 0.588 us | _raw_spin_lock_irq();
>>> 600.376968 | 0) kworker-81 | | ohci_rh_resume [ohci_hcd]() {
>>> 600.377043 | 0) kworker-81 | | msleep() {
>>
>> Please find the full callgraph and the HTML output attached.
>>
>> Is that expected?
>
> I can't tell exactly what's happening from your callgraph and HTML, but
> yes, in general it is expected.
>
> The reason is because some devices have different wakeup settings for
> runtime suspend and system suspend: A device that is enabled for wakeup
> signalling during runtime suspend often is not enabled for wakeup
> during system suspend.
>
> As a result, the device's wakeup setting has to be changed when the
> system goes to sleep, and to do that, we have to wake the device up
> temporarily if it is already in runtime suspend.
Understood. Thank you for the explanation.
Sorry for being ignorant, but I have two more questions.
1. Should this also happen, if no USB device is connected to a hub?
2. If somebody point me to the code, how the callback(?)
`pm_runtime_resume()` is hooked up in `usb_suspend()` that’d help
me to better understand, what is going on.
Kind regards and thank you very much in advance,
Paul
[-- Attachment #2: S/MIME Cryptographic Signature --]
[-- Type: application/pkcs7-signature, Size: 5174 bytes --]
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: `ohci_rh_resume()` called during `usb_dev_suspend()`
2018-07-24 14:30 ` Paul Menzel
@ 2018-07-24 14:59 ` Alan Stern
0 siblings, 0 replies; 4+ messages in thread
From: Alan Stern @ 2018-07-24 14:59 UTC (permalink / raw)
To: Paul Menzel; +Cc: linux-usb, linux-kernel
On Tue, 24 Jul 2018, Paul Menzel wrote:
> Dear Alan,
>
>
> Thank you for your quick response.
>
> On 07/24/18 16:21, Alan Stern wrote:
> > On Tue, 24 Jul 2018, Paul Menzel wrote:
>
> >> Profiling the suspend to and resume/wake-up from ACPI S3 with
> >> `sleepgraph.py` on an ASRock E350M1, I noticed that resume methods are
> >> called during suspend.
> >>
> >> Here is an excerpt from the callgraph.
> >>
> >>> 600.376906 | 0) kworker-81 | | /* device_pm_callback_start: usb usb5, parent: 0000:00:14.5, type [suspend] */
> >>> 600.376909 | 0) kworker-81 | | usb_dev_suspend() {
> >>> 600.376911 | 0) kworker-81 | | usb_suspend() {
> >>> 600.376913 | 0) kworker-81 | | __pm_runtime_resume() {
> >>> 600.376915 | 0) kworker-81 | | _cond_resched() {
> >>> 600.376917 | 0) kworker-81 | 0.565 us | rcu_all_qs();
> >>> 600.376921 | 0) kworker-81 | 4.034 us | } /* _cond_resched */
> >>> 600.376922 | 0) kworker-81 | 0.505 us | _raw_spin_lock_irqsave();
> >>> 600.376926 | 0) kworker-81 | | rpm_resume() {
> >>> 600.376928 | 0) kworker-81 | 0.573 us | _raw_spin_lock();
> >>> 600.376934 | 0) kworker-81 | 0.706 us | rpm_resume();
> >>> 600.376937 | 0) kworker-81 | 0.556 us | _raw_spin_lock();
> >>> 600.376942 | 0) kworker-81 | 0.721 us | __rpm_get_callback();
> >>> 600.376946 | 0) kworker-81 | 0.564 us | dev_pm_disable_wake_irq_check();
> >>> 600.376949 | 0) kworker-81 | | rpm_callback() {
> >>> 600.376952 | 0) kworker-81 | | __rpm_callback() {
> >>> 600.376954 | 0) kworker-81 | | usb_runtime_resume() {
> >>> 600.376956 | 0) kworker-81 | | usb_resume_both() {
> >>> 600.376959 | 0) kworker-81 | | generic_resume() {
> >>> 600.376960 | 0) kworker-81 | | hcd_bus_resume() {
> >>> 600.376963 | 0) kworker-81 | | ohci_bus_resume [ohci_hcd]() {
> >>> 600.376964 | 0) kworker-81 | 0.588 us | _raw_spin_lock_irq();
> >>> 600.376968 | 0) kworker-81 | | ohci_rh_resume [ohci_hcd]() {
> >>> 600.377043 | 0) kworker-81 | | msleep() {
> >>
> >> Please find the full callgraph and the HTML output attached.
> >>
> >> Is that expected?
> >
> > I can't tell exactly what's happening from your callgraph and HTML, but
> > yes, in general it is expected.
> >
> > The reason is because some devices have different wakeup settings for
> > runtime suspend and system suspend: A device that is enabled for wakeup
> > signalling during runtime suspend often is not enabled for wakeup
> > during system suspend.
> >
> > As a result, the device's wakeup setting has to be changed when the
> > system goes to sleep, and to do that, we have to wake the device up
> > temporarily if it is already in runtime suspend.
>
> Understood. Thank you for the explanation.
>
> Sorry for being ignorant, but I have two more questions.
>
> 1. Should this also happen, if no USB device is connected to a hub?
Yes, it can happen, because the root hub (which is built into the USB
controller hardware on the computer) may have different wakeup settings
for runtime suspend and system suspend.
> 2. If somebody point me to the code, how the callback(?)
> `pm_runtime_resume()` is hooked up in `usb_suspend()` that’d help
> me to better understand, what is going on.
usb_suspend() calls choose_wakeup(), and under certain conditions,
choose_wakeup() calls pm_runtime_resume().
Alan Stern
> Kind regards and thank you very much in advance,
>
> Paul
>
>
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2018-07-24 14:59 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-07-23 23:19 `ohci_rh_resume()` called during `usb_dev_suspend()` Paul Menzel
2018-07-24 14:21 ` Alan Stern
2018-07-24 14:30 ` Paul Menzel
2018-07-24 14:59 ` Alan Stern
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).