关于使用事件和跟踪点分析行为的说明¶

作者:: Mel Gorman (PCL 信息主要基于 Ingo Molnar 的电子邮件)

1. 简介¶

跟踪点（请参阅使用 Linux 内核跟踪点）可以在不创建自定义内核模块的情况下使用，以使用事件跟踪基础设施注册探测函数。

简单来说，跟踪点代表了重要的事件，可以将它们与其他跟踪点结合起来，以构建系统内部发生情况的“全貌”。有许多方法可以收集和解释这些事件。在没有任何当前最佳实践的情况下，本文档描述了一些可以使用的方法。

本文档假定 debugfs 已挂载在 /sys/kernel/debug 上，并且已在内核中配置了适当的跟踪选项。假设 PCL 工具 tools/perf 已经安装并且在您的路径中。

2. 列出可用事件¶

2.1 标准实用程序¶

所有可能的事件都可以在 /sys/kernel/tracing/events 中看到。简单地调用

$ find /sys/kernel/tracing/events -type d

将大致指示可用的事件数量。

2.2 PCL (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 系统范围的事件启用¶

有关如何系统范围地启用事件的正确描述，请参阅事件跟踪。启用与页面分配相关的所有事件的一个简短示例如下：

$ 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 开关并分析睡眠，可以检查一段时间内的系统范围的事件。

$ 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 - 函数跟踪器描述了如何使用 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 - 函数跟踪器深入介绍了如何在 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 的列表中将许多页面释放到主分配器，它会将其识别为每个 CPU 的耗尽，即使没有该事件的特定跟踪点

它可以基于 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)

乍一看，似乎时间花在了将像素图复制到卡上。需要进一步调查以确定为什么像素图会被如此频繁地复制，但一个起点是将 libpixmap 的一个古老的构建版本从几个月前完全被遗忘的库路径中取出！

Linux 内核

目录

本页