Has anyone here looked into reducing the amount of time the USB serial
driver disables interrupts? On an ARM system, I'm seeing about 746 us
of latency for handling a USB interrupt, which seems rather excessive.
I attached a trace captured with the irqsoff tracer.
Note: the 500MHz ARM cycle counter was used for timestamping
the entry so the reported times have to be doubled to get actual time
in micro-seconds.
>From what I can see:
o OHCI takes interrupt and frees up an URB that is done
o USB serial driver submits a new URB (for transmit, I think)
o another URB is freed (receive, I think), then a new receive URB is
submited
I'm hoping there is something silly going on and things are done at the
hardirq level when they should be done as softirqs, but I just started
looking into this.
Anyone have any helpful thoughts/pointers?
Thanks!
--david
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.9.44+
# --------------------------------------------------------------------
# latency: 373 us, #188/188, CPU#0 | (M:server VP:0, KP:0, SP:0 HP:0)
# -----------------
# | task: kworker/0:0-1437 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: __irq_usr
# => ended at: __schedule
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<...>-1896 0d... 1650: __irq_usr
<...>-1896 0d... 5443: aic5_handle <-__irq_usr
<...>-1896 0d... 7472: irq_get_domain_generic_chip <-aic5_handle
<...>-1896 0d... 10194: __handle_domain_irq <-aic5_handle
<...>-1896 0d... 11685: irq_enter <-__handle_domain_irq
<...>-1896 0d.h. 13521: irq_find_mapping <-__handle_domain_irq
<...>-1896 0d.h. 15403: generic_handle_irq <-__handle_domain_irq
<...>-1896 0d.h. 16673: irq_to_desc <-generic_handle_irq
<...>-1896 0d.h. 18662: handle_fasteoi_irq <-generic_handle_irq
<...>-1896 0d.h. 20194: irq_may_run <-handle_fasteoi_irq
<...>-1896 0d.h. 22426: handle_irq_event <-handle_fasteoi_irq
<...>-1896 0d.h. 23743: handle_irq_event_percpu <-handle_irq_event
<...>-1896 0d.h. 25072: __handle_irq_event_percpu
<-handle_irq_event_percpu
<...>-1896 0d.h. 26492: usb_hcd_irq <-__handle_irq_event_percpu
<...>-1896 0d.h. 28284: ohci_irq <-usb_hcd_irq
<...>-1896 0d.h. 32109: arm_heavy_mb <-ohci_irq
<...>-1896 0d.h. 33430: l2c210_sync <-arm_heavy_mb
<...>-1896 0d.h. 37489: add_to_done_list.part.0 <-ohci_irq
<...>-1896 0d.h. 39777: add_to_done_list.part.0 <-ohci_irq
<...>-1896 0d.h. 41538: ohci_work <-ohci_irq
<...>-1896 0d.h. 43671: td_done <-ohci_work
<...>-1896 0d.h. 47023: finish_urb <-ohci_work
<...>-1896 0d.h. 48342: urb_free_priv <-finish_urb
<...>-1896 0d.h. 49684: td_free <-urb_free_priv
<...>-1896 0d.h. 51204: dma_pool_free <-td_free
<...>-1896 0d.h. 54677: kfree <-urb_free_priv
<...>-1896 0d.h. 56661: ___cache_free <-kfree
<...>-1896 0d.h. 59101: usb_hcd_unlink_urb_from_ep <-finish_urb
<...>-1896 0d.h. 61064: usb_hcd_giveback_urb <-finish_urb
<...>-1896 0d.h. 62745: __usb_hcd_giveback_urb <-usb_hcd_giveback_urb
<...>-1896 0d.h. 64082: unmap_urb_for_dma <-__usb_hcd_giveback_urb
<...>-1896 0d.h. 65456: usb_hcd_unmap_urb_for_dma <-unmap_urb_for_dma
<...>-1896 0d.h. 66757: usb_hcd_unmap_urb_setup_for_dma
<-usb_hcd_unmap_urb_for_dma
<...>-1896 0d.h. 69135: arm_dma_unmap_page <-usb_hcd_unmap_urb_for_dma
<...>-1896 0d.h. 70590: __dma_page_dev_to_cpu <-arm_dma_unmap_page
<...>-1896 0d.h. 72810: usb_anchor_suspend_wakeups
<-__usb_hcd_giveback_urb
<...>-1896 0d.h. 74157: usb_unanchor_urb <-__usb_hcd_giveback_urb
<...>-1896 0d.h. 76333: usb_serial_generic_write_bulk_callback
<-__usb_hcd_giveback_urb
<...>-1896 0d.h. 79605: usb_serial_generic_write_start
<-usb_serial_generic_write_bulk_callback
<...>-1896 0d.h. 84314: ftdi_prepare_write_buffer
<-usb_serial_generic_write_start
<...>-1896 0d.h. 91988: usb_submit_urb <-usb_serial_generic_write_start
<...>-1896 0d.h. 96555: usb_hcd_submit_urb <-usb_submit_urb
<...>-1896 0d.h. 98117: usb_get_urb <-usb_hcd_submit_urb
<...>-1896 0d.h. 99710: usb_hcd_map_urb_for_dma <-usb_hcd_submit_urb
<...>-1896 0d.h. 102131: arm_dma_map_page <-usb_hcd_map_urb_for_dma
<...>-1896 0d.h. 103581: __dma_page_cpu_to_dev <-arm_dma_map_page
<...>-1896 0d.h. 105096: dma_cache_maint_page <-__dma_page_cpu_to_dev
<...>-1896 0d.h. 107224: l2c210_clean_range <-__dma_page_cpu_to_dev
<...>-1896 0d.h. 110437: ohci_urb_enqueue <-usb_hcd_submit_urb
<...>-1896 0d.h. 114226: __kmalloc <-ohci_urb_enqueue
<...>-1896 0d.h. 115568: kmalloc_slab <-__kmalloc
<...>-1896 0d.h. 119997: td_alloc <-ohci_urb_enqueue
<...>-1896 0d.h. 121705: dma_pool_alloc <-td_alloc
<...>-1896 0d.h. 124871: usb_hcd_link_urb_to_ep <-ohci_urb_enqueue
<...>-1896 0d.h. 129019: td_fill <-ohci_urb_enqueue
<...>-1896 0d.h. 131229: arm_heavy_mb <-td_fill
<...>-1896 0d.h. 132402: l2c210_sync <-arm_heavy_mb
<...>-1896 0d.h. 134233: arm_heavy_mb <-ohci_urb_enqueue
<...>-1896 0d.h. 135382: l2c210_sync <-arm_heavy_mb
<...>-1896 0d.h. 136560: arm_heavy_mb <-ohci_urb_enqueue
<...>-1896 0d.h. 137725: l2c210_sync <-arm_heavy_mb
<...>-1896 0d.h. 140841: usb_serial_port_softint
<-usb_serial_generic_write_bulk_callback
<...>-1896 0d.h. 142226: queue_work_on <-usb_serial_port_softint
<...>-1896 0d.h. 143991: __queue_work <-queue_work_on
<...>-1896 0d.h. 146634: get_work_pool <-__queue_work
<...>-1896 0d.h. 149908: insert_work <-__queue_work
<...>-1896 0d.h. 151270: get_pwq <-insert_work
<...>-1896 0d.h. 152701: wake_up_worker <-insert_work
<...>-1896 0d.h. 154495: wake_up_process <-wake_up_worker
<...>-1896 0d.h. 155926: try_to_wake_up <-wake_up_process
<...>-1896 0d.h. 158553: activate_task <-try_to_wake_up
<...>-1896 0d.h. 159825: update_rq_clock <-activate_task
<...>-1896 0d.h. 163829: enqueue_task_fair <-activate_task
<...>-1896 0d.h. 166046: update_curr.constprop.13 <-enqueue_task_fair
<...>-1896 0d.h. 168350: place_entity.constprop.9 <-enqueue_task_fair
<...>-1896 0d.h. 171209: check_spread.constprop.10 <-enqueue_task_fair
<...>-1896 0d.h. 172719: __enqueue_entity.constprop.16 <-enqueue_task_fair
<...>-1896 0d.h. 175001: wq_worker_waking_up <-try_to_wake_up
<...>-1896 0d.h. 176643: kthread_data <-wq_worker_waking_up
<...>-1896 0d.h. 178596: ttwu_do_wakeup <-try_to_wake_up
<...>-1896 0d.h. 179881: check_preempt_curr <-ttwu_do_wakeup
<...>-1896 0d.h. 181402: check_preempt_wakeup <-check_preempt_curr
<...>-1896 0d.h. 183408: update_curr.constprop.13 <-check_preempt_wakeup
<...>-1896 0d.h. 184842: wakeup_preempt_entity <-check_preempt_wakeup
<...>-1896 0d.h. 186710: set_next_buddy <-check_preempt_wakeup
<...>-1896 0d.h. 187959: resched_curr <-check_preempt_wakeup
<...>-1896 0dnh. 189613: ttwu_stat.constprop.22 <-try_to_wake_up
<...>-1896 0dnh. 193413: usb_anchor_resume_wakeups
<-__usb_hcd_giveback_urb
<...>-1896 0dnh. 195048: usb_free_urb <-__usb_hcd_giveback_urb
<...>-1896 0dnh. 196431: arm_heavy_mb <-finish_urb
<...>-1896 0dnh. 197593: l2c210_sync <-arm_heavy_mb
<...>-1896 0dnh. 200023: td_done <-ohci_work
<...>-1896 0dnh. 202269: finish_urb <-ohci_work
<...>-1896 0dnh. 203504: urb_free_priv <-finish_urb
<...>-1896 0dnh. 204632: td_free <-urb_free_priv
<...>-1896 0dnh. 206022: dma_pool_free <-td_free
<...>-1896 0dnh. 208057: kfree <-urb_free_priv
<...>-1896 0dnh. 209625: ___cache_free <-kfree
<...>-1896 0dnh. 211283: usb_hcd_unlink_urb_from_ep <-finish_urb
<...>-1896 0dnh. 212440: usb_hcd_giveback_urb <-finish_urb
<...>-1896 0dnh. 213633: __usb_hcd_giveback_urb <-usb_hcd_giveback_urb
<...>-1896 0dnh. 214768: unmap_urb_for_dma <-__usb_hcd_giveback_urb
<...>-1896 0dnh. 215940: usb_hcd_unmap_urb_for_dma <-unmap_urb_for_dma
<...>-1896 0dnh. 217116: usb_hcd_unmap_urb_setup_for_dma
<-usb_hcd_unmap_urb_for_dma
<...>-1896 0dnh. 218473: arm_dma_unmap_page <-usb_hcd_unmap_urb_for_dma
<...>-1896 0dnh. 219715: __dma_page_dev_to_cpu <-arm_dma_unmap_page
<...>-1896 0dnh. 221466: l2c210_inv_range <-__dma_page_dev_to_cpu
<...>-1896 0dnh. 223163: dma_cache_maint_page <-__dma_page_dev_to_cpu
<...>-1896 0dnh. 225148: usb_anchor_suspend_wakeups
<-__usb_hcd_giveback_urb
<...>-1896 0dnh. 226346: usb_unanchor_urb <-__usb_hcd_giveback_urb
<...>-1896 0dnh. 228312: usb_serial_generic_read_bulk_callback
<-__usb_hcd_giveback_urb
<...>-1896 0dnh. 230344: ftdi_process_read_urb
<-usb_serial_generic_read_bulk_callback
<...>-1896 0dnh. 234752: usb_serial_generic_submit_read_urb
<-usb_serial_generic_read_bulk_callback
<...>-1896 0dnh. 236533: usb_submit_urb
<-usb_serial_generic_submit_read_urb
<...>-1896 0dnh. 238401: usb_hcd_submit_urb <-usb_submit_urb
<...>-1896 0dnh. 239628: usb_get_urb <-usb_hcd_submit_urb
<...>-1896 0dnh. 240935: usb_hcd_map_urb_for_dma <-usb_hcd_submit_urb
<...>-1896 0dnh. 242257: arm_dma_map_page <-usb_hcd_map_urb_for_dma
<...>-1896 0dnh. 243425: __dma_page_cpu_to_dev <-arm_dma_map_page
<...>-1896 0dnh. 244583: dma_cache_maint_page <-__dma_page_cpu_to_dev
<...>-1896 0dnh. 246043: l2c210_inv_range <-__dma_page_cpu_to_dev
<...>-1896 0dnh. 247775: ohci_urb_enqueue <-usb_hcd_submit_urb
<...>-1896 0dnh. 250071: __kmalloc <-ohci_urb_enqueue
<...>-1896 0dnh. 251187: kmalloc_slab <-__kmalloc
<...>-1896 0dnh. 253554: td_alloc <-ohci_urb_enqueue
<...>-1896 0dnh. 254755: dma_pool_alloc <-td_alloc
<...>-1896 0dnh. 257346: usb_hcd_link_urb_to_ep <-ohci_urb_enqueue
<...>-1896 0dnh. 259505: td_fill <-ohci_urb_enqueue
<...>-1896 0dnh. 261243: arm_heavy_mb <-td_fill
<...>-1896 0dnh. 262412: l2c210_sync <-arm_heavy_mb
<...>-1896 0dnh. 264388: arm_heavy_mb <-ohci_urb_enqueue
<...>-1896 0dnh. 265537: l2c210_sync <-arm_heavy_mb
<...>-1896 0dnh. 266854: arm_heavy_mb <-ohci_urb_enqueue
<...>-1896 0dnh. 267983: l2c210_sync <-arm_heavy_mb
<...>-1896 0dnh. 270318: usb_anchor_resume_wakeups
<-__usb_hcd_giveback_urb
<...>-1896 0dnh. 271558: usb_free_urb <-__usb_hcd_giveback_urb
<...>-1896 0dnh. 272862: arm_heavy_mb <-finish_urb
<...>-1896 0dnh. 274006: l2c210_sync <-arm_heavy_mb
<...>-1896 0dnh. 276291: arm_heavy_mb <-ohci_irq
<...>-1896 0dnh. 277469: l2c210_sync <-arm_heavy_mb
<...>-1896 0dnh. 278823: arm_heavy_mb <-ohci_irq
<...>-1896 0dnh. 279952: l2c210_sync <-arm_heavy_mb
<...>-1896 0dnh. 282801: usb_hcd_irq <-__handle_irq_event_percpu
<...>-1896 0dnh. 284855: ehci_irq <-usb_hcd_irq
<...>-1896 0dnh. 287806: add_interrupt_randomness
<-handle_irq_event_percpu
<...>-1896 0dnh. 289340: read_current_timer <-add_interrupt_randomness
<...>-1896 0dnh. 292206: note_interrupt <-handle_irq_event_percpu
<...>-1896 0dnh. 294773: irq_gc_eoi <-handle_fasteoi_irq
<...>-1896 0dnh. 296598: arm_heavy_mb <-irq_gc_eoi
<...>-1896 0dnh. 297789: l2c210_sync <-arm_heavy_mb
<...>-1896 0dnh. 299285: irq_exit <-__handle_domain_irq
<...>-1896 0dn.. 302081: do_work_pending <-slow_work_pending
<...>-1896 0dn.. 304508: schedule <-do_work_pending
<...>-1896 0dn.. 307405: rcu_sched_qs <-__schedule
<...>-1896 0dn.. 309457: raise_softirq <-rcu_sched_qs
<...>-1896 0dn.. 311037: __raise_softirq_irqoff <-raise_softirq
<...>-1896 0dn.. 312717: wakeup_softirqd <-raise_softirq
<...>-1896 0dn.. 314508: wake_up_process <-wakeup_softirqd
<...>-1896 0dn.. 315647: try_to_wake_up <-wake_up_process
<...>-1896 0dn.. 317440: activate_task <-try_to_wake_up
<...>-1896 0dn.. 318685: update_rq_clock <-activate_task
<...>-1896 0dn.. 321077: enqueue_task_fair <-activate_task
<...>-1896 0dn.. 322403: update_curr.constprop.13 <-enqueue_task_fair
<...>-1896 0dn.. 323851: place_entity.constprop.9 <-enqueue_task_fair
<...>-1896 0dn.. 325350: check_spread.constprop.10 <-enqueue_task_fair
<...>-1896 0dn.. 326655: __enqueue_entity.constprop.16 <-enqueue_task_fair
<...>-1896 0dn.. 328613: ttwu_do_wakeup <-try_to_wake_up
<...>-1896 0dn.. 329795: check_preempt_curr <-ttwu_do_wakeup
<...>-1896 0dn.. 330984: check_preempt_wakeup <-check_preempt_curr
<...>-1896 0dn.. 332419: ttwu_stat.constprop.22 <-try_to_wake_up
<...>-1896 0dn.. 335259: update_rq_clock <-__schedule
<...>-1896 0dn.. 336960: pick_next_task_fair <-__schedule
<...>-1896 0dn.. 338334: put_prev_task_fair <-pick_next_task_fair
<...>-1896 0dn.. 339527: update_curr.constprop.13 <-put_prev_task_fair
<...>-1896 0dn.. 340683: check_spread.constprop.10 <-put_prev_task_fair
<...>-1896 0dn.. 342065: __enqueue_entity.constprop.16
<-put_prev_task_fair
<...>-1896 0dn.. 344084: __pick_first_entity <-pick_next_task_fair
<...>-1896 0dn.. 345816: wakeup_preempt_entity <-pick_next_task_fair
<...>-1896 0dn.. 347322: clear_buddies <-pick_next_task_fair
<...>-1896 0dn.. 348783: set_next_entity <-pick_next_task_fair
<...>-1896 0d... 355738: atomic_notifier_call_chain <-__switch_to
<...>-1896 0d... 356958: notifier_call_chain <-atomic_notifier_call_chain
<...>-1896 0d... 363821: vfp_notifier <-notifier_call_chain
<...>-1896 0d... 365828: thumbee_notifier <-notifier_call_chain
kworker/-1437 0d... 369629: finish_task_switch <-__schedule
kworker/-1437 0d... 372286: finish_task_switch <-__schedule
kworker/-1437 0d... 375367: trace_hardirqs_on <-__schedule
kworker/-1437 0d... 383566: <stack trace>
=> worker_thread
=> kthread
=> ret_from_fork
--
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
