Off-CPU Analysis

性能问题可以分为以下两种类型之一:

  • On-CPU :线程花费时间在 CPU 上运行。
  • Off-CPU :在 I/O、锁、定时器、分页/交换等阻塞时花费时间等待。

非 CPU 分析是一种性能方法,其中测量和研究非 CPU 时间,以及堆栈跟踪等上下文。它与 CPU 分析不同,后者仅检查在 CPU 上执行的线程。在这里,目标是阻塞和脱离 CPU 的线程状态,如右图中的蓝色所示。

Off-CPU 分析是对 CPU 分析的补充,因此可以理解 100% 的线程时间。这种方法也不同于检测通常阻塞的应用程序功能的跟踪技术,因为这种方法针对的是内核调度程序的阻塞概念,这是一个方便的包罗万象的方法。

线程离开 CPU 的原因有很多,包括 I/O 和锁,但也有一些与当前线程的执行无关的原因,包括由于对 CPU 资源的高需求和中断而导致的非自愿上下文切换。不管是什么原因,如果这发生在工作负载请求(同步代码路径)期间,那么它就会引入延迟。

在本页中,我将介绍非 CPU 时间作为指标,并总结非 CPU 分析的技术。作为非 CPU 分析的示例实现,我将把它应用到 Linux,然后在后面的部分中总结其他操作系统。

目录:

1. 先决条件
2. 简介
3. 开销
4. Linux
5. Off-CPU 时间
6. Off-CPU 分析
7. 请求上下文
8. 注意事项 9. 火焰图
10. 唤醒
11. 其他操作系统
12. 起源
13. 总结
14. 更新

先决条件

CPU 外分析需要堆栈跟踪可供跟踪器使用,您可能需要先修复它。许多应用程序都使用 -fomit-frame-pointer gcc 选项编译,打破了基于帧指针的堆栈遍历。像 Java 这样的 VM 运行时动态编译方法,如果没有额外的帮助,跟踪器可能无法找到它们的符号信息,导致堆栈跟踪仅是十六进制。还有其他陷阱。请参阅我之前关于修复堆栈跟踪JIT 符号以获得性能的文章。

介绍

为了解释off-CPU分析的作用,我先总结一下CPU采样和跟踪进行比较。然后,我将总结两种非 CPU 分析方法:跟踪和采样。虽然十多年来我一直在推广非 CPU 分析,但它仍然不是一种广泛使用的方法,部分原因是生产 Linux 环境中缺乏测量它的工具。现在,eBPF 和更新的 Linux 内核(4.8+)正在改变这种情况。

1. CPU 采样

许多传统的分析工具使用对所有 CPU 的活动进行定时采样,以特定时间间隔或速率(例如,99 赫兹)收集当前指令地址(程序计数器)或整个堆栈回溯跟踪的快照。这将给出正在运行的函数或堆栈跟踪的计数,从而可以计算出 CPU 周期花费在何处的合理估计。在 Linux 上,采样模式下的perf工具(例如 -F 99)会进行定时 CPU 采样。

考虑应用程序函数 A() 调用函数 B(),它进行阻塞系统调用:


    CPU Sampling ----------------------------------------------->
     |  |  |  |  |  |  |                      |  |  |  |  |         
     A  A  A  A  B  B  B                      B  A  A  A  A         
    A(---------.                                .----------)        
               |                                |                   
               B(--------.                   .--)                   
                         |                   |         user-land    
   - - - - - - - - - - syscall - - - - - - - - - - - - - - - - -    
                         |                   |         kernel       
                         X     Off-CPU       |                      
                       block . . . . . interrupt  

虽然这对于研究 CPU 上的问题非常有效,包括热代码路径和自适应互斥体自旋,但当应用程序阻塞并等待 CPU 外时,它不会收集数据。

  1. 应用程序跟踪
    App Tracing ------------------------------------------------>
    |          |                                |          |        
    A(         B(                               B)         A)       
                                                                    
    A(---------.                                .----------)        
               |                                |                   
               B(--------.                   .--)                   
                         |                   |         user-land    
   - - - - - - - - - - syscall - - - - - - - - - - - - - - - - -    
                         |                   |         kernel       
                         X     Off-CPU       |                      
                       block . . . . . interrupt  

