linux trace学习(二)——trace使用

备注：
1. Kernel版本：4.19.123
2. 使用工具：Source Insight 4.0
3. 参考博客：
Linux ftrace框架介绍及运用
Linux ftrace 2.1、ftrace的使用

文章目录

linux trace学习(二)——trace使用
- trace通用使用方法
- - 使能和配置大小
  - trace、trace_pipe和snapshot的区别
  - tracer
  - instances
  - 特定CPU信息
  - trace选项设置
- tracepoint
- - trace Events生效条件
  - trace Events的过滤功能
  - Events的trigger功能
  - 在Linux command line启动Events
- irqsoff
- preemptoff

trace通用使用方法

使能和配置大小

配置trace的开关(tracing_on)

echo 0/1 > /sys/kernel/debug/tracing/tracing_on

配置trace的buff大小

# 设置RingBuffer的大小
echo n > /sys/kernel/debug/tracing/buffer_size_kb# buffer_total_size_kb就变成NR_CPUS的倍数
# cat /sys/kernel/debug/tracing/buffer_size_kb
7 (expanded: 1408)# cat /sys/kernel/debug/tracing/buffer_total_size_kb
21 (expanded: 4224)

trace、trace_pipe和snapshot的区别

trace是从RingBuffer中取出内容，trace_pipe会一直读取Buffer流。

snapshot是trace的一个瞬间快照：

配置CONFIG_TRACER_SNAPSHOT 将会使快照特性有效对于所有的non latency tracers。(Latency tracers仅仅记录最大延迟，例如“irqsoff” or “wakeup”，不能使用这个特性，因为它们已经在内部使用快照机制)。

快照在一个特定时间点保留当前trace buffer而不停止跟踪。ftrace交换当前缓存区和备用缓存区，在新的当前缓存区(之前的备用缓存区)中继续跟踪。

以下是tracefs中关于这个特性的相关配置文件：

# 清除和释放快照缓冲区
echo 0 > /sys/kernel/debug/tracing/snapshot # 申请一个快照缓冲区，然后从快照中读内容使用和trace文件同样的格式输出。读快照和系统tracing并行进行。
echo 1 > /sys/kernel/debug/tracing/snapshot # 非0和1外的数值，清除snapshot缓冲区内容
echo ^[0,1] > /sys/kernel/debug/tracing/snapshot

snapshot使用示例：

# echo 1 > /sys/kernel/debug/tracing/events/sched/enable
#
# echo 1 > /sys/kernel/debug/tracing/snapshot
#
# cat /sys/kernel/debug/tracing/snapshot
# tracer: nop
#
# entries-in-buffer/entries-written: 606/606   #P:3
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |sh-118   [000] dn.2 18136.674248: sched_stat_runtime: comm=sh pid=118 runtime=25084 [ns] vruntime=1183096730 [ns]sh-118   [000] dn.2 18136.674302: sched_stat_runtime: comm=sh pid=118 runtime=15208 [ns] vruntime=1183111938 [ns]sh-118   [000] dn.2 18136.674343: sched_stat_runtime: comm=sh pid=118 runtime=13166 [ns] vruntime=1183125104 [ns]sh-118   [000] dn.2 18136.674384: sched_stat_runtime: comm=sh pid=118 runtime=13708 [ns] vruntime=1183138812 [ns]sh-118   [000] dn.2 18136.674425: sched_stat_runtime: comm=sh pid=118 runtime=13583 [ns] vruntime=1183152395 [ns]sh-118   [000] dn.2 18136.674466: sched_stat_runtime: comm=sh pid=118 runtime=13541 [ns] vruntime=1183165936 [ns]sh-118   [000] dn.2 18136.674507: sched_stat_runtime: comm=sh pid=118 runtime=13291 [ns] vruntime=1183179227 [ns]sh-118   [000] dn.4 18136.674548: sched_wakeup: comm=migration/0 pid=13 prio=0 target_cpu=000sh-118   [000] dn.4 18136.674556: sched_wakeup: comm=migration/1 pid=16 prio=0 target_cpu=001sh-118   [000] dn.4 18136.674564: sched_wakeup: comm=migration/2 pid=21 prio=0 target_cpu=002<idle>-0     [001] d..2 18136.674565: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=migration/1 next_pid=16 next_prio=0sh-118   [000] dn.2 18136.674569: sched_stat_runtime: comm=sh pid=118 runtime=24125 [ns] vruntime=1183203352 [ns]<idle>-0     [002] d..2 18136.674572: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=migration/2 next_pid=21 next_prio=0[......]

