17.13.2. ftrace
Trace a single function:
cd /sys/kernel/debug/tracing/ # Stop tracing. echo 0 > tracing_on # Clear previous trace. echo > trace # List the available tracers, and pick one. cat available_tracers echo function > current_tracer # List all functions that can be traced # cat available_filter_functions # Choose one. echo __kmalloc > set_ftrace_filter # Confirm that only __kmalloc is enabled. cat enabled_functions echo 1 > tracing_on # Latest events. head trace # Observe trace continuously, and drain seen events out. cat trace_pipe &
Sample output:
# tracer: function # # entries-in-buffer/entries-written: 97/97 #P:1 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | head-228 [000] .... 825.534637: __kmalloc <-load_elf_phdrs head-228 [000] .... 825.534692: __kmalloc <-load_elf_binary head-228 [000] .... 825.534815: __kmalloc <-load_elf_phdrs head-228 [000] .... 825.550917: __kmalloc <-__seq_open_private head-228 [000] .... 825.550953: __kmalloc <-tracing_open head-229 [000] .... 826.756585: __kmalloc <-load_elf_phdrs head-229 [000] .... 826.756627: __kmalloc <-load_elf_binary head-229 [000] .... 826.756719: __kmalloc <-load_elf_phdrs head-229 [000] .... 826.773796: __kmalloc <-__seq_open_private head-229 [000] .... 826.773835: __kmalloc <-tracing_open head-230 [000] .... 827.174988: __kmalloc <-load_elf_phdrs head-230 [000] .... 827.175046: __kmalloc <-load_elf_binary head-230 [000] .... 827.175171: __kmalloc <-load_elf_phdrs
Trace all possible functions, and draw a call graph:
echo 1 > max_graph_depth echo 1 > events/enable echo function_graph > current_tracer
Sample output:
# CPU DURATION FUNCTION CALLS # | | | | | | | 0) 2.173 us | } /* ntp_tick_length */ 0) | timekeeping_update() { 0) 4.176 us | ntp_get_next_leap(); 0) 5.016 us | update_vsyscall(); 0) | raw_notifier_call_chain() { 0) 2.241 us | notifier_call_chain(); 0) + 19.879 us | } 0) 3.144 us | update_fast_timekeeper(); 0) 2.738 us | update_fast_timekeeper(); 0) ! 117.147 us | } 0) | _raw_spin_unlock_irqrestore() { 0) 4.045 us | _raw_write_unlock_irqrestore(); 0) + 22.066 us | } 0) ! 265.278 us | } /* update_wall_time */
TODO: what do +
and !
mean?
Each enable
under the events/
tree enables a certain set of functions, the higher the enable
more functions are enabled.
TODO: can you get function arguments? https://stackoverflow.com/questions/27608752/does-ftrace-allow-capture-of-system-call-arguments-to-the-linux-kernel-or-only