这里对函数进行了检测,以便在它们开始“(”和结束“)”时收集时间戳,以便计算函数花费的时间。如果时间戳包括经过时间和 CPU 时间(例如,使用 times(2) 或 getrusage(2)),那么也可以计算出哪些函数在 CPU 上很慢,哪些函数因为在 CPU 外被阻塞而很慢. 与采样不同,这些时间戳可以具有非常高的分辨率(纳秒)。

虽然这可行,但缺点是您要么跟踪所有应用程序功能,这可能会对性能产生重大影响(并影响您尝试测量的性能),要么您选择可能阻塞的功能,并希望您没有错过任何一个。

3. 非 CPU 跟踪

我将在这里对此进行总结,然后在接下来的部分中对其进行更详细的解释。


    Off-CPU Tracing -------------------------------------------->
                         |                   |                   
                         B                   B                   
                         A                   A                   
    A(---------.                                .----------)        
               |                                |                   
               B(--------.                   .--)                   
                         |                   |         user-land    
   - - - - - - - - - - syscall - - - - - - - - - - - - - - - - -    
                         |                   |         kernel       
                         X     Off-CPU       |                      
                       block . . . . . interrupt    

使用这种方法,只跟踪将线程从 CPU 切换的内核函数,以及时间戳和用户级堆栈跟踪。这专注于非 CPU 事件,无需跟踪所有应用程序功能,也无需知道应用程序是什么。这种方法适用于任何阻塞事件,适用于任何应用程序:MySQL、Apache、Java 等。

非 CPU 跟踪捕获任何 应用程序的所有 等待事件。

在本页后面,我将跟踪内核非 CPU 事件并包括一些应用程序级别的工具来过滤掉异步等待时间(例如,等待工作的线程)。与应用程序级别的检测不同,我不需要寻找所有可能阻塞 CPU 的地方;我只需要确定应用程序在时间敏感的代码路径中(例如,在 MySQL 查询期间),以便延迟与工作负载同步。

Off-CPU 跟踪是我一直用于 Off-CPU 分析的主要方法。但也有抽样。

4. 非 CPU 采样

    Off-CPU Sampling ------------------------------------------->
                          |  |  |  |  |  |  |                       
                          O  O  O  O  O  O  O                       
    A(---------.                                .----------)        
               |                                |                   
               B(--------.                   .--)                   
                         |                   |         user-land    
   - - - - - - - - - - syscall - - - - - - - - - - - - - - - - -    
                         |                   |         kernel       
                         X     Off-CPU       |                      
                       block . . . . . interrupt  

这种方法使用定时采样从不在 CPU 上运行的线程捕获阻塞的堆栈跟踪。它也可以通过 wall-time profiler 来完成:它始终对所有线程进行采样,无论它们是在 CPU 上还是在 CPU 外。然后可以过滤壁时间配置文件输出以仅查找非 CPU 堆栈。

系统分析器很少使用 CPU 外采样。采样通常作为每个 CPU 的定时器中断来实现,然后检查当前正在运行的被中断的进程:生成一个 CPU 配置文件。非 CPU 采样器必须以不同的方式工作:或者在每个应用程序线程中设置计时器以唤醒它们并捕获堆栈,或者让内核每隔一段时间遍历所有线程并捕获它们的堆栈。

高架

警告:使用非 CPU 跟踪时,请注意调度程序事件可能非常频繁——在极端情况下,每秒数百万个事件——尽管跟踪程序可能只会为每个事件增加少量开销,因为开销的事件率可以加起来并变得重要。非 CPU 采样也存在开销问题,因为系统可能有数以万计的线程必须不断地进行采样,开销比仅通过 CPU 计数的 CPU 采样高出几个数量级。

要使用非 CPU 分析,您需要注意每一步的开销。将每个事件转储到用户空间进行后处理的跟踪器很容易变得令人望而却步,每分钟创建 GB 的跟踪数据。该数据必须写入文件系统和存储设备并进行后处理,这会消耗更多的 CPU。这就是为什么可以进行内核摘要的跟踪器(如 Linux eBPF)对于减少开销和使 CPU 外分析变得实用如此重要。还要注意反馈循环:跟踪器跟踪由它们自己引起的事件。

