Hi, On Wed, Apr 19, 2017 at 1:25 PM, Stefan Wahren <[email protected]> wrote: > Hi, > >> Doug Anderson <[email protected]> hat am 18. April 2017 um 22:41 >> geschrieben: >> >> >> It's hard to know for sure that all of this time is really in >> urb_enqueue(). Possible we could have task switched out and been >> blocked elsewhere. Using ftrace to get more fine-grained timings >> would be useful. ktime_get(), ktime_sub(), and ktime_to_us() are your >> friends here if you want to use trace_printk. > > i'm a newbie to ftrace, so i hope this would be helpful. > > # connect PL2303 to the onboard hub > # echo 0 > options/sleep-time > # echo 0 > function_profile_enabled > # echo 1 > function_profile_enabled > # ./usb_test > # Waiting for at least 20 seconds and then disconnect PL2303 > # echo 0 > function_profile_enabled > # cat trace_stat/function0 > > Function Hit Time Avg > s^2 > -------- --- ---- --- > --- > bcm2835_handle_irq 361347 219567633 us 607.636 us > 1485199 us > __handle_domain_irq 1082482 212639551 us 196.437 us > 3642030 us > generic_handle_irq 1082482 100592051 us 92.927 us > 50511334 us > irq_exit 1082482 98197771 us 90.715 us > 29649040 us > handle_level_irq 1082482 95812379 us 88.511 us > 51910093 us > do_sys_open 1806 87612983 us 48512.17 us > 2198507 us > SyS_open 1601 87372331 us 54573.59 us > 1898996 us > do_filp_open 1862 87368058 us 46921.62 us > 1634982 us > path_openat 1862 87314553 us 46892.88 us > 3357817 us > __do_softirq 3035 86266050 us 28423.73 us > 6449768 us > vfs_open 1515 85877012 us 56684.49 us > 101673.5 us > do_dentry_open 1515 85861429 us 56674.21 us > 812420.7 us > usb_submit_urb 136 85760172 us 630589.5 us > 59532024 us > usb_hcd_submit_urb 134 85756518 us 639974.0 us > 726298102 us > _dwc2_hcd_urb_enqueue 134 85738333 us 639838.3 us > 874104371 us
The 134 calls to this are taking a ton of time. It would be nice to know where all the time actually was in here. Are you on a single-core device, or multi-core? Oh, probably this so slow because we're just getting interrupted constantly. You can see that during your trace 80686112 us was in handle_irq_event(). Presumably all of that time could have been counted towards whatever code you were in when the interrupt went off. Of that 80 seconds, 60 seconds or so was usb_hcd_irq, and of that 57 seconds was in _dwc2_hcd_irq(). Presumably the big part of your problem is that dwc2_handle_hcd_intr() is just too slow. From glancing at the numbers below, it seems likely that nothing in particular is slow, it's just running a lot of code and (in total) all of that is slow. ...but someone with more time on their hands would need to really debug. One thing that would be interesting would be to see if you can increase the bug clock for talking to the dwc2 controller. Possibly some of those memory mapped IOs talking to dwc2 could be making everything slow? Other than that, maybe you can find some way to optimize the code in dwc2 so it runs faster, at least in the cases you care about... > chrdev_open 87 85716519 us 985247.3 us > 1951112835 us > tty_open 3 85714494 us 28571498 us > 3743206849 us > tty_port_open 3 85712603 us 28570867 us > 1968003468 us > serial_open 1 85712472 us 85712472 us > 0.000 us > serial_port_activate 1 85709890 us 85709890 us > 0.000 us > pl2303_open 1 85709875 us 85709875 us > 0.000 us > usb_serial_generic_open 1 85701170 us 85701170 us > 0.000 us > usb_serial_generic_submit_read 1 85701166 us 85701166 us > 0.000 us > usb_serial_generic_submit_read 2 85701160 us 42850580 us > 2252410463 us > handle_irq_event 1082482 80686112 us 74.538 us > 36417905 us > handle_irq_event_percpu 1082482 78398378 us 72.424 us > 34060119 us > __handle_irq_event_percpu 1082482 68466046 us 63.249 us > 53609076 us > usb_hcd_irq 1078945 59761116 us 55.388 us > 25139388 us > _dwc2_hcd_irq 1078945 57481606 us 53.275 us > 30847036 us > dwc2_handle_hcd_intr 1078945 55380910 us 51.328 us > 35986237 us > do_idle 394 43577379 us 110602.4 us > 84278209 us > dwc2_hc_n_intr 651065 42408491 us 65.137 us > 7281229 us > default_idle_call 229969 38021287 us 165.332 us > 11386904 us > arch_cpu_idle 229969 37379305 us 162.540 us > 2168909 us > dwc2_halt_channel 650811 34208348 us 52.562 us > 7792012 us > dwc2_release_channel 651065 33042638 us 50.751 us > 8112754 us > dwc2_hc_nak_intr 334689 18892951 us 56.449 us > 1823592 us > dwc2_hc_ack_intr 315986 18323433 us 57.988 us > 151346.6 us > dwc2_hcd_select_transactions 1730010 11694955 us 6.760 us > 1188442 us > dwc2_hcd_queue_transactions 651065 10931854 us 16.790 us > 952074.2 us > dwc2_assign_and_init_hc 651065 9540885 us 14.654 us > 258067.1 us > dwc2_queue_transaction 651065 9192559 us 14.119 us > 736431.6 us > tick_nohz_irq_exit 325055 9052192 us 27.848 us > 916293.3 us > __tick_nohz_idle_enter.constpr 324760 8463861 us 26.061 us > 2410440 us > dwc2_hc_start_transfer 651065 7687376 us 11.807 us > 625773.3 us > irq_enter 1082482 6627959 us 6.122 us > 11528932 us > arm_heavy_mb 10903913 6603586 us 0.605 us > 60562924 us > unmask_irq 1082482 4763699 us 4.400 us > 1032638 us > tick_irq_enter 326467 4377088 us 13.407 us > 4606805 us > dwc2_handle_common_intr 1078945 3799392 us 3.521 us > 1131504 us > add_interrupt_randomness 1082482 3542044 us 3.272 us > 30545511 us > get_next_armctrl_hwirq 1443829 3276974 us 2.269 us > 2116848 us > tick_nohz_restart 70325 3250462 us 46.220 us > 35710.73 us > dwc2_hc_cleanup 651065 3079003 us 4.729 us > 81202.50 us > dwc2_hcd_qh_deactivate 651065 3039940 us 4.669 us > 90928.10 us > ledtrig_cpu 459938 2450327 us 5.327 us > 1466705 us > arch_cpu_idle_exit 229969 2443315 us 10.624 us > 8606787 us > do_page_fault 5509 2304998 us 418.405 us > 17961439 us > ktime_get 795998 2121741 us 2.665 us > 166119.5 us > get_next_timer_interrupt 324760 1998999 us 6.155 us > 32201.63 us > handle_mm_fault 5537 1945500 us 351.363 us > 8324917 us > dwc2_is_controller_alive 2157890 1473590 us 0.682 us > 291399.4 us > hrtimer_cancel 70450 1394330 us 19.791 us > 36980.28 us > arch_cpu_idle_enter 229969 1350759 us 5.873 us > 10789.94 us > hrtimer_try_to_cancel 71029 1266967 us 17.837 us > 30260.75 us > filemap_map_pages 1632 1263006 us 773.900 us > 207846.4 us > tick_program_event 141799 1260485 us 8.889 us > 9343.194 us > hrtimer_start_range_ns 97555 1253698 us 12.851 us > 43166.94 us > irq_to_desc 1082482 1146955 us 1.059 us > 546937.6 us > link_path_walk 3486 1134351 us 325.401 us > 484443.0 us > __remove_hrtimer 99205 999724.0 us 10.077 us > 201933.9 us > clockevents_program_event 141799 985346.0 us 6.948 us > 7114.725 us > note_interrupt 1082482 899494.0 us 0.830 us > 705141.6 us > update_ts_time_stats.constprop 324760 862996.0 us 2.657 us > 21813.81 us > alloc_set_pte 20011 805880.0 us 40.271 us > 1086748 us > SyS_read 1940 805061.0 us 414.979 us > 164198.7 us > _local_bh_enable 326467 777908.0 us 2.382 us > 37202.43 us > vfs_read 2080 761487.0 us 366.099 us > 22944777 us > dwc2_hcd_get_frame_number 1097673 721108.0 us 0.656 us > 525348.1 us > do_munmap 1194 717161.0 us 600.637 us > 65635.31 us > schedule 3297 700578.0 us 212.489 us > 28594.59 us > __vfs_read 2080 694376.0 us 333.834 us > 21955675 us > walk_component 9912 683211.0 us 68.927 us > 349771.7 us > irq_find_mapping 1082482 673162.0 us 0.621 us > 900861.5 us > __next_timer_interrupt 324929 667175.0 us 2.053 us > 4576.720 us > armctrl_translate_shortcut 1079274 662875.0 us 0.614 us > 164464.8 us > filename_lookup 1316 646059.0 us 490.926 us > 148884.8 us > mmput 259 644417.0 us 2488.096 us > 33155247 us > armctrl_unmask_irq 1082482 639692.0 us 0.590 us > 891074.7 us > armctrl_mask_irq 1082482 636505.0 us 0.588 us > 888583.1 us > exit_mmap 45 634389.0 us 14097.53 us > 24105769 us > irq_state_set_masked 1082482 622182.0 us 0.574 us > 894212.6 us > user_path_at_empty 1156 620229.0 us 536.530 us > 166865.3 us > SyS_munmap 895 600613.0 us 671.075 us > 75763.68 us > vm_mmap_pgoff 1437 598955.0 us 416.809 us > 55882.41 us > read_current_timer 1082666 598757.0 us 0.553 us > 86817.59 us > irq_may_run 1082482 598471.0 us 0.552 us > 898308.6 us > vm_munmap 937 595309.0 us 635.335 us > 70914.31 us > path_lookupat 1316 592448.0 us 450.188 us > 147624.4 us > SyS_mmap_pgoff 1325 588992.0 us 444.522 us > 62142.49 us > irq_state_clr_masked 1082482 582077.0 us 0.537 us > 893572.4 us > idle_cpu 1082482 580428.0 us 0.536 us > 905609.5 us > do_execve 28 573864.0 us 20495.14 us > 98356111 us > do_execveat_common 28 573576.0 us 20484.85 us > 98471441 us > dwc2_hc_set_even_odd_frame 651065 570127.0 us 0.875 us > 543701.5 us > ledtrig_cpu.part.0 229969 549060.0 us 2.387 us > 9142.920 us > do_mmap 1437 548817.0 us 381.918 us > 54270.64 us > do_work_pending 2211 525805.0 us 237.813 us > 234836.0 us > led_trigger_event 460228 501093.0 us 1.088 us > 4759241 us > search_binary_handler 28 501026.0 us 17893.78 us > 93445723 us > clocksource_mmio_readl_up 807791 500765.0 us 0.619 us > 91050.42 us > load_elf_binary 28 500359.0 us 17869.96 us > 93309220 us > process_one_work 558 496994.0 us 890.670 us > 7196614 us > tick_do_update_jiffies64 324826 496168.0 us 1.527 us > 3422867 us > hrtimer_forward 72095 490887.0 us 6.808 us > 4548.034 us > unmap_vmas 1239 490538.0 us 395.914 us > 2723415 us > finish_task_switch 3926 479983.0 us 122.257 us > 25336.71 us > unmap_single_vma 3403 474812.0 us 139.527 us > 959184.6 us > __sync_icache_dcache 27231 468069.0 us 17.188 us > 364740.1 us > SyS_execve 16 462210.0 us 28888.12 us > 4450186 us > unmap_region 1194 460297.0 us 385.508 us > 44372.58 us > unmap_page_range 3403 455941.0 us 133.982 us > 956896.1 us > bcm2835_time_interrupt 3208 455584.0 us 142.014 us > 56012.72 us > mmap_region 1437 449599.0 us 312.873 us > 55175.49 us > hrtimer_interrupt 3208 443908.0 us 138.375 us > 55446.73 us > dwc2_hcd_qh_add 632341 436511.0 us 0.690 us > 58787.66 us > lookup_fast 11601 436227.0 us 37.602 us > 570183.6 us > inode_permission 14699 426528.0 us 29.017 us > 404007.8 us > SyS_access 561 412200.0 us 734.759 us > 146663.8 us > dwc2_hcd_qh_unlink 632344 410157.0 us 0.648 us > 87505.07 us > seq_read 669 408885.0 us 611.188 us > 226703.8 us > SyS_faccessat 564 406969.0 us 721.576 us > 141955.4 us > dwc2_check_qtd_still_ok 651065 392283.0 us 0.602 us > 59460.80 us > SyS_getdents64 392 379673.0 us 968.553 us > 13678636 us > SyS_write 404 378782.0 us 937.579 us > 254399.0 us > iterate_dir 393 367777.0 us 935.819 us > 13659529 us > vfs_write 404 358326.0 us 886.945 us > 240956.8 us > __hrtimer_run_queues.constprop 3227 357720.0 us 110.852 us > 47783.12 us > task_work_run 1460 350902.0 us 240.343 us > 71379.18 us > _cond_resched 109971 344855.0 us 3.135 us > 2245087 us > __vfs_write 404 333260.0 us 824.900 us > 230347.3 us > ____fput 1680 326232.0 us 194.185 us > 40913.99 us > __inode_permission 14699 324102.0 us 22.049 us > 328791.7 us > __fput 1680 316285.0 us 188.264 us > 40874.09 us > flush_old_exec 28 313336.0 us 11190.57 us > 96843591 us > tick_sched_timer 1964 312793.0 us 159.263 us > 2002.533 us > do_wp_page 1758 300693.0 us 171.042 us > 17667.03 us > _do_fork 29 281388.0 us 9703.034 us > 54207832 us > copy_process.part.4 29 273985.0 us 9447.758 us > 53888393 us > SyS_clone 17 267170.0 us 15715.88 us > 2444683 us > free_pgtables 1239 265593.0 us 214.360 us > 500428.0 us > dput 15879 265579.0 us 16.725 us > 269685.7 us > SyS_openat 205 258191.0 us 1259.468 us > 209643.6 us > pfn_valid 18146 257726.0 us 14.202 us > 121416.6 us > update_wall_time 5957 250787.0 us 42.099 us > 619.230 us > mmc_blk_issue_rq 63 246608.0 us 3914.412 us > 8858815 us > mmc_blk_issue_rw_rq 63 241626.0 us 3835.333 us > 8884205 us > vfs_statx 441 232198.0 us 526.526 us > 150124.0 us > SyS_sendmsg 316 226698.0 us 717.398 us > 164208.5 us > mmc_start_request 145 225615.0 us 1555.965 us > 5542154 us > __sys_sendmsg 316 223856.0 us 708.405 us > 164907.1 us > wp_page_copy 1061 222841.0 us 210.029 us > 13010.76 us > __generic_file_write_iter 206 219092.0 us 1063.553 us > 242948.7 us > terminate_walk 3225 217649.0 us 67.488 us > 47336.14 us > ext4_file_write_iter 170 216280.0 us 1272.235 us > 127738.3 us > __mmc_start_request 145 214090.0 us 1476.482 us > 5509235 us > ___sys_sendmsg 316 212732.0 us 673.202 us > 161410.8 us > kmem_cache_alloc 17570 210590.0 us 11.985 us > 120917.2 us > mmc_start_areq 63 210528.0 us 3341.714 us > 9610382 us > sdhci_request 145 209828.0 us 1447.089 us > 5547701 us > sock_sendmsg 353 208523.0 us 590.716 us > 147666.9 us > __split_vma 981 206458.0 us 210.456 us > 13253.43 us > credit_entropy_bits 16914 205434.0 us 12.145 us > 208.830 us > hrtimer_get_next_event 324760 199659.0 us 0.614 us > 17454.58 us > path_put 6090 196782.0 us 32.312 us > 54264.43 us > SyS_mprotect 427 193190.0 us 452.435 us > 42168.10 us > SyS_stat64 370 181587.0 us 490.775 us > 119707.4 us > nr_iowait_cpu 324760 176767.0 us 0.544 us > 17782.33 us > __vma_adjust 1452 174253.0 us 120.008 us > 5746.323 us > tick_sched_handle 1964 174004.0 us 88.596 us > 419.232 us > sdhci_irq 211 173984.0 us 824.568 us > 4212897 us > touch_softlockup_watchdog_sche 323207 173767.0 us 0.537 us > 108651.0 us > kernfs_iop_permission 5012 173442.0 us 34.605 us > 21830.09 us > __local_bh_enable 329502 172898.0 us 0.524 us > 9002.660 us > proc_single_show 233 170938.0 us 733.639 us > 235941.1 us > mprotect_fixup 455 163622.0 us 359.608 us > 43581.82 us > SyS_recvmsg 515 163337.0 us 317.159 us > 23749.85 us > update_process_times 1964 161227.0 us 82.091 us > 436.558 us > usb_control_msg 131 160306.0 us 1223.709 us > 63779.20 us > __sys_recvmsg 515 159685.0 us 310.067 us > 23888.88 us > check_carrier 29 159209.0 us 5489.965 us > 157176.1 us > __dentry_kill 1306 159044.0 us 121.779 us > 13522.69 us > smsc95xx_mdio_read 29 156605.0 us 5400.172 us > 147578.2 us > __smsc95xx_mdio_read 29 156128.0 us 5383.724 us > 153872.9 us > ext4_readdir 60 152036.0 us 2533.933 us > 67111799 us > run_ksoftirqd 844 151846.0 us 179.912 us > 74010.42 us > usb_start_wait_urb 131 151181.0 us 1154.053 us > 59721.86 us > find_vma 8806 149418.0 us 16.967 us > 419885.5 us > __alloc_pages_nodemask 4365 143647.0 us 32.908 us > 22236.43 us > ___sys_recvmsg 515 143567.0 us 278.770 us > 23183.05 us > memblock_is_map_memory 18146 142969.0 us 7.878 us > 62191.29 us > timekeeping_max_deferment 252165 141177.0 us 0.559 us > 3782.924 us > unlink_anon_vmas 3403 137080.0 us 40.282 us > 17090.37 us > __vma_link_rb 3403 136104.0 us 39.995 us > 12357.79 us > rcu_process_callbacks 1050 135701.0 us 129.239 us > 66292.86 us > SyS_close 1977 135041.0 us 68.306 us > 4406.697 us > pick_next_task_fair 3996 133622.0 us 33.438 us > 1391.499 us > proc_readfd 50 133185.0 us 2663.700 us > 18788258 us > proc_readfd_common 50 132911.0 us 2658.220 us > 18769391 us > generic_perform_write 206 132888.0 us 645.087 us > 134152.0 us > __mix_pool_bytes 16914 128343.0 us 7.587 us > 303.814 us > run_timer_softirq 1960 127980.0 us 65.295 us > 13337.43 us > timekeeping_update 5956 127128.0 us 21.344 us > 147.035 us > try_to_wake_up 2348 125639.0 us 53.508 us > 5318.431 us > ktime_add_safe 241886 125624.0 us 0.519 us > 6352.310 us > __rcu_process_callbacks 2100 125522.0 us 59.772 us > 1422883 us > __wake_up 19318 121496.0 us 6.289 us > 54037.07 us > tick_nohz_idle_enter 394 119544.0 us 303.411 us > 24204.73 us > proc_fill_cache 402 119333.0 us 296.848 us > 32614.19 us > unix_dgram_sendmsg 144 119088.0 us 827.000 us > 197140.4 us > enqueue_hrtimer 99205 118756.0 us 1.197 us > 1634.105 us > call_usermodehelper_exec_async 12 117852.0 us 9821.000 us > 319067.4 us > mutex_lock 14089 117414.0 us 8.333 us > 245056.5 us > sock_recvmsg 548 116787.0 us 213.114 us > 20249.99 us > __smsc95xx_read_reg 87 116418.0 us 1338.137 us > 39000.81 us > usbnet_read_cmd 87 115523.0 us 1327.850 us > 37075.87 us > SyS_epoll_wait 336 114271.0 us 340.092 us > 47629.77 us > __close_fd 1977 113569.0 us 57.445 us > 3969.846 us > split_vma 501 112236.0 us 224.023 us > 20703.73 us > vma_link 1248 111097.0 us 89.020 us > 5058.706 us > __usbnet_read_cmd 87 111024.0 us 1276.137 us > 34288.14 us > schedule_hrtimeout_range 390 107480.0 us 275.589 us > 10798.57 us > dentry_unlink_inode 733 107440.0 us 146.575 us > 8915.389 us > unix_find_other 172 106799.0 us 620.924 us > 79499.41 us > iput 757 106445.0 us 140.614 us > 8828.710 us > ext4_htree_fill_tree 36 106438.0 us 2956.611 us > 10423331 us > kernfs_fop_read 198 105215.0 us 531.388 us > 48887.87 us > htree_dirblock_to_tree 36 104352.0 us 2898.666 us > 10008360 us > schedule_hrtimeout_range_clock 390 103931.0 us 266.489 us > 10595.17 us > SyS_connect 99 102476.0 us 1035.111 us > 160650.8 us > __mark_inode_dirty 641 102069.0 us 159.234 us > 35047.69 us > expire_timers 700 100145.0 us 143.064 us > 8519.548 us > do_wait 42 99498.00 us 2369.000 us > 11701021 us > lookup_slow 413 99137.00 us 240.041 us > 40034.02 us > release_task 29 98995.00 us 3413.620 us > 12343735 us > SyS_fstat64 1168 98993.00 us 84.754 us > 5326.254 us > wait_consider_task 444 98839.00 us 222.610 us > 1532328 us > kmem_cache_free 17783 98715.00 us 5.551 us > 72804.30 us > > ... -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html
