linux trace学习(二)——trace使用
备注：
1. Kernel版本：4.19.123
2. 使用工具：Source Insight 4.0
3. 参考博客：
Linux ftrace框架介绍及运用
Linux ftrace 2.1、ftrace的使用
文章目录
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=000
sh-118 [000] dn.4 18136.674556: sched_wakeup: comm=migration/1 pid=16 prio=0 target_cpu=001
sh-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=0
sh-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
待补充。
1950
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