如果我对新的调度程序跟踪器完全一无所知,我将从仅跟踪十分之一秒(0.1 秒)开始,然后从那里逐步提高,同时密切测量对系统 CPU 利用率的影响,应用程序请求率和应用程序延迟。我还将考虑上下文切换的速率(例如,通过 vmstat 中的“cs”列测量),并在具有较高速率的服务器上更加小心。

为了让您了解开销,我测试了一个运行 Linux 4.15 的 8 CPU 系统,MySQL 负载很重,导致每秒 102k 上下文切换。服务器故意以 CPU 饱和(0% 空闲)运行,因此任何跟踪器开销都会导致应用程序性能明显下降。然后,我将通过调度程序跟踪的 CPU 外分析与 Linux perf 和 eBPF 进行了比较,它们展示了不同的方法:用于事件转储的 perf 和用于内核内汇总的 eBPF:

  • 使用 perf 跟踪每个调度程序事件导致跟踪时吞吐量下降 9%,在 perf.data 捕获文件刷新到磁盘时偶尔下降 12%。该文件在 10 秒的跟踪中最终达到 224 MB。然后通过运行 perf 脚本对文件进行后处理以进行符号转换,这在 35 秒内导致性能下降 13%(损失 1 个 CPU)。您可以通过 10 秒的性能跟踪成本 45 秒的 9-13% 开销来总结这一点。
  • 使用 eBPF 计算内核上下文中的堆栈数反而导致 10 秒跟踪期间吞吐量下降 6%,从初始化 eBPF 时的 1 秒下降 13% 开始,然后是 6 秒的后处理(符号解析已经汇总的堆栈)成本下降了 13%。因此,10 秒的跟踪在 17 秒内花费了 6-13% 的开销。好多了。

当跟踪持续时间增加时会发生什么?对于 eBPF,它只捕获和转换独特的堆栈,不会随着跟踪持续时间线性扩展。我通过将跟踪时间从 10 秒增加到 60 秒来测试这一点,这只将 eBPF 后处理时间从 6 秒增加到 7 秒。perf 同样将其后处理时间从 35 秒增加到 212 秒,因为它需要处理 6 倍的数据量。为了完全理解这一点,值得注意的是,后期处理是一种用户级别的活动,可以通过调整来减少对生产工作负载的干扰,例如通过使用不同的调度程序优先级。想象一下,将这个活动的 CPU 限制在 10%(一个 CPU):性能损失可能可以忽略不计,然后 eBPF 后处理阶段可能需要 70 秒——还不错。但是 perf 脚本时间可能需要 2120 秒(35 分钟),这会使调查停滞。perf 的开销不仅仅是 CPU,它也是磁盘 I/O。

这个 MySQL 示例与生产工作负载相比如何?它每秒进行 102k 上下文切换,这是相对较高的:我目前看到的许多生产系统都在 20-50k/s 范围内。这表明这里描述的开销比我在那些生产系统上看到的高出大约 2 倍。但是,MySQL 的堆栈深度比较轻,通常只有 20-40 帧,而生产应用程序可以超过 100 帧。这也很重要,并且可能意味着我的 MySQL 堆栈遍历开销可能只是我在生产中看到的一半。所以这可能会平衡我的生产系统。

Linux:性能、eBPF

非 CPU 分析是一种通用方法,适用于任何操作系统。我将演示如何在 Linux 上使用非 CPU 跟踪,然后在后面的部分中总结其他操作系统。

Linux 上有许多跟踪器可用于 CPU 外分析。我将在这里使用eBPF,因为它可以轻松地对堆栈跟踪和时间进行内核摘要。eBPF 是 Linux 内核的一部分,我将通过bcc前端工具使用它。这些至少需要 Linux 4.8 来支持堆栈跟踪。

你可能想知道我是如何在 eBPF 之前进行 CPU 外分析的。许多不同的方法,包括针对每种阻塞类型的完全不同的方法:存储 I/O 的存储跟踪、调度程序延迟的内核统计信息等等。之前为了实际进行非 CPU 分析,我使用了 SystemTap 和perf事件日志记录——尽管它有更高的开销(我在perf_events Off-CPU Time Flame Graph中写过它)。有一次,我编写了一个名为proc-profiler.pl的简单的实时内核堆栈分析器,它为给定的 PID 对 /proc/PID/stack 进行采样。它工作得很好。我也不是第一个破解这种壁挂时间分析器的人,请参阅poormansprofiler和Tanel Poder 的快速’ n’dirty故障排除。

