动态追踪技术(二)：trace your kernel Functions!

Ftrace是一个设计用来帮助开发者和设计者监视内核的追踪器，可用于调试或分析延迟以及性能问题。ftrace令人印象最深刻的是作为一个function tracer，内核函数调用、耗时等情况一览无余。另外，ftrace最常见的用途是事件追踪，通过内核是成百上千的静态事件点，看到系统内核的哪些部分在运行。实际上，ftrace更是一个追踪框架，它具备丰富工具集：延迟跟踪检查、何时发生中断、任务的启用、禁用及抢占等。在ftrace的基线版本之上，还有很多第三方提供的开源工具，用于简化操作或者提供数据可视化等扩展应用。

一、Introduction

Developer(s): Steven Rostedt(RedHat) and others
Initial release: October 9, 2008;
Operating system: Linux （merged into the Linux kernel mainline in kernel version 2.6.27）
Type: Kernel extension
License: GNU GPL
Website: www.kernel.org/doc/Documentation/trace

二、ABC

在使用ftrace之前，需要确认调试目录是否已经挂载，默认目录：/sys/kernel/debug/ 。

debugfs是Linux内核中一种特殊的文件系统，非常易用、基于RAM，专门设计用于调试。（since version 2.6.10-rc3，https://en.wikipedia.org/wiki/Debugfs)。

mount -t debugfs none /sys/kernel/debug
或者指定到自己的目录
mkdir /debug
mount -t debugfs nodev /debug

挂载之后会自动创建如下文件：

/sys/kernel/debug# ls -lrt
drwxr-xr-x.  2 root root 0 12月 28 17:24 x86
drwxr-xr-x.  3 root root 0 12月 28 17:24 boot_params
drwxr-xr-x. 34 root root 0 12月 28 17:24 bdi
-r--r--r--.  1 root root 0 12月 28 17:24 gpio
drwxr-xr-x.  3 root root 0 12月 28 17:24 usb
drwxr-xr-x.  4 root root 0 12月 28 17:24 xen
drwxr-xr-x.  6 root root 0 12月 28 17:24 tracing
drwxr-xr-x.  2 root root 0 12月 28 17:24 extfrag
drwxr-xr-x.  2 root root 0 12月 28 17:24 dynamic_debug
drwxr-xr-x.  2 root root 0 12月 28 17:24 hid
-rw-r--r--.  1 root root 0 12月 28 17:24 sched_features
drwxr-xr-x.  2 root root 0 12月 28 17:24 mce
drwxr-xr-x.  2 root root 0 12月 28 17:24 kprobes
-r--r--r--.  1 root root 0 12月 28 17:24 vmmemctl
/sys/kernel/debug/tracing# ls -lrt
-rw-r--r--.  1 root root 0 12月 28 17:24 tracing_thresh
-rw-r--r--.  1 root root 0 12月 28 17:24 tracing_on
-rw-r--r--.  1 root root 0 12月 28 17:24 tracing_max_latency
-rw-r--r--.  1 root root 0 12月 28 17:24 tracing_enabled
-rw-r--r--.  1 root root 0 12月 28 17:24 tracing_cpumask
drwxr-xr-x.  2 root root 0 12月 28 17:24 trace_stat
-r--r--r--.  1 root root 0 12月 28 17:24 trace_pipe
-rw-r--r--.  1 root root 0 12月 28 17:24 trace_options
--w--w----.  1 root root 0 12月 28 17:24 trace_marker
-rw-r--r--.  1 root root 0 12月 28 17:24 trace_clock
-rw-r--r--.  1 root root 0 12月 28 17:24 trace
-rw-r--r--.  1 root root 0 12月 28 17:24 sysprof_sample_period
-r--r--r--.  1 root root 0 12月 28 17:24 set_graph_function
-rw-r--r--.  1 root root 0 12月 28 17:24 set_ftrace_pid
-rw-r--r--.  1 root root 0 12月 28 17:24 set_ftrace_notrace
-r--r--r--.  1 root root 0 12月 28 17:24 saved_cmdlines
-r--r--r--.  1 root root 0 12月 28 17:24 README
drwxr-xr-x.  2 root root 0 12月 28 17:24 options
-rw-r--r--.  1 root root 0 12月 28 17:24 function_profile_enabled
-r--r--r--.  1 root root 0 12月 28 17:24 dyn_ftrace_total_info
-rw-r--r--.  1 root root 0 12月 28 17:24 buffer_size_kb
-r--r--r--.  1 root root 0 12月 28 17:24 available_tracers
-r--r--r--.  1 root root 0 12月 28 17:24 available_filter_functions
-rw-r--r--.  1 root root 0 12月 28 17:24 set_event
-r--r--r--.  1 root root 0 12月 28 17:24 printk_formats
drwxr-xr-x. 34 root root 0 12月 28 17:24 per_cpu
drwxr-xr-x. 24 root root 0 12月 28 17:24 events
-r--r--r--.  1 root root 0 12月 28 17:24 available_events
-r--r--r--.  1 root root 0 12月 28 17:24 kprobe_profile
-rw-r--r--.  1 root root 0 12月 28 17:24 kprobe_events
-r--r--r--.  1 root root 0 12月 28 17:24 stack_trace
-rw-r--r--.  1 root root 0 12月 28 17:24 stack_max_size
-rw-r--r--.  1 root root 0 5月  31 11:50 current_tracer
-rwxr-xr-x.  1 root root 0 5月  31 11:57 set_ftrace_filter

