关于使用事件和跟踪点分析行为的注意事项¶

作者:: 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 内核

目录

本页