非 CPU 时间

这是线程在 CPU 外等待(阻塞时间)而不是在 CPU 上运行的时间。它可以作为持续时间的总数来衡量(已经由 /proc 统计信息提供),或者针对每个阻塞事件进行衡量(通常需要跟踪器)。

首先,我将展示您可能已经熟悉的工具的总非 CPU 时间。time(1) 命令。例如,定时 tar(1):


$ time tar cf archive.tar linux-4.15-rc2

real	0m50.798s
user	0m1.048s
sys	0m11.627s

tar 运行大约需要一分钟,但 time 命令显示它只花费了 1.0 秒的用户模式 ​​CPU 时间和 11.6 秒的内核模式 CPU 时间,而总运行时间为 50.8 秒。我们错过了 38.2 秒!那是 tar 命令在 CPU 之外被阻止的时间,毫无疑问,将存储 I/O 作为其归档生成的一部分。

要更详细地检查非 CPU 时间,可以使用内核调度程序函数的动态跟踪或使用 sched 跟踪点的静态跟踪。bcc/eBPF 项目包括由 Sasha Goldshtein 开发的 cpudist,它有一个 -O 模式来测量非 CPU 时间。这需要 Linux 4.4 或更高版本。测量 tar 的非 CPU 时间:

# /usr/share/bcc/tools/cpudist -O -p `pgrep -nx tar`
Tracing off-CPU time... Hit Ctrl-C to end.
^C
     usecs               : count     distribution
         0 -> 1          : 3        |                                        |
         2 -> 3          : 50       |                                        |
         4 -> 7          : 289      |                                        |
         8 -> 15         : 342      |                                        |
        16 -> 31         : 517      |                                        |
        32 -> 63         : 5862     |***                                     |
        64 -> 127        : 30135    |****************                        |
       128 -> 255        : 71618    |****************************************|
       256 -> 511        : 37862    |*********************                   |
       512 -> 1023       : 2351     |*                                       |
      1024 -> 2047       : 167      |                                        |
      2048 -> 4095       : 134      |                                        |
      4096 -> 8191       : 178      |                                        |
      8192 -> 16383      : 214      |                                        |
     16384 -> 32767      : 33       |                                        |
     32768 -> 65535      : 8        |                                        |
     65536 -> 131071     : 9        |                                        |

这表明大多数阻塞事件在 64 到 511 微秒之间,这与闪存存储 I/O 延迟(这是基于闪存的系统)一致。在跟踪时,最慢的阻塞事件达到了 65 到 131 毫秒的范围(此直方图中的最后一个桶)。

这个非 CPU 时间包括什么?从线程阻塞到再次开始运行的所有内容,包括调度程序延迟。

在撰写本文时,cpudist 使用 kprobes(内核动态跟踪)来检测 finish_task_switch() 内核函数。(出于 API 稳定性的原因,它应该使用 sched 跟踪点,但第一次尝试没有成功,现在已恢复。)

finish_task_switch() 的原型是:

static struct rq *finish_task_switch(struct task_struct *prev)

为了让您了解此工具的工作原理:在下一个运行线程的上下文中调用 finish_task_switch() 函数。eBPF 程序可以使用 kprobes 检测此函数和参数,获取当前 PID(通过 bpf_get_current_pid_tgid()),并获取高分辨率时间戳(bpf_ktime_get_ns())。这是上述摘要所需的所有信息,它使用 eBPF 映射在内核上下文中有效地存储直方图桶。这是cpudist的完整来源。

eBPF 并不是 Linux 上唯一用于测量非 CPU 时间的工具。perf工具在其perf sched timehist输出中提供了一个“等待时间”列,该列不包括调度程序时间,因为它分别显示在相邻列中。该输出显示每个调度程序事件的等待时间,并且比 eBPF 直方图摘要要花费更多的开销来衡量。

将 CPU 外时间测量为直方图有点有用,但不是很多。我们真正想知道的是上下文——为什么 线程会阻塞和脱离 CPU。这是off-CPU分析的重点。

