我们可以使用ftrace来把内核调试,但是我们发现一个问题就是,我需要反复的echo这echo那,为了避免这类问题,linux提供了trace-cmd工具,其目的是方便ftrace的使用,仅此而已。
首先我们安装trace-cmd
apt install trace-cmd
然后我们可以看看trace-cmd可以获取哪些信息:
# trace-cmd list -h trace-cmd version 2.8.3 usage: trace-cmd list [-e [regex]][-t][-o][-f [regex]] -e list available events -F show event format -R show event triggers -l show event filters -t list available tracers -o list available options -f [regex] list available functions to filter on -P list loaded plugin files (by path) -O list plugin options -B list defined buffer instances -C list the defined clocks (and active one)
我们看看record支持哪些参数
# trace-cmd record -h trace-cmd version 2.8.3 usage: trace-cmd record [-v][-e event [-f filter]][-p plugin][-F][-d][-D][-o file] \ [-q][-s usecs][-O option ][-l func][-g func][-n func] \ [-P pid][-N host:port][-t][-r prio][-b size][-B buf][command ...] [-m max][-C clock] -e run command with event enabled -f filter for previous -e event -R trigger for previous -e event -p run command with plugin enabled -F filter only on the given process -P trace the given pid like -F for the command -c also trace the children of -F (or -P if kernel supports it) -C set the trace clock -T do a stacktrace on all events -l filter function name -g set graph function -n do not trace function -m max size per CPU in kilobytes -M set CPU mask to trace -v will negate all -e after it (disable those events) -d disable function tracer when running -D Full disable of function tracing (for all users) -o data output file [default trace.dat] -O option to enable (or disable) -r real time priority to run the capture threads -s sleep interval between recording (in usecs) [default: 1000] -S used with --profile, to enable only events in command line -N host:port to connect to (see listen) -t used with -N, forces use of tcp in live trace -b change kernel buffersize (in kilobytes per CPU) -B create sub buffer and following events will be enabled here -k do not reset the buffers after tracing. -i do not fail if an event is not found -q print no output to the screen --quiet print no output to the screen --module filter module name --by-comm used with --profile, merge events for related comms --profile enable tracing options needed for report --profile --func-stack perform a stack trace for function tracer (use with caution) --max-graph-depth limit function_graph depth --no-filter include trace-cmd threads in the trace
我相信对于了解ftrace的人来说,这些就无需解释了
我们可以把trace-cmd的使用习惯和perf对齐。如下讲解一下trace-cmd调试function trace和function graph trace,还是以usb_submit_urb为例。
trace-cmd record -p function -l usb_submit_urb --func-stack 此时我们会在本地记录trace.dat文件,我们通过report查看即可
# trace-cmd report | less CPU 1 is empty CPU 2 is empty CPU 3 is empty CPU 4 is empty CPU 5 is empty CPU 6 is empty CPU 7 is empty cpus=8 <idle>-0 [000] 569.464380: function: usb_submit_urb <idle>-0 [000] 569.464385: kernel_stack: <stack trace> => usb_submit_urb (ffffffc008d28b28) => hid_irq_in (ffffffc0090770e4) => __usb_hcd_giveback_urb (ffffffc008d26338) => usb_giveback_urb_bh (ffffffc008d264ac) => tasklet_action_common.isra.0 (ffffffc00808f020) => tasklet_hi_action (ffffffc00808f33c) => __do_softirq (ffffffc0080104b0) => irq_exit (ffffffc00808ee40) => __handle_domain_irq (ffffffc0080fea0c) => gic_handle_irq (ffffffc008010128) => el1_irq (ffffffc008011c08) => cpuidle_enter_state (ffffffc008ff95dc) => cpuidle_enter (ffffffc008ff9984) => call_cpuidle (ffffffc0080c9b18) => do_idle (ffffffc0080c9e18) => cpu_startup_entry (ffffffc0080ca040) => rest_init (ffffffc0095071d0) => arch_call_rest_init (ffffffc009ed0a34) => start_kernel (ffffffc009ed0f94) <idle>-0 [000] 569.468361: function: usb_submit_urb <idle>-0 [000] 569.468365: kernel_stack: <stack trace>
trace-cmd record -p function_graph -g usb_submit_urb 此时为了能够查看括号的注释,我们report如下:
# trace-cmd report -O tailprint CPU 1 is empty CPU 2 is empty CPU 3 is empty CPU 4 is empty CPU 5 is empty CPU 6 is empty CPU 7 is empty cpus=8 <idle>-0 [000] 1094.765032: funcgraph_entry: | finish_task_switch() { <idle>-0 [000] 1094.765034: funcgraph_entry: | _raw_spin_unlock_irq() { <idle>-0 [000] 1094.765035: funcgraph_entry: 0.584 us | do_raw_spin_unlock(); <idle>-0 [000] 1094.765037: funcgraph_exit: 2.334 us | } /* _raw_spin_unlock_irq */ <idle>-0 [000] 1094.765037: funcgraph_exit: 6.417 us | } /* finish_task_switch */ <idle>-0 [000] 1102.416579: funcgraph_entry: | usb_submit_urb() { <idle>-0 [000] 1102.416584: funcgraph_entry: | usb_hcd_submit_urb() { <idle>-0 [000] 1102.416585: funcgraph_entry: | usb_get_urb() { <idle>-0 [000] 1102.416586: funcgraph_entry: 0.875 us | usb_get_urb.part.0(); <idle>-0 [000] 1102.416587: funcgraph_exit: 2.917 us | } /* usb_get_urb */