tracer

从available_tracers可以获取系统支持的Tracer,current_tracer是当前使用中的Tracer。

Events只有在nop tracer下才会起作用，同时多个tracer不能共享。同一时候只能一个Tracer在生效。

# cat /sys/kernel/debug/tracing/available_tracers
function_graph irqsoff function nop#echo function > current_tracer

instances

在tracefs中有个“instances”文件夹，这个文件夹可以使用mkdir创建新的子文件夹、使用rmdir删除子文件夹。如果子文件夹被创建，它默认包含以下文件和文件夹：

# cd instances/
#
# mkdir test
#
# ls test/
available_tracers     set_event             trace_clock
buffer_size_kb        set_event_pid         trace_marker
buffer_total_size_kb  set_ftrace_filter     trace_marker_raw
current_tracer        set_ftrace_notrace    trace_options
events                set_ftrace_pid        trace_pipe
free_buffer           snapshot              tracing_cpumask
options               timestamp_mode        tracing_max_latency
per_cpu               trace                 tracing_on

如你所见，新的文件夹类似于tracing文件夹本身。实际上，它是非常类似的，除了buffer和events 是不可知的也许来自主文件夹或者是来自其他创建的实例。

在新文件夹中的文件拥有和tracing中文件一样的名字，除了它使用独立的新的buffer。这些文件影响自己的buffer不影响主buffer，除了trace_options，当前trace_options的配置会影响所有的新实例和top buffer都会保持一样，以后会改进这一点。

注意文件夹中没有“function tracer”文件，也没有“current_tracer”和“available_tracers”文件，这是因为这个buffer当前只会给trace event使用。

特定CPU信息

抓取特定cpu信息0~3：

#echo f > tracing_cpumask

查看特定CPU信息：

#cat per_cpu/cpu0/trace

trace选项设置

通过options内容设置，对Trace的输出进行定制，控制输出大小。
trace_option是options设置的结果，可以看出开了哪些选项，关闭了哪些选项。

# cat trace_options
print-parent
[......]
overwrite
nodisable_on_free
irq-info
markers
noevent-fork
function-trace
nofunction-fork
nodisplay-graph
nostacktrace
nofunc_stack_trace
#
# echo 0 > options/irq-info
#
# echo 0 > options/markers
#
# echo 0 > options/function-trace
#
# cat trace_options
print-parent
[......]
overwrite
nodisable_on_free
noirq-info
nomarkers
noevent-fork
nofunction-trace
nofunction-fork
nodisplay-graph
nostacktrace
nofunc_stack_trace

tracepoint

可以对系统特定事件进行跟踪，在available_events可以找到所有事件。
然后将需要的时间通过echo xxx >> set_event写入。也可以通过events目录来打开。
如：查找与irq相关的事件：

# cat available_events | grep irq
irq:softirq_raise
irq:softirq_exit
irq:softirq_entry
irq:irq_handler_exit
irq:irq_handler_entry
preemptirq:preempt_enable
preemptirq:preempt_disable
preemptirq:irq_enable
preemptirq:irq_disable

trace Events生效条件

在current_tracer为nop，然后设置tracing/events下面的enable，即可通过tracing/trace或者tracing/trace_pipe查看内容。

trace Events的过滤功能

echo net >set_event--------------------------------打开所有net目录下的事件echo skb >>set_event------------------------------附加设置skb到目录下

在events目录下，有很多子目录。这些目录里面可以使用filter，过滤很多不需要的信息。

通过format可以知道，timer_start这个时间的field名称，然后在filter进行设置。
针对某一pid进行过滤。

将对应pid写入set_event_pid，就可达到只监控某个进程的Events。
清空跟踪器