CPU 外分析

非 CPU 分析是一种分析非 CPU 时间以及堆栈跟踪以确定线程阻塞原因的方法。由于这个原理,off-CPU 跟踪分析技术可以很容易地实现:

脱离 CPU 时应用程序堆栈跟踪不会更改。

这意味着我们只需要在非 CPU 周期的开始或结束时测量一次堆栈跟踪。结束通常更容易,因为无论如何您都在记录时间间隔。这是用于使用堆栈跟踪测量非 CPU 时间的跟踪伪代码:


on context switch finish:
	sleeptime[prev_thread_id] = timestamp
	if !sleeptime[thread_id]
		return
	delta = timestamp - sleeptime[thread_id]
	totaltime[pid, execname, user stack, kernel stack] += delta
	sleeptime[thread_id] = 0

on tracer exit:
	for each key in totaltime:
		print key
		print totaltime[key]

关于这一点的一些注意事项:所有测量都发生在一个检测点,即上下文切换例程的结尾,它位于下一个线程的上下文中(例如,Linux finish_task_switch() 函数)。这样,我们可以通过简单地获取当前上下文(pid、execname、用户堆栈、内核堆栈)来在检索该持续时间的上下文的同时计算非 CPU 持续时间,这使得跟踪器变得容易。

这就是我的 offcputime bcc/eBPF 程序所做的,它至少需要 Linux 4.8 才能工作。我将演示使用 bcc/eBPF offcputime 来测量 tar 程序的阻塞堆栈。我将其限制为仅以 (-K) 开头的内核堆栈:


# /usr/share/bcc/tools/offcputime -K -p `pgrep -nx tar`
Tracing off-CPU time (us) of PID 15342 by kernel stack... Hit Ctrl-C to end.
^C
[...]

    finish_task_switch
    __schedule
    schedule
    schedule_timeout
    __down
    down
    xfs_buf_lock
    _xfs_buf_find
    xfs_buf_get_map
    xfs_buf_read_map
    xfs_trans_read_buf_map
    xfs_da_read_buf
    xfs_dir3_block_read
    xfs_dir2_block_getdents
    xfs_readdir
    iterate_dir
    SyS_getdents
    entry_SYSCALL_64_fastpath
    -                tar (18235)
        203075

    finish_task_switch
    __schedule
    schedule
    schedule_timeout
    wait_for_completion
    xfs_buf_submit_wait
    xfs_buf_read_map
    xfs_trans_read_buf_map
    xfs_imap_to_bp
    xfs_iread
    xfs_iget
    xfs_lookup
    xfs_vn_lookup
    lookup_slow
    walk_component
    path_lookupat
    filename_lookup
    vfs_statx
    SYSC_newfstatat
    entry_SYSCALL_64_fastpath
    -                tar (18235)
        661626

    finish_task_switch
    __schedule
    schedule
    io_schedule
    generic_file_read_iter
    xfs_file_buffered_aio_read
    xfs_file_read_iter
    __vfs_read
    vfs_read
    SyS_read
    entry_SYSCALL_64_fastpath
    -                tar (18235)
        18413238

我已将输出截断为最后三个堆栈。最后一个显示总共 18.4 秒的非 CPU 时间,位于以 io_schedule() 结尾的读取系统调用路径中——这是 tar 读取文件内容,并阻塞磁盘 I/O。它上面的堆栈在 stat 系统调用中显示了 662 毫秒,它也最终通过 xfs_buf_submit_wait() 等待存储 I/O。顶部堆栈,总共 203 毫秒,似乎在执行 getdents 系统调用(目录列表)时显示锁上的 tar 阻塞。

解释这些堆栈跟踪需要对源代码有一点了解,这取决于应用程序的复杂程度及其语言。你做的越多,你就会变得越快,因为你会识别相同的函数和堆栈。

我现在将包括用户级堆栈:


# /usr/share/bcc/tools/offcputime -p `pgrep -nx tar`
Tracing off-CPU time (us) of PID 18311 by user + kernel stack... Hit Ctrl-C to end.
[...]

    finish_task_switch
    __schedule
    schedule
    io_schedule
    generic_file_read_iter
    xfs_file_buffered_aio_read
    xfs_file_read_iter
    __vfs_read
    vfs_read
    SyS_read
    entry_SYSCALL_64_fastpath
    [unknown]
    -                tar.orig (30899)
        9125783

