7.ftrace实操--instances

290 阅读3分钟

在tracefs跟踪目录中有一个名为“instances”的目录。

使用mkdir可以在这个目录中创建新的目录,使用rmdir可以删除目录。在这个目录中使用mkdir创建的目录在创建之后已经包含了文件和其他目录:

[root@idle tracing]# mkdir instances/idle
[root@idle tracing]# ls instances/idle/
available_tracers     per_cpu               trace_clock
buffer_percent        set_event             trace_marker
buffer_size_kb        set_event_pid         trace_marker_raw
buffer_total_size_kb  set_ftrace_filter     trace_options
current_tracer        set_ftrace_notrace    trace_pipe
error_log             set_ftrace_pid        tracing_cpumask
events                snapshot              tracing_max_latency
free_buffer           timestamp_mode        tracing_on
options               trace
[root@idle tracing]# cat instances/idle/buffer_size_kb 
1410

新目录中的文件与原tracing目录中同名的文件的工作方式相同,只是所使用的缓冲区是一个单独的新缓冲区。这些文件会影响该缓冲区,但不会影响主缓冲区。

当前我们使用的内核版本linux5.0,已经有current_tracer和available_tracers,可以使用function tracer,但是不支持function_graph。

[root@idle tracing]# cat available_tracers 
function_graph wakeup_dl wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function nop
[root@idle tracing]# mkdir instances/idle
[root@idle tracing]# cat instances/idle/available_tracers 
wakeup_dl wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function nop

下面举例说明instances如何使用:

cd /sys/kernel/debug/tracing/ 
echo 0 > tracing_on
echo 0 > trace

echo function > current_tracer
echo vfs_open > ./set_ftrace_filter
echo 1 > ./options/func_stack_trace

mkdir instances/sched
echo 1 > instances/sched/events/sched/sched_wakeup/enable

mkdir instances/syscall
echo 1 > instances/syscall/events/syscalls/sys_enter_read/enable
echo 1 > instances/syscall/events/syscalls/sys_enter_readlinkat/enable

echo 1 > tracing_on

cat /mnt/ftrace_script/function/test.file

echo 0 > tracing_on
cat trace
cat instances/sched/trace
cat instances/syscall/trace

echo nop > ./current_tracer
echo 0 > ./options/func_stack_trace
echo !vfs_open >> ./set_ftrace_filter
echo 0 > trace
rmdir instances/sched
rmdir instances/syscall
 tracer: function
#
# entries-in-buffer/entries-written: 40/40   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
             cat-769   [002] ....  2286.434048: vfs_open <-do_last
             cat-769   [002] ....  2286.434125: <stack trace>
 => vfs_open
 => path_openat
 => do_filp_open
 => do_open_execat
 => __do_execve_file
 => do_execveat_common
 => do_execve
 => __se_sys_execve
 => __arm64_sys_execve
 => __invoke_syscall
 => invoke_syscall
 => el0_svc_common
 => el0_svc_handler
 => el0_svc
             cat-769   [002] ....  2286.437829: vfs_open <-do_last

# tracer: nop
#
# entries-in-buffer/entries-written: 155/155   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [003] dNs.  2285.484852: sched_wakeup: comm=rcu_sched pid=10 prio=120 tar
get_cpu=003
          <idle>-0     [003] dNs.  2285.500782: sched_wakeup: comm=rcu_sched pid=10 prio=120 tar
get_cpu=003
          <idle>-0     [003] dNs.  2285.532258: sched_wakeup: comm=rcu_sched pid=10 prio=120 tar
get_cpu=003
          <idle>-0     [000] dNs.  2285.539682: sched_wakeup: comm=ksoftirqd/0 pid=9 prio=120 ta
rget_cpu=000

# tracer: nop
#
# entries-in-buffer/entries-written: 18/18   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
             cat-769   [002] ....  2286.472346: sys_read(fd: 3, buf: ffffef106c00, count: 340)
             cat-769   [002] ....  2286.574676: sys_read(fd: 3, buf: ffff9a9ae000, count: 20000)
             cat-769   [002] ....  2286.591041: sys_read(fd: 3, buf: ffff9a9ae000, count: 20000)
            bash-766   [001] ....  2286.663201: sys_read(fd: fe, buf: aaab09e06310, count: 2dd)
           <...>-770   [002] ....  2286.787743: sys_read(fd: 3, buf: ffffc0ff16d0, count: 340)