在内核层面上分析事件有很多的工具:SystemTap、ktap、Sysdig、LTTNG 等等,你也可以在网络上找到关于这些工具的大量介绍文章和资料。
而对于使用 Linux 原生机制去跟踪系统事件以及检索/分析故障信息的方面的资料却很少找的到。这就是 ftrace,它是添加到内核中的第一款跟踪工具,今天我们来看一下它都能做什么,让我们从它的一些重要术语开始吧。
内核跟踪和分析
内核分析 Kernel profiling 可以发现性能“瓶颈”。分析能够帮我们发现在一个程序中性能损失的准确位置。特定的程序生成一个 概述 profile — 这是一个事件总结 — 它能够用于帮我们找出哪个函数占用了大量的运行时间。尽管这些程序并不能识别出为什么会损失性能。
瓶颈经常发生在无法通过分析来识别的情况下。要推断出为什么会发生事件,就必须保存发生事件时的相关上下文,这就需要去 跟踪 tracing 。
跟踪可以理解为在一个正常工作的系统上活动的信息收集过程。它使用特定的工具来完成这项工作,就像录音机来记录声音一样,用它来记录各种系统事件。
跟踪程序能够同时跟踪应用级和操作系统级的事件。它们收集的信息能够用于诊断多种系统问题。
有时候会将跟踪与日志比较。它们两者确时很相似,但是也有不同的地方。
对于跟踪,记录的信息都是些低级别事件。它们的数量是成百上千的,甚至是成千上万的。对于日志,记录的信息都是些高级别事件,数量上通常少多了。这些包含用户登录系统、应用程序错误、数据库事务等等。
就像日志一样,跟踪数据可以被原样读取,但是用特定的应用程序提取的信息更有用。所有的跟踪程序都能这样做。
在内核跟踪和分析方面,Linux 内核有三个主要的机制:
- 跟踪点 tracepoint :一种基于静态测试代码的工作机制
- 探针 kprobe :一种动态跟踪机制,用于在任意时刻中断内核代码的运行,调用它自己的处理程序,在完成需要的操作之后再返回
- perf_events —— 一个访问 PMU( 性能监视单元 Performance Monitoring Unit )的接口
我并不想在这里写关于这些机制方面的内容,任何对它们感兴趣的人可以去访问 Brendan Gregg 的博客。
使用 ftrace,我们可以与这些机制进行交互,并可以从用户空间直接得到调试信息。下面我们将讨论这方面的详细内容。示例中的所有命令行都是在内核版本为 3.13.0-24 的 Ubuntu 14.04 中运行的。
ftrace:常用信息
ftrace 是 Function Trace 的简写,但它能做的远不止这些:它可以跟踪上下文切换、测量进程阻塞时间、计算高优先级任务的活动时间等等。
ftrace 是由 Steven Rostedt 开发的,从 2008 年发布的内核 2.6.27 中开始就内置了。这是为记录数据提供的一个调试 Ring 缓冲区的框架。这些数据由集成到内核中的跟踪程序来采集。
ftrace 工作在 debugfs 文件系统上,在大多数现代 Linux 发行版中都默认挂载了。要开始使用 ftrace,你将进入到 sys/kernel/debug/tracing
目录(仅对 root 用户可用):
# cd /sys/kernel/debug/tracing
这个目录的内容看起来应该像这样:
аvailable_filter_functions options stack_trace_filter
available_tracers per_cpu trace
buffer_size_kb printk_formats trace_clock
buffer_total_size_kb README trace_marker
current_tracer saved_cmdlines trace_options
dyn_ftrace_total_info set_event trace_pipe
enabled_functions set_ftrace_filter trace_stat
events set_ftrace_notrace tracing_cpumask
free_buffer set_ftrace_pid tracing_max_latency
function_profile_enabled set_graph_function tracing_on
instances set_graph_notrace tracing_thresh
kprobe_events snapshot uprobe_events
kprobe_profile stack_max_size uprobe_profile
我不想去描述这些文件和子目录;它们的描述在 官方文档 中已经写的很详细了。我只想去详细介绍与我们这篇文章相关的这几个文件:
- available_tracers —— 可用的跟踪程序
- current_tracer —— 正在运行的跟踪程序
- tracing_on —— 负责启用或禁用数据写入到 Ring 缓冲区的系统文件(如果启用它,数字 1 被添加到文件中,禁用它,数字 0 被添加)
- trace —— 以人类友好格式保存跟踪数据的文件
可用的跟踪程序
我们可以使用如下的命令去查看可用的跟踪程序的一个列表:
root@andrei:/sys/kernel/debug/tracing#: cat available_tracers
blk mmiotrace function_graph wakeup_rt wakeup function nop
我们来快速浏览一下每个跟踪程序的特性:
- function —— 一个无需参数的函数调用跟踪程序
- function_graph —— 一个使用子调用的函数调用跟踪程序
- blk —— 一个与块 I/O 跟踪相关的调用和事件跟踪程序(它是 blktrace 使用的)
- mmiotrace —— 一个内存映射 I/O 操作跟踪程序
- nop —— 最简单的跟踪程序,就像它的名字所暗示的那样,它不做任何事情(尽管在某些情况下可能会派上用场,我们将在后文中详细解释)
函数跟踪程序
在开始介绍函数跟踪程序 ftrace 之前,我们先看一个测试脚本:
#!/bin/sh
dir=/sys/kernel/debug/tracing
sysctl kernel.ftrace_enabled=1
echo function > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on
sleep 1
echo 0 > ${dir}/tracing_on
less ${dir}/trace
这个脚本是非常简单的,但是还有几个需要注意的地方。命令 sysctl ftrace.enabled=1
启用了函数跟踪程序。然后我们通过写它的名字到 current_tracer
文件来启用 current tracer
。
接下来,我们写入一个 1
到 tracing_on
,它启用了 Ring 缓冲区。这些语法都要求在 1
和 >
符号前后有一个空格;写成像 echo 1> tracing_on
这样将不能工作。一行之后我们禁用它(如果 0
写入到 tracing_on
, 缓冲区不会被清除并且 ftrace 并不会被禁用)。
我们为什么这样做呢?在两个 echo
命令之间,我们看到了命令 sleep 1
。我们启用了缓冲区,运行了这个命令,然后禁用它。这将使跟踪程序采集了这个命令运行期间发生的所有系统调用的信息。
在脚本的最后一行,我们写了一个在控制台上显示跟踪数据的命令。
一旦脚本运行完成后,我们将看到下列的输出(这里只列出了一个小片断):
# tracer: function
#
# entries-in-buffer/entries-written: 29571/29571 #P:2
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
trace.sh-1295 [000] .... 90.502874: mutex_unlock