这不起作用:用户级堆栈只是“[未知]”。原因是 tar 的默认版本是在没有帧指针的情况下编译的,而这个版本的 bcc/eBPF 需要它们来遍历堆栈跟踪。我想展示这个陷阱的样子,以防你也碰到它。

我确实修复了 tar 的堆栈(参见前面的先决条件)以查看它们的样子:

# /usr/share/bcc/tools/offcputime -p `pgrep -nx tar`
Tracing off-CPU time (us) of PID 18375 by user + kernel stack... Hit Ctrl-C to end.
[...]

    finish_task_switch
    __schedule
    schedule
    io_schedule
    generic_file_read_iter
    xfs_file_buffered_aio_read
    xfs_file_read_iter
    __vfs_read
    vfs_read
    SyS_read
    entry_SYSCALL_64_fastpath
    __read_nocancel
    dump_file0
    dump_file
    dump_dir0
    dump_dir
    dump_file0
    dump_file
    dump_dir0
    dump_dir
    dump_file0
    dump_file
    dump_dir0
    dump_dir
    dump_file0
    dump_file
    create_archive
    main
    __libc_start_main
    [unknown]
    -                tar (15113)
        426525
[...]

好的,看起来 tar 对文件系统树有一个递归遍历算法。

这些堆栈跟踪很棒——它显示了为什么应用程序阻塞和等待 CPU 外,以及等待了多长时间。这正是我通常要寻找的信息。但是,阻塞堆栈跟踪并不总是那么有趣,因为有时您需要查找请求同步上下文。

请求同步上下文

等待工作的应用程序,如在套接字上等待线程池的 Web 服务器,对 CPU 外分析提出了挑战:通常大部分阻塞时间将在堆栈中等待工作,而不是在做工作。这会使输出充满不那么有趣的堆栈。

作为这种现象的一个例子,这里是一个什么都不做的 MySQL 服务器进程的 CPU 外堆栈。每秒零请求:

# /usr/share/bcc/tools/offcputime -p `pgrep -nx mysqld`
Tracing off-CPU time (us) of PID 29887 by user + kernel stack... Hit Ctrl-C to end.
^C
[...]

  finish_task_switch
    __schedule
    schedule
    do_nanosleep
    hrtimer_nanosleep
    sys_nanosleep
    entry_SYSCALL_64_fastpath
    __GI___nanosleep
    srv_master_thread
    start_thread
    -                mysqld (29908)
        3000333

    finish_task_switch
    __schedule
    schedule
    futex_wait_queue_me
    futex_wait
    do_futex
    sys_futex
    entry_SYSCALL_64_fastpath
    pthread_cond_timedwait@@GLIBC_2.3.2
    os_event::wait_time_low(unsigned long, long)
    srv_error_monitor_thread
    start_thread
    -                mysqld (29906)
        3000342

    finish_task_switch
    __schedule
    schedule
    read_events
    do_io_getevents
    SyS_io_getevents
    entry_SYSCALL_64_fastpath
    [unknown]
    LinuxAIOHandler::poll(fil_node_t**, void**, IORequest*)
    os_aio_handler(unsigned long, fil_node_t**, void**, IORequest*)
    fil_aio_wait(unsigned long)
    io_handler_thread
    start_thread
    -                mysqld (29896)
        3500863
[...]

各种线程正在轮询工作和其他后台任务。这些后台堆栈可以控制输出,即使对于繁忙的 MySQL 服务器也是如此。我通常寻找的是数据库查询或命令期间的非 CPU 时间。这才是最重要的时间——伤害最终客户的时间。为了在输出中找到那些,我需要在查询上下文中寻找堆栈。

例如,现在来自繁忙的 MySQL 服务器:

