wiki/ news/ 2012-08-14 - Hacking USB latencies with Josh

We set up the flight computer and threw Josh at it, and lo and behold, things happened. First we rebuilt the kernel to have ftrace, and then we dove into the ftraces. Notes from Josh:

./trace-cmd record -p function_graph -e irq:irq_handler_entry -e irq:irq_handler_exit -b 200000 taskset -c 1 ~/gfe2368/usb-speed-test/hostside/usb-speed-test-host
immediately type b, enter, wait a few seconds, ctrl-c, wait for the prompt to come back.
./trace-cmd report --cpu 0 > ../report-cpu-0
./trace-cmd report --cpu 1 > ../report-cpu-1
Copy those reports off to another system for analysis.

Look for irq_handler_entry on uhci_hcd:usbN where usbN corresponds to your
device, and the corresponding irq_handler_exit.  That tells you when the kernel
processed the USB interrupt that gave it the data.

Then look forward for the sys_write call that writes to the serial port, and
look at all the calls inbetween.

Some timings on a USB event:

6102.534270: irq_handler_entry:    irq=16 name=uhci_hcd:usb5
6102.534400: irq_handler_exit:     irq=16 ret=handled
6102.534561: (back to usb-speed-test in-kernel, in finish_task_switch)
6102.534888: (finished the call to poll; significant time spent polling tty devices, perhaps stdio?)
6102.534930: (finished a second call to poll)
6102.534985: (finished ioctl that returns the data)