ftrace 使用记录

ftrace 使用记录

ftrace

内核开启选项，编译内核：

CONFIG_FTRACE=y
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y
CONFIG_FUNCTION_TRACER=y
CONFIG_FTRACE_SYSCALLS=y

内核挂载debugfs文件系统：

mount -t debugfs debugfs /sys/kernel/debug
cd /sys/kernel/debug/tracing

过滤输出usb相关的函数：

echo 0 > tracing_on
echo nop > current_tracer
echo > set_ftrace_filter
echo function > current_tracer 
echo '*usb*' > set_ftrace_filter
echo 1 > tracing_on

从端抓取trace

cat trace :

[root@dvrdvs tracing] # cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 58815/307200   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
    irq/201-dwc3-812   [002] d...  1071.748252: usb_ep_queue <-source_sink_complete
    irq/201-dwc3-812   [002] d...  1071.748253: usb_gadget_map_request <-__dwc3_gadget_ep_queue
    irq/201-dwc3-812   [002] d...  1071.748253: usb_gadget_map_request_by_dev <-usb_gadget_map_request
    irq/201-dwc3-812   [002] d...  1071.748281: usb_gadget_unmap_request <-dwc3_gadget_giveback
    irq/201-dwc3-812   [002] d...  1071.748281: usb_gadget_unmap_request_by_dev <-usb_gadget_unmap_request
    irq/201-dwc3-812   [002] d...  1071.748283: usb_gadget_giveback_request <-dwc3_gadget_giveback
    irq/201-dwc3-812   [002] d...  1071.748283: usb_ep_queue <-source_sink_complete
    irq/201-dwc3-812   [002] d...  1071.748283: usb_gadget_map_request <-__dwc3_gadget_ep_queue
    irq/201-dwc3-812   [002] d...  1071.748284: usb_gadget_map_request_by_dev <-usb_gadget_map_request
    irq/201-dwc3-812   [002] d...  1071.748312: usb_gadget_unmap_request <-dwc3_gadget_giveback
    irq/201-dwc3-812   [002] d...  1071.748312: usb_gadget_unmap_request_by_dev <-usb_gadget_unmap_request
    irq/201-dwc3-812   [002] d...  1071.748313: usb_gadget_giveback_request <-dwc3_gadget_giveback

echo 0 > tracing_on
echo nop > current_tracer
echo  > set_ftrace_filter
echo function_graph > current_tracer 
echo "*usb*" > set_ftrace_filter
echo 1 > tracing_on

cat trace :

[root@dvrdvs tracing] # cat trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 2)               |  usb_gadget_unmap_request() {
 2)   1.580 us    |    usb_gadget_unmap_request_by_dev();
 2)   3.840 us    |  }
 2)               |  usb_gadget_giveback_request() {
 2)               |    usb_ep_queue() {
 2)               |      usb_gadget_map_request() {
 2)   1.160 us    |        usb_gadget_map_request_by_dev();
 2)   2.360 us    |      }
 2)   6.820 us    |    }
 2)   8.460 us    |  }
 2)               |  usb_gadget_unmap_request() {
 2)   0.920 us    |    usb_gadget_unmap_request_by_dev();
 2)   1.940 us    |  }
 2)               |  usb_gadget_giveback_request() {
 2)               |    usb_ep_queue() {
 2)               |      usb_gadget_map_request() {
 2)   0.960 us    |        usb_gadget_map_request_by_dev();
 2)   1.820 us    |      }
 2)   4.540 us    |    }
 2)   5.540 us    |  }
 2)               |  usb_gadget_unmap_request() {
 2)   0.900 us    |    usb_gadget_unmap_request_by_dev();
 2)   1.740 us    |  }
 2)               |  usb_gadget_giveback_request() {
 2)               |    usb_ep_queue() {
 2)               |      usb_gadget_map_request() {
 2)   0.940 us    |        usb_gadget_map_request_by_dev();
 2)   1.800 us    |      }
 2)   4.500 us    |    }
 2)   5.400 us    |  }

主端抓取trace

