usb: dwc2: NMI watchdog: BUG: soft lockup - CPU#0 stuck for 146s

Stefan Wahren stefan.wahren at i2se.com
Wed Apr 19 13:25:02 PDT 2017


Hi,

> Doug Anderson <dianders at chromium.org> 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 
  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

...



More information about the linux-arm-kernel mailing list