对子系统的filter写入0，即可清空整个子系统的filter
echo 0 > filter

Events的trigger功能


enable_event/disable_event
stacktrace
snapshot
traceon/traceoff

在Linux command line启动Events

irqsoff

当中断关闭CPU不能响应任何外部的事件，将会阻止内核响应timer、鼠标中断，对应的结果就是响应延迟。

irqsoff tracer追踪关中断时间，当一个新的最大latency到来时，它会记住新的最大latency event，丢弃掉旧的最大latency event。”echo 0 >tracing_max_latency”会复位最大值。

# echo 0 > options/function-trace
#
# echo irqsoff > current_tracer
#
# echo 1 > tracing_on
#
#
#
# echo 0 > tracing_max_latency
#
#  echo 0 > tracing_on
#
# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.19.123
# --------------------------------------------------------------------
# latency: 47 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:3)
#    -----------------
#    | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
#    -----------------
#  => started at: __irq_svc
#  => ended at:   __irq_svc-----------------记录禁止中断时间最长的开始和结束函数
#
#
#                  _------=> CPU#
#                 / _-----=> irqs-off-------------d表示中断被disabled，'.'表示中断没有被关闭。
#                | / _----=> need-resched------N-表示need_resched被设置；'.'-表示need_resched没有被设置，中断返回不会进行进程切换。
#                || / _---=> hardirq/softirq-----H-表示softirq中发生了硬件中断；h-硬件中断；s-softirq；'.'-不在中断上下文中。
#                ||| / _--=> preempt-depth-----当抢占中断势能后，该域代表preempt_disabled的级别。
#                |||| /     delay
#  cmd     pid   ||||| time  |   caller----------cmd-进程名，pid-进程id，time-表示trace从开始到当前的相对时间，delay-突出显示那些有高延迟的地方以便引起注意。！表示需要引起注意。
#     \   /      |||||  \    |   /         <idle>-0       0d..1    1us+: __irq_svc<idle>-0       0dn.1   46us : __irq_svc<idle>-0       0dn.1   49us+: tracer_hardirqs_on <-__irq_svc<idle>-0       0dn.1   77us : <stack trace>=> arch_cpu_idle=> default_idle_call=> do_idle=> cpu_startup_entry=> rest_init=> start_kernel

有47us的延迟
tracer_hardirqs_on <-__irq_svc关闭了中断

# echo 1 > options/function-trace
#
# echo irqsoff > current_tracer
#
# echo 1 > tracing_on
#
#
#
# echo 0 > tracing_max_latency
#
#  echo 0 > tracing_on
# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.19.123
# --------------------------------------------------------------------
# latency: 369 us, #205/205, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:3)
#    -----------------
#    | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
#    -----------------
#  => started at: __irq_svc
#  => ended at:   __irq_svc
#
#
#                  _------=> CPU#
#                 / _-----=> irqs-off
#                | / _----=> need-resched
#                || / _---=> hardirq/softirq
#                ||| / _--=> preempt-depth
#                |||| /     delay
#  cmd     pid   ||||| time  |   caller
#     \   /      |||||  \    |   /         <idle>-0       0d..1    1us : __irq_svc<idle>-0       0d..1    3us : gic_handle_irq <-__irq_svc<idle>-0       0d..1    4us : __handle_domain_irq <-gic_handle_irq<idle>-0       0d..1    6us : irq_enter <-__handle_domain_irq<idle>-0       0d..1    8us : rcu_irq_enter <-irq_enter[......]<idle>-0       0d..1  366us : rcu_dynticks_eqs_enter <-rcu_nmi_exit<idle>-0       0d..1  369us : __irq_svc<idle>-0       0d..1  371us+: tracer_hardirqs_on <-__irq_svc<idle>-0       0d..1  433us : <stack trace>=> arch_cpu_idle=> default_idle_call=> do_idle=> cpu_startup_entry=> rest_init=> start_kernel

有369us的延迟
但是我们可以看到在此之间的函数调用
使能function-trace增加了不少开销，会增加延迟时间，但是也提供了更多的有用信息

preemptoff

待补充。