100Hz 中断usb_hcd_irq 耗时 20us :

             ut4-1037  [000] d...  1450.957002: usb_submit_urb <-proc_do_submiturb
             ut4-1037  [000] d...  1450.957003: usb_hcd_submit_urb <-usb_submit_urb
             ut4-1037  [000] d...  1450.957004: usb_get_urb <-usb_hcd_submit_urb
             ut4-1037  [000] d...  1450.957005: usb_hcd_map_urb_for_dma <-usb_hcd_submit_urb
             ut4-1037  [000] d...  1450.957007: usb_hcd_is_primary_hcd <-xhci_urb_enqueue
             ut4-1037  [000] d...  1450.957008: usb_hcd_is_primary_hcd <-xhci_check_args.isra.1
             ut4-1037  [000] d...  1450.957011: usb_hcd_link_urb_to_ep <-prepare_transfer
             ut4-1037  [000] ....  1450.957018: usbdev_poll <-do_sys_poll
          <idle>-0     [000] d.h.  1450.957038: usb_hcd_irq <-__handle_irq_event_percpu
          <idle>-0     [000] d.h.  1450.957039: usb_hcd_is_primary_hcd <-xhci_irq
          <idle>-0     [000] d.h.  1450.957044: usb_hcd_unlink_urb_from_ep <-xhci_irq
          <idle>-0     [000] d.h.  1450.957045: usb_hcd_giveback_urb <-xhci_irq
          <idle>-0     [000] d.h.  1450.957046: __usb_hcd_giveback_urb <-usb_hcd_giveback_urb
          <idle>-0     [000] d.h.  1450.957046: usb_hcd_unmap_urb_for_dma <-unmap_urb_for_dma
          <idle>-0     [000] d.h.  1450.957047: usb_hcd_unmap_urb_setup_for_dma <-usb_hcd_unmap_urb_for_dma
          <idle>-0     [000] d.h.  1450.957048: usb_anchor_suspend_wakeups <-__usb_hcd_giveback_urb
          <idle>-0     [000] d.h.  1450.957049: usb_unanchor_urb <-__usb_hcd_giveback_urb
          <idle>-0     [000] dnh.  1450.957052: usb_anchor_resume_wakeups <-__usb_hcd_giveback_urb
          <idle>-0     [000] dnh.  1450.957053: usb_free_urb <-__usb_hcd_giveback_urb
             ut4-1037  [000] ....  1450.957060: usbdev_poll <-do_sys_poll
             ut4-1037  [000] ....  1450.957063: usbdev_ioctl <-do_vfs_ioctl
             ut4-1037  [000] ....  1450.957064: usbdev_do_ioctl <-usbdev_ioctl
             ut4-1037  [000] ....  1450.957066: usb_free_urb <-free_async
             ut4-1037  [000] ....  1450.957070: usbdev_ioctl <-do_vfs_ioctl
             ut4-1037  [000] ....  1450.957071: usbdev_do_ioctl <-usbdev_ioctl
             ut4-1037  [000] ....  1450.957089: usbdev_ioctl <-do_vfs_ioctl
             ut4-1037  [000] ....  1450.957090: usbdev_do_ioctl <-usbdev_ioctl
             ut4-1037  [000] ....  1450.957092: usb_alloc_urb <-proc_do_submiturb
             ut4-1037  [000] ....  1450.957093: usbfs_increase_memory_usage <-proc_do_submiturb
             ut4-1037  [000] d...  1450.957096: usb_submit_urb <-proc_do_submiturb
             ut4-1037  [000] d...  1450.957097: usb_hcd_submit_urb <-usb_submit_urb

1000Hz 中断usb_hcd_irq 耗时 16us :

             ut4-1019  [000] d...   282.857089: usb_submit_urb <-proc_do_submiturb
             ut4-1019  [000] d...   282.857090: usb_hcd_submit_urb <-usb_submit_urb
             ut4-1019  [000] d...   282.857091: usb_get_urb <-usb_hcd_submit_urb
             ut4-1019  [000] d...   282.857092: usb_hcd_map_urb_for_dma <-usb_hcd_submit_urb
             ut4-1019  [000] d...   282.857094: usb_hcd_is_primary_hcd <-xhci_urb_enqueue
             ut4-1019  [000] d...   282.857095: usb_hcd_is_primary_hcd <-xhci_check_args.isra.1
             ut4-1019  [000] d...   282.857097: usb_hcd_link_urb_to_ep <-prepare_transfer
             ut4-1019  [000] ....   282.857104: usbdev_poll <-do_sys_poll
          <idle>-0     [000] d.h.   282.857120: usb_hcd_irq <-__handle_irq_event_percpu
          <idle>-0     [000] d.h.   282.857121: usb_hcd_is_primary_hcd <-xhci_irq
          <idle>-0     [000] d.h.   282.857126: usb_hcd_unlink_urb_from_ep <-xhci_irq
          <idle>-0     [000] d.h.   282.857127: usb_hcd_giveback_urb <-xhci_irq
          <idle>-0     [000] d.h.   282.857128: __usb_hcd_giveback_urb <-usb_hcd_giveback_urb
          <idle>-0     [000] d.h.   282.857129: usb_hcd_unmap_urb_for_dma <-unmap_urb_for_dma
          <idle>-0     [000] d.h.   282.857130: usb_hcd_unmap_urb_setup_for_dma <-usb_hcd_unmap_urb_for_dma
          <idle>-0     [000] d.h.   282.857131: usb_anchor_suspend_wakeups <-__usb_hcd_giveback_urb
          <idle>-0     [000] d.h.   282.857132: usb_unanchor_urb <-__usb_hcd_giveback_urb
          <idle>-0     [000] dnh.   282.857135: usb_anchor_resume_wakeups <-__usb_hcd_giveback_urb
          <idle>-0     [000] dnh.   282.857136: usb_free_urb <-__usb_hcd_giveback_urb
             ut4-1019  [000] ....   282.857143: usbdev_poll <-do_sys_poll
             ut4-1019  [000] ....   282.857146: usbdev_ioctl <-do_vfs_ioctl
             ut4-1019  [000] ....   282.857147: usbdev_do_ioctl <-usbdev_ioctl
             ut4-1019  [000] ....   282.857149: usb_free_urb <-free_async
             ut4-1019  [000] ....   282.857153: usbdev_ioctl <-do_vfs_ioctl
             ut4-1019  [000] ....   282.857154: usbdev_do_ioctl <-usbdev_ioctl
             ut4-1019  [000] ....   282.857173: usbdev_ioctl <-do_vfs_ioctl
             ut4-1019  [000] ....   282.857174: usbdev_do_ioctl <-usbdev_ioctl
             ut4-1019  [000] ....   282.857175: usb_alloc_urb <-proc_do_submiturb
             ut4-1019  [000] ....   282.857177: usbfs_increase_memory_usage <-proc_do_submiturb
             ut4-1019  [000] d...   282.857179: usb_submit_urb <-proc_do_submiturb

100Hz 到 1000Hz 处理上有提升。

事件抓取

echo 0 > tracing_on
echo nop > current_tracer
echo 1 > events/enable
echo 1 > tracing_on