# /usr/share/bcc/tools/offcputime -p `pgrep -nx mysqld`
Tracing off-CPU time (us) of PID 29887 by user + kernel stack... Hit Ctrl-C to end.
^C
[...]

   finish_task_switch
    __schedule
    schedule
    io_schedule
    wait_on_page_bit_common
    __filemap_fdatawait_range
    file_write_and_wait_range
    ext4_sync_file
    do_fsync
    SyS_fsync
    entry_SYSCALL_64_fastpath
    fsync
    log_write_up_to(unsigned long, bool)
    trx_commit_complete_for_mysql(trx_t*)
    [unknown]
    ha_commit_low(THD*, bool, bool)
    TC_LOG_DUMMY::commit(THD*, bool)
    ha_commit_trans(THD*, bool, bool)
    trans_commit_stmt(THD*)
    mysql_execute_command(THD*, bool)
    mysql_parse(THD*, Parser_state*)
    dispatch_command(THD*, COM_DATA const*, enum_server_command)
    do_command(THD*)
    handle_connection
    pfs_spawn_thread
    start_thread
    -                mysqld (13735)
        1086119

[...]

此堆栈标识查询期间的一些时间(延迟)。do_command() → mysql_execute_command() 代码路径是免费的。我知道这一点是因为我熟悉这个堆栈所有部分的代码:MySQL 和内核内部。

您可以想象编写一个简单的文本后处理器,它根据某些特定于应用程序的模式匹配提取出感兴趣的堆栈。这可能会很好。还有另一种更有效的方法,虽然也需要应用程序细节:扩展跟踪程序​​以检测应用程序请求(在此 MySQL 服务器示例中为 do_command() 函数),然后仅记录非 CPU 时间,如果它发生在应用程序请求期间。我以前做过,它可以帮助。

注意事项

最大的警告是非 CPU 分析的开销,如前面开销部分所述,其次是让堆栈跟踪工作,我在前面的先决条件部分中对此进行了总结。还有调度程序延迟和非自愿上下文切换需要注意,我将在这里总结,以及唤醒堆栈,我将在后面的部分讨论。

调度程序延迟

这些堆栈中缺少的东西是,如果非 CPU 时间包括等待 CPU 运行队列所花费的时间。该时间称为调度程序延迟、运行队列延迟或调度程序队列延迟。如果 CPU 以饱和状态运行,那么任何时候线程阻塞,它都可能在被唤醒后等待额外的时间等待 CPU 启动。该时间将包含在非 CPU 时间中。

您可以使用额外的跟踪事件将非 CPU 时间划分为阻塞时间与调度程序延迟,但实际上,CPU 饱和很容易发现,因此当您有已知的 CPU 饱和问题要处理。

非自愿上下文切换

如果您看到没有意义的用户级堆栈跟踪——没有理由阻塞和脱离 CPU——这可能是由于非自愿的上下文切换。这通常发生在 CPU 饱和时,内核 CPU 调度程序让线程打开 CPU,然后在它们到达时间片时将它们踢掉。线程可以随时启动,例如在 CPU 繁重的代码路径中间,由此产生的 CPU 外堆栈跟踪毫无意义。

这是来自 offcputime 的示例堆栈,可能是非自愿的上下文切换:

# /usr/share/bcc/tools/offcputime -p `pgrep -nx mysqld`
Tracing off-CPU time (us) of PID 29887 by user + kernel stack... Hit Ctrl-C to end.
[...]

    finish_task_switch
    __schedule
    schedule
    exit_to_usermode_loop
    prepare_exit_to_usermode
    swapgs_restore_regs_and_return_to_usermode
    Item_func::type() const
    JOIN::make_join_plan()
    JOIN::optimize()
    st_select_lex::optimize(THD*)
    handle_query(THD*, LEX*, Query_result*, unsigned long long, unsigned long long)
    [unknown]
    mysql_execute_command(THD*, bool)
    Prepared_statement::execute(String*, bool)
    Prepared_statement::execute_loop(String*, bool, unsigned char*, unsigned char*)
    mysqld_stmt_execute(THD*, unsigned long, unsigned long, unsigned char*, unsigned long)
    dispatch_command(THD*, COM_DATA const*, enum_server_command)
    do_command(THD*)
    handle_connection
    pfs_spawn_thread
    start_thread
    -                mysqld (30022)
        13

[...]

目前尚不清楚(基于函数名称)为什么该线程在 Item_func::type() 中阻塞。我怀疑这是一个非自愿的上下文切换,因为服务器 CPU 已饱和。

使用 offcputime 的一种解决方法是过滤 TASK_UNINTERRUPTIBLE 状态 (2):

