ftrace, readme improvements

2026-01-23 02:05:57 +01:00 · 2017-06-24 22:46:15 +01:00
parent fa9c635a2e
commit 6af950a200
4 changed files with 115 additions and 5 deletions
--- a/ftrace.md
+++ b/ftrace.md
@@ -0,0 +1,87 @@
+# ftrace
+
+Trace a single function:
+
+    cd /sys/kernel/debug/tracing/
+
+    # Stop tracing.
+    echo 0 > tracing_on
+
+    # Clear previous trace.
+    echo '' > trace
+
+    echo 1 > max_graph_depth
+
+    # 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 continously, 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 > 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.