Hi, On Thu, Apr 20, 2017 at 12:46 AM, Stefan Wahren <stefan.wahren@xxxxxxxx> wrote: > Am 19.04.2017 um 23:47 schrieb Doug Anderson: >> Hi, >> >> On Wed, Apr 19, 2017 at 1:25 PM, Stefan Wahren <stefan.wahren@xxxxxxxx> wrote: >>> Hi, >>> >>>> Doug Anderson <dianders@xxxxxxxxxxxx> 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? > > Raspberry Pi B is a single core device which runs with 700 MHz cpu freq. > >> 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(). > > Since the FTDI (full speed device) and the PL2303 (also full speed > device) behaves differently, i will try to compare those ftraces. The most interesting to know is what the endpoints looked like for these two devices. Since they are full speed devices, I'd expect that any interrupt end points should fire once per "ms" at most. >> 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. > > Unfortunately the bcm2835 datasheet [1] doesn't provide many information > about the USB IP core and the Synopsys documents aren't public > available. The Raspberry Pi Foundation decided to use a different driver > which uses FIQ in the downstream tree [2], but this won't be an option here. > > Maybe i could start with comparing the register settings between dwc2 > and dwc_otg. I was suggesting looking at clock speeds related to usb that might be in /sys/kernel/debug/clk/clk_summary ...but at 700 MHz single core (and I think it's also an older ARM core so 700 MHz there might be a lot slower than 700 MHz on newer cores), the theory that you're just running too many instructions is a sane one. Probably someone just needs to see if there's any way to fast path some of the common cases in the IRQ handler. -Doug -- 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