三、BASIC

1. Function tracer

以Function tracer为例，结果存储在 trace，该文件类似一张报表，该表将显示 4 列信息。首先是进程信息，包括进程名和PID ；第二列是CPU；第三列是时间戳；第四列是函数信息，缺省情况下，这里将显示内核函数名以及它的上一层调用函数。

cd /sys/kernel/debug/tracing
echo function > current_tracer
cat trace

# tracer: function
#
#  TASK-PID   CPU#  TIMESTAMP        FUNCTION
#   |  |       |  
gmond-6684  [004] 13285965.088308: _spin_lock <-hrtimer_interrupt
gmond-6684  [004] 13285965.088308: ktime_get_update_offsets <-hrtimer_interrupt
gmond-6684  [004] 13285965.088309: __run_hrtimer <-hrtimer_interrupt
gmond-6684  [004] 13285965.088309: __remove_hrtimer <-__run_hrtimer
gmond-6684  [004] 13285965.088309: tick_sched_timer <-__run_hrtimer
gmond-6684  [004] 13285965.088309: ktime_get <-tick_sched_timer
gmond-6684  [004] 13285965.088310: tick_do_update_jiffies64 <-tick_sched_timer
gmond-6684  [004] 13285965.088310: update_process_times <-tick_sched_timer

2. Function graph tracer

Function graph tracer 和 function tracer 类似，但输出为函数调用图，更加容易阅读：

