使用事件和追踪点分析行为的说明¶
- 作者:
Mel Gorman（PCL 信息在很大程度上基于 Ingo Molnar 的电子邮件）
1. 简介¶
追踪点（参见 Using the Linux Kernel Tracepoints）可以无需创建自定义内核模块，即可通过事件追踪基础架构注册探测函数。
简而言之，追踪点代表了重要的事件，可以与其他追踪点结合使用，以构建系统内部运行情况的“宏观图景”。收集和解释这些事件的方法有很多。在缺乏当前最佳实践的情况下，本文档描述了一些可以使用的方法。
本文档假定 debugfs 已挂载在 /sys/kernel/debug 上，并且已在内核中配置了适当的追踪选项。同时假定 PCL 工具 tools/perf 已安装并且位于您的路径中。
2. 列出可用事件¶
2.1 标准工具¶
所有可能的事件都可以在 /sys/kernel/tracing/events 中看到。只需简单调用
$ find /sys/kernel/tracing/events -type d
就会大致显示出可用事件的数量。
2.2 PCL (Performance Counters for Linux)¶
使用 perf 工具可以发现和枚举所有计数器和事件（包括追踪点）。获取可用事件列表非常简单：
$ perf list 2>&1 | grep Tracepoint
ext4:ext4_free_inode [Tracepoint event]
ext4:ext4_request_inode [Tracepoint event]
ext4:ext4_allocate_inode [Tracepoint event]
ext4:ext4_write_begin [Tracepoint event]
ext4:ext4_ordered_write_end [Tracepoint event]
[ .... remaining output snipped .... ]
3. 启用事件¶
3.1 系统范围的事件启用¶
有关如何在系统范围内启用事件的正确描述，请参见 Event Tracing。启用与页面分配相关的所有事件的一个简短示例如下：
$ for i in `find /sys/kernel/tracing/events -name "enable" | grep mm_`; do echo 1 > $i; done
3.2 使用 SystemTap 在系统范围内启用事件¶
在 SystemTap 中，可以使用 kernel.trace() 函数调用来访问追踪点。以下是一个每 5 秒报告一次是哪些进程在分配页面的示例。
global page_allocs
probe kernel.trace("mm_page_alloc") {
page_allocs[execname()]++
}
function print_count() {
printf ("%-25s %-s\n", "#Pages Allocated", "Process Name")
foreach (proc in page_allocs-)
printf("%-25d %s\n", page_allocs[proc], proc)
printf ("\n")
delete page_allocs
}
probe timer.s(5) {
print_count()
}
3.3 使用 PCL 在系统范围内启用事件¶
通过指定 -a 开关并分析 sleep，可以检查持续一段时间内的系统范围事件。
$ perf stat -a \
-e kmem:mm_page_alloc -e kmem:mm_page_free \
-e kmem:mm_page_free_batched \
sleep 10
Performance counter stats for 'sleep 10':
9630 kmem:mm_page_alloc
2143 kmem:mm_page_free
7424 kmem:mm_page_free_batched
10.002577764 seconds time elapsed
类似地，可以执行一个 shell 并在需要时退出它，以获取此时的报告。
3.4 局部事件启用¶
ftrace - Function Tracer 描述了如何使用 set_ftrace_pid 按线程启用事件。
3.5 使用 PCL 启用局部事件¶
可以使用 PCL 在进程的持续时间内按局部基础激活和跟踪事件，如下所示。
$ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free \
-e kmem:mm_page_free_batched ./hackbench 10
Time: 0.909
Performance counter stats for './hackbench 10':
17803 kmem:mm_page_alloc
12398 kmem:mm_page_free
4827 kmem:mm_page_free_batched
0.973913387 seconds time elapsed
4. 事件过滤¶
ftrace - Function Tracer 深入介绍了如何在 ftrace 中过滤事件。显然，使用 grep 和 awk 处理 trace_pipe 是一种选择，任何读取 trace_pipe 的脚本也是如此。
5. 使用 PCL 分析事件方差¶
任何工作负载在多次运行之间都可能表现出差异，了解标准偏差可能很重要。大体上，这需要由性能分析人员手动完成。如果离散事件的发生对性能分析人员有用，则可以使用 perf。
$ perf stat --repeat 5 -e kmem:mm_page_alloc -e kmem:mm_page_free
-e kmem:mm_page_free_batched ./hackbench 10
Time: 0.890
Time: 0.895
Time: 0.915
Time: 1.001
Time: 0.899
Performance counter stats for './hackbench 10' (5 runs):
16630 kmem:mm_page_alloc ( +- 3.542% )
11486 kmem:mm_page_free ( +- 4.771% )
4730 kmem:mm_page_free_batched ( +- 2.325% )
0.982653002 seconds time elapsed ( +- 1.448% )
如果需要依赖离散事件聚合的某些更高层级的事件，则需要开发脚本。
使用 --repeat，还可以结合 -a 和 sleep 在系统范围内查看事件随时间波动的状况。
$ perf stat -e kmem:mm_page_alloc -e kmem:mm_page_free \
-e kmem:mm_page_free_batched \
-a --repeat 10 \
sleep 1
Performance counter stats for 'sleep 1' (10 runs):
1066 kmem:mm_page_alloc ( +- 26.148% )
182 kmem:mm_page_free ( +- 5.464% )
890 kmem:mm_page_free_batched ( +- 30.079% )
1.002251757 seconds time elapsed ( +- 0.005% )
6. 使用辅助脚本进行更高级别的分析¶
当启用事件时，触发的事件可以从 /sys/kernel/tracing/trace_pipe 中以人类可读的格式读取，尽管也存在二进制选项。通过对输出进行后处理，可以酌情在线收集更多信息。后处理的示例可能包括：
从 /proc 中读取触发该事件的 PID 的信息
从一系列低级事件派生出一个高级事件。
计算两个事件之间的延迟
Documentation/trace/postprocess/trace-pagealloc-postprocess.pl 是一个示例脚本，它可以从 STDIN 或追踪副本中读取 trace_pipe。在线使用时，中断一次可以生成报告而不退出，中断两次则会退出。
简而言之，该脚本只是读取 STDIN 并对事件进行计数，但它也可以做更多事情，例如：
从许多低级事件中派生高级事件。如果许多页面从每个 CPU 列表（per-CPU lists）释放回主分配器，它会将其识别为一个 per-CPU 排空（drain），即使该事件没有特定的追踪点
它可以基于 PID 或单个进程编号进行聚合
如果内存出现外部碎片，它会报告碎片事件是严重还是中等。
在接收到关于某个 PID 的事件时，它可以记录其父进程是谁，这样如果大量事件来自生命周期极短的进程，就可以识别出负责创建所有这些辅助进程的父进程
7. 使用 PCL 进行更低级别的分析¶
可能还存在这样的需求：识别程序中的哪些函数在内核中生成了事件。要开始此类分析，必须记录数据。在撰写本文时，这需要 root 权限
$ perf record -c 1 \
-e kmem:mm_page_alloc -e kmem:mm_page_free \
-e kmem:mm_page_free_batched \
./hackbench 10
Time: 0.894
[ perf record: Captured and wrote 0.733 MB perf.data (~32010 samples) ]
请注意使用 ‘-c 1’ 来设置采样的事件周期。默认采样周期相当高，以最大限度地减少开销，但收集的信息因此可能会非常粗糙。
此记录输出了一个名为 perf.data 的文件，可以使用 perf report 对其进行分析。
$ perf report
# Samples: 30922
#
# Overhead Command Shared Object
# ........ ......... ................................
#
87.27% hackbench [vdso]
6.85% hackbench /lib/i686/cmov/libc-2.9.so
2.62% hackbench /lib/ld-2.9.so
1.52% perf [vdso]
1.22% hackbench ./hackbench
0.48% hackbench [kernel]
0.02% perf /lib/i686/cmov/libc-2.9.so
0.01% perf /usr/bin/perf
0.01% perf /lib/ld-2.9.so
0.00% hackbench /lib/i686/cmov/libpthread-2.9.so
#
# (For more details, try: perf report --sort comm,dso,symbol)
#
据此，绝大多数事件都是在 VDSO 内的事件上触发的。对于简单的二进制文件，通常会是这样，所以让我们看一个稍微不同的例子。在撰写本文的过程中，我们注意到 X 正在生成大量的页面分配，因此让我们来看看它：
$ perf record -c 1 -f \
-e kmem:mm_page_alloc -e kmem:mm_page_free \
-e kmem:mm_page_free_batched \
-p `pidof X`
这在几秒钟后被中断，并且
$ perf report
# Samples: 27666
#
# Overhead Command Shared Object
# ........ ....... .......................................
#
51.95% Xorg [vdso]
47.95% Xorg /opt/gfx-test/lib/libpixman-1.so.0.13.1
0.09% Xorg /lib/i686/cmov/libc-2.9.so
0.01% Xorg [kernel]
#
# (For more details, try: perf report --sort comm,dso,symbol)
#
因此，将近一半的事件发生在某个库中。为了解哪个符号
$ perf report --sort comm,dso,symbol
# Samples: 27666
#
# Overhead Command Shared Object Symbol
# ........ ....... ....................................... ......
#
51.95% Xorg [vdso] [.] 0x000000ffffe424
47.93% Xorg /opt/gfx-test/lib/libpixman-1.so.0.13.1 [.] pixmanFillsse2
0.09% Xorg /lib/i686/cmov/libc-2.9.so [.] _int_malloc
0.01% Xorg /opt/gfx-test/lib/libpixman-1.so.0.13.1 [.] pixman_region32_copy_f
0.01% Xorg [kernel] [k] read_hpet
0.01% Xorg /opt/gfx-test/lib/libpixman-1.so.0.13.1 [.] get_fast_path
0.00% Xorg [kernel] [k] ftrace_trace_userstack
要查看在 pixmanFillsse2 函数内部的什么地方出了问题
$ perf annotate pixmanFillsse2
[ ... ]
0.00 : 34eeb: 0f 18 08 prefetcht0 (%eax)
: }
:
: extern __inline void __attribute__((__gnu_inline__, __always_inline__, _
: _mm_store_si128 (__m128i *__P, __m128i __B) : {
: *__P = __B;
12.40 : 34eee: 66 0f 7f 80 40 ff ff movdqa %xmm0,-0xc0(%eax)
0.00 : 34ef5: ff
12.40 : 34ef6: 66 0f 7f 80 50 ff ff movdqa %xmm0,-0xb0(%eax)
0.00 : 34efd: ff
12.39 : 34efe: 66 0f 7f 80 60 ff ff movdqa %xmm0,-0xa0(%eax)
0.00 : 34f05: ff
12.67 : 34f06: 66 0f 7f 80 70 ff ff movdqa %xmm0,-0x90(%eax)
0.00 : 34f0d: ff
12.58 : 34f0e: 66 0f 7f 40 80 movdqa %xmm0,-0x80(%eax)
12.31 : 34f13: 66 0f 7f 40 90 movdqa %xmm0,-0x70(%eax)
12.40 : 34f18: 66 0f 7f 40 a0 movdqa %xmm0,-0x60(%eax)
12.31 : 34f1d: 66 0f 7f 40 b0 movdqa %xmm0,-0x50(%eax)
乍一看，似乎时间都花在了将像素图（pixmaps）复制到显卡上。需要进一步调查以确定为什么像素图被复制得如此频繁，但一个出发点是从几个月前被完全遗忘的库路径中清除掉一个陈旧的 libpixmap 构建版本！