# /usr/share/bcc/tools/offcputime -p `pgrep -nx mysqld` --state 2

在 Linux 上,状态 TASK_RUNNING (0) 会发生非自愿的上下文切换,而我们通常感兴趣的阻塞事件是 TASK_INTERRUPTIBLE (1) 或 TASK_UNINTERRUPTIBLE (2),offcputime 可以使用 --state 进行匹配。我在我的Linux 平均负载:解决谜题中使用了这个特性。

# /usr/share/bcc/tools/offcputime -df -p `pgrep -nx mysqld` 30 > out.stacks
[...copy out.stacks to your local system if desired...]
# git clone https://github.com/brendangregg/FlameGraph
# cd FlameGraph
# ./flamegraph.pl --color=io --title="Off-CPU Time Flame Graph" --countname=us < out.stacks > out.svg

Then open out.svg in a web browser. It looks like this (SVG, PNG):

更好:这显示了所有 CPU 外的堆栈跟踪,堆栈深度位于 y 轴,宽度对应于每个堆栈的总时间。从左到右的顺序没有意义。内核和用户堆栈之间有分隔符“-”,它们是由 offcputime 的 -d 选项插入的。

您可以点击放大。例如,单击右下角的“do_command(THD*)”框,可以放大查询期间发生的阻塞路径。您可能想要生成只显示这些路径的火焰图,这可以像 grep 一样简单,因为折叠格式是每个堆栈一行:

# grep do_command < out.stacks | ./flamegraph.pl --color=io --title="Off-CPU Time Flame Graph" --countname=us > out.svg

The resulting flame graph (SVG, PNG):

看起来很棒。

有关非 CPU 火焰图的更多信息,请参阅我的Off-CPU 火焰图页面。

唤醒

既然您知道如何进行 CPU 外跟踪并生成火焰图,那么您将开始真正查看这些火焰图并对其进行解释。您可能会发现许多非 CPU 堆栈显示阻塞路径,但不是阻塞的全部原因。该原因和代码路径与另一个线程有关,该线程在阻塞线程上调用唤醒。这事儿常常发生。

我在我的Off-CPU Flame Graphs页面中介绍了这个主题,以及两个工具:wakeuptime 和 offwaketime,用于测量唤醒堆栈并将它们与非 CPU 堆栈相关联。

其他操作系统

  • Solaris :DTrace 可用于 CPU 外跟踪。这是我的原始页面:Solaris Off-CPU Analysis
  • FreeBSD :可以使用 procstat -ka 进行内核堆栈采样,使用 DTrace 进行用户和内核堆栈跟踪,可以执行非 CPU 分析。我为此创建了一个单独的页面:FreeBSD Off-CPU Analysis

起源

在探索了 DTrace sched 提供程序及其 sched:::off-cpu 探测器的使用之后,我在 2005 年左右开始使用这种方法。在 DTrace 探测器名称之后(不是一个完美的名称:2005 年在阿德莱德教授 DTrace 课程时,一位 Sun 工程师说我不应该将其称为 CPU 外时间) CPU 没有“关闭”)。Solaris 动态跟踪指南有一些示例,可以针对某些特定情况和进程状态测量从 sched:::off-cpu 到 sched:::on-cpu 的时间。我没有过滤进程状态,而是捕获了所有非 CPU 事件,并包含堆栈跟踪来解释原因。我认为这种方法很明显,所以我怀疑我是第一个这样做的人,但我似乎是一段时间以来唯一真正推广这种方法的人。我在 2007 年在DTracing Off-CPU Time,以及以后的帖子和讲座。

概括

非 CPU 分析可以是一种有效的方法来定位线程阻塞和等待其他事件的延迟类型。通过从上下文切换线程的内核调度程序函数中跟踪这一点,可以以相同的方式分析所有非 CPU 延迟类型,而无需跟踪多个源。要查看 off-CPU 事件的上下文以了解它发生的原因,可以检查用户和内核堆栈回溯跟踪。

通过 CPU 分析和非 CPU 分析,您可以全面了解线程将时间花在哪里。这些是互补的技术。

有关 CPU 外分析的更多信息,请参阅Off-CPU Flame GraphsHot/Cold Flame Graphs中的可视化。