# tracer: function_graph
#
#     TIME        CPU  DURATION                  FUNCTION CALLS
#      |          |     |   |                     |   |   |   |
 21)   ==========> |
 21)               |  smp_apic_timer_interrupt() {
 31)   ==========> |
 31)               |  smp_apic_timer_interrupt() {
 8)               |  smp_apic_timer_interrupt() {
 11)   2.598 us    |    native_apic_mem_write();
 18)   3.106 us    |    native_apic_mem_write();
 30)   ==========> |
 30)               |  smp_apic_timer_interrupt() {
  3)   3.590 us    |    native_apic_mem_write();
 22)   2.944 us    |    native_apic_mem_write();
  7)   3.392 us    |    native_apic_mem_write();
 17)   ==========> |
 17)               |  smp_apic_timer_interrupt() {
 27)   ==========> |
 27)               |  smp_apic_timer_interrupt() {
 16)   ==========> |
 16)               |  smp_apic_timer_interrupt() {
Linux ftrace tracers

四、体系结构

Ftrace有两大组成部分，framework和一系列的tracer 。每个tracer完成不同的功能，它们统一由framework管理。 ftrace 的trace信息保存在ring buffer中，由framework负责管理。Framework 利用debugfs建立tracing目录，并提供了一系列的控制文件。

Linux ftrace架构示意图

ftrace is a dynamic tracing system. 当你开始“ftracing”一个内核函数的时候，该函数的代码实际上就已经发生变化了。内核将在程序集中插入一些额外的指令，使得函数调用时可以随时通知追踪程序。

WARNNING:使用ftrace追踪内核将有可能对系统性能产生影响，追踪的函数越多，开销越大。
使用者必须提前做好准备工作，生产环境必须谨慎使用。

#cat available_tracers //查看支持的tracers
blk kmemtrace function_graph wakeup_rt wakeup function sysprof sched_switch initcall nop

五、Useful Tools

1. trace-cmd

trace-cmd是一个非常有用的Ftrace命令行工具。

sudo apt-get install trace-cmd
或者
git clone git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

使用方法：


sudo trace-cmd record --help #help
sudo trace-cmd record -p function -P 123456 #record for PID
sudo trace-cmd record -p function -l do_page_fault #record for function
  plugin 'function'
Hit Ctrl^C to stop recording

trace.dat

$ sudo trace-cmd report
          chrome-15144 [000] 11446.466121: function:             do_page_fault
          chrome-15144 [000] 11446.467910: function:             do_page_fault
          chrome-15144 [000] 11446.469174: function:             do_page_fault
          chrome-15144 [000] 11446.474225: function:             do_page_fault
          chrome-15144 [000] 11446.474386: function:             do_page_fault
          chrome-15144 [000] 11446.478768: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.480172: function:             do_page_fault
          chrome-1830  [003] 11446.486696: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.488983: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.489034: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.489045: function:             do_page_fault

在很有情况下不能使用函数追踪，需要依赖 事件追踪 的支持，例如：

# cat available_events  //查看支持的事件类型
power:power_start
power:power_frequency
power:power_end

sched:sched_kthread_stop
sched:sched_kthread_stop_ret
sched:sched_wait_task
sched:sched_wakeup
sched:sched_wakeup_new
sched:sched_switch
sched:sched_migrate_task
sched:sched_process_free
sched:sched_process_exit
sched:sched_process_wait
sched:sched_process_fork
sched:sched_stat_wait
sched:sched_stat_sleep
sched:sched_stat_iowait
sched:sched_stat_runtime

sudo trace-cmd record -e sched:sched_switch
sudo trace-cmd report

输出如下：

 16169.624862:   Chrome_ChildIOT:24817 [112] S ==> chrome:15144 [120]
 16169.624992:   chrome:15144 [120] S ==> swapper/3:0 [120]
 16169.625202:   swapper/3:0 [120] R ==> Chrome_ChildIOT:24817 [112]
 16169.625251:   Chrome_ChildIOT:24817 [112] R ==> chrome:1561 [112]
 16169.625437:   chrome:1561 [112] S ==> chrome:15144 [120]

切换路径：PID 24817 -> 15144 -> kernel -> 24817 -> 1561 -> 15114。

2. perf-tools

perf-tools 是性能调试大神Brendan Gregg开发的一个工具包，提供了很多强大的功能，例如：
iosnoop: 磁盘I/O分析详细包括延迟
iolatency: 磁盘I/O分析概要(柱状图)
execsnoop: 追踪进程exec()
opensnoop: 追踪open()系统调用，包含文件名
killsnoop: 追踪kill()信号（进程和信号详细）

代码下载：https://github.com/brendangregg/perf-tools

# ./execsnoop  //显示新进程和参数：
Tracing exec()s. Ctrl-C to end.
   PID   PPID ARGS
 22898  22004 man ls
 22905  22898 preconv -e UTF-8
 22908  22898 pager -s
 22907  22898 nroff -mandoc -rLL=164n -rLT=164n -Tutf8
 22906  22898 tbl
 22911  22910 locale charmap
 22912  22907 groff -mtty-char -Tutf8 -mandoc -rLL=164n -rLT=164n
 22913  22912 troff -mtty-char -mandoc -rLL=164n -rLT=164n -Tutf8
 22914  22912 grotty


# ./iolatency -Q  //测量设备I/O延迟
Tracing block I/O. Output every 1 seconds. Ctrl-C to end.
  >=(ms) .. <(ms)   : I/O      |Distribution                          |
       0 -> 1       : 1913     |######################################|
       1 -> 2       : 438      |#########                             |
       2 -> 4       : 100      |##                                    |
       4 -> 8       : 145      |###                                   |
       8 -> 16      : 43       |#                                     |
      16 -> 32      : 43       |#                                     |
      32 -> 64      : 1        |#                                     |
[...]

六、可视化工具:KernelShark

KernelShark是trace-cmd的前端工具，提供了对trace.dat的可视化分析（Graph View 、List View、Simple and Advance filtering）。


Linux ftrace KernelShark
Linux ftrace KernelShark Filters

扩展阅读：Linux 操作系统

推荐：电子书《Linux Perf Master》

发表在GitBook平台，欢迎订阅、下载、批评指正:
https://www.gitbook.com/book/riboseyim/linux-perf-master/details

eBook
最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 206,602评论 6赞 481
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 88,442评论 2赞 382
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 152,878评论 0赞 344
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 55,306评论 1赞 279
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 64,330评论 5赞 373
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 49,071评论 1赞 285
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 38,382评论 3赞 400
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 37,006评论 0赞 259
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 43,512评论 1赞 300
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,965评论 2赞 325
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,094评论 1赞 333
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,732评论 4赞 323
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,283评论 3赞 307
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,286评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,512评论 1赞 262
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 45,536评论 2赞 354
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,828评论 2赞 345

推荐阅读更多精彩内容