如果你发现某个程序明显受限于CPU资源(CPU-Bound)， 那么你就可以用到本章提到的CPU工具来进一步定位并分析问题。市面上有各种各样的采样式性能剖析:器(SamplingProfiler)以及各种各样的性能指标来帮助你理解程序的CPU用量。
不过，(这可能会出乎你的意料)，BPF跟踪系统仍然可以在很多地方帮助你进行深度分析。
学习目标
■理解CPU的运行模式、CPU调度器的行为及CPU缓存。
■理解如何使用BPF来分析CPU调度器、CPU用量及硬件性能。
■学习一个行之有效的CPU性能分析策略。
■分析和解决大量短期程序占用CPU资源的问题。
■展示以及量化运行队列( run queue) 中的延迟。
■通过跟踪系统调用(syscall) 来理解系统CPU使用时间。
■调查软中断(soft interrupt) 和硬中断( hard interrupt) 占用的CPU资源。
■使用各种bpfrace单行程序来定制分析CPU用量。
本章一开始，将先简要介绍CPU调度器和CPU缓存的行为，这些背景知识可以帮助你理解CPU用量分析的过程。接下来，会解释在CPU用量分析中BPF能够起作用的地方，并且提供一个整体的性能分析策略。为了避免重新发明轮子和帮助你进行深入分析，这里笔者会先简要介绍传统的CPU分析工具，然后关注BPF相关工具，以及一系列BPF小程序。本章最后还提供了一些可选习。
6.1 背景知识
6.1.1 CPU 基础知识
CPU的运行模式
略
CPU调度器
本书用以下几个术语来指代线程的几种状态：
on-CPU：指代ON-PROC，指正在CPU上运行的线程
off-CPU：指代其他所有的状态，包括所有不在CPU.上运行的状态。
CPU缓存
CPU中一般包含多个层次的缓存，不同型号的CPU中的缓存大小和延迟各不相同。
| 层次 | 描述 |
|---|---|
| L1缓存(level .n层次，水平) | L1 分为指令缓存( I$ ) 和数据缓存( D$ )两部分，大小在千字节(KB) 级别，访问速度为纳秒级别。通常是每个CPU核独占 |
| L2缓存(level .n层次，水平) | 大小在千字节(MB) 级别，访问速度为纳秒级别。 通常是每个CPU核独占 |
| L3缓存(level .n层次，水平) | LLC也被称为L3缓存 ，大小在兆字节(MB)级别,速度相对较慢。通常是在CPU槽内所有核共享的。 |
内存管理单元MMU负责将虚拟内存地址转换为物理内存地址，它也有专用的缓存，称为地址转换缓存(TLB)。
在过去的几十年中，CPU的时钟速度不断提高，核心数量不断增加，硬件线程也在不断增加。
通过增加CPU缓存的大小，内存带宽有所提高，且内存访问延迟在不断降低。
然而，内存性能提高的水平并没有和CPU保持同步。现在越来越多的程序的性能都受限于内存性能，而非CPU性能。
扩展阅读
以上是在使用工具中不可缺少的–些基础知识，与CPU相关的软件和硬件知识在Systems Performancelre 一书的第6章中有更深入的讨论。
6.1.2 BPF 的分析能力
传统性能分析工具中提供了对CPU各种用量的测量。例如，可以展示每个进程的CPU使用率、上下文切换的速度、运行队列的长度等。接下来我们会简要介绍这些传统工具。
BPF跟踪工具可以提供更多细节信息，可回答以下这些问题:
创建了哪些新进程?运行时长是多长?
- 为什么CPU系统时间很高?是由于系统调用导致的吗?具体是哪些系统调用?
- 线程每次唤醒时在CPU上花费多长时间?
- 线程在运行队列中等待的时间有多长?
- 运行队列最长的时候有多少线程在等待执行?
- 不同CPU之间的运行队列是否均衡?
- 为什么某个线程会主动脱离CPU ?脱离时间有多长?
- 哪些软中断和硬中断占用了CPU时间?
- 当其他运行队列中有需要运行的程序时，哪些CPU仍然处于空闲状态?
- 应用程序处理每个请求时的LLC的命中率是多少?
这些问题都可以由BPF程序来回答，具体包括使用在CPU调度器和系统调用事件中埋入的跟踪点，
- 用kprobes(内核动态插桩)来跟踪调度器内部函数，
- 用uprobes(用户动态插桩)来跟踪应用程序内部函数，
- 以及利用PMC(性能监控计数器)来获取定时采样CPU数据和CPU内部数据等。
这些数据源也可以混合使用：一个BPF程序可以用uprobes(用户动态插桩)来获取应用程序执行上下文信息，同时将其与PMC(性能监控计数器)数据对应起来展示。这样的程序就可以展示应用程序在处理请求时的LLC(最后一层缓存)命中率
BPF程序收集的信息可以按每个事件来展示，也可按统计分布情况展示。通过获取程序调用栈信息，可以展示每个事件的触发原因。使用系统内核中的BPF映射表和输出缓冲器，这类操作都是十分高效的。
事件源
表6-1列出了测量CPU用量的各种事件源。
额外消耗
跟踪CPU调度器事件时，效率尤其重要，因为上下文切换这样的调度器事件每秒可能触发几百万次。虽然BPF程序通常很短，执行效率很高(运行时长在微秒级)，但是如果每次上下文切换时都执行该程序，累积起来的性能消耗也是很可观的，甚至大到影响系统的行为。在最糟糕的情况下，针对调度器的跟踪可能会消耗10%的系统性能。如果BPF程序缺乏优化，那么这种额外消耗可能会过高，甚至导致系统无法使用。
在考虑到额外消耗之后，使用BPF进行调度器跟踪比较适合短期的、临时的性能分析。通过一些小测试可以量化额外消耗的大小:如果CPU每秒的利用率是恒定的，那么当BPF工具运行和不运行时的区别是多少?
避免CPU工具产生过多额外消耗的方式，一般是避免跟踪调度器中的高频事件，而改为测量额外消耗很低的低频事件——例如进程创建事件、线程迁移事件等(每秒最多几千次)。定时采样这类分析的额外消耗则受限于固定的频率,所以几乎可以忽略不计。
6.1.3分析策略
如果你对CPU性能分析不熟悉的话，可能会觉得无从下手——不知道用哪个工具针对哪个目标进行分析。笔者建议你采用以下分析策略来逐步进行:
-
1.在花时间使用分析工具之前，先保证待分析的对象处于CPU运行状态。检查系统中的整体CPU利用率(例如，用mpstat(1),并且保证每个CPU都处于在线状态(检查是否有些CPU由于某些原因处于下线状态)。
-
2.确认系统负载确实受限于CPU.
a. 系统中所有CPU的使用率是否都很高，还是仅某个CPU使用率高(例如，用mpstat())。
b.检查系统中运行队列的延迟(例如，使用BCC runqlat(1)。 系统中的一些软件限制——例如容器的设置——可以限制进程所能使用的CPU资源，进而导致某些程序在空闲系统上仍然受限于CPU。通过分析运行队列延迟，可以识别这种类型的反常规情景。 -
3.先量化整个系统中的CPU使用量的百分比，然后再按进程、CPU模式、CPUID来分解。这可以用传统工具来进行(如mpstat(1). top(1) 等)。可以通过某种模式或者某个CPU的高使用率情况寻找某个进程。
a.如果系统时间占比高，那么可按照进程和系统调用类型来统计系统调用的频率和数量，同时检查系统调用的参数来识别值得优化的地方(例如，使用perf(1)、bpftrace 单行程序，以及BCC sysstat(8)。 -
4.用性能剖析器(Profiler)来采样应用程序的调用栈信息，再用CPU火焰图来展示。很多CPU问题都可以通过检查火焰图来分析。
-
5.针对某个CPU使用率高的任务，可考虑开发一些定制工具来获取更多的上下文信息。性能剖析器通常可以展示哪些函数正在运行，但是不能展示调用参数和函数内部的信息，理解CPU用量时可能需要这些信息。例如，
a.内核模式:如果某个文件系统针对文件进行stat()消耗了很多CPU资源，那么文件名是什么? (这 可以用BCC statsnoop(8)来获取，也可以通过BPF工具的内核跟踪点和kprobes来获取。)
b.用户模式:如果某个应用程序忙于处理请求，那么这些请求到底是什么? (如果没有针对这个程序的特定工具，可以考虑用USDT或uprobes来开发这种工具。) -
6.测量硬中断的资源消耗，这些信息可能对基于定时器的分析器不可见(例如BCC hardirqs(1))。
-
7.从本章中提到的BPF工具中选择一个执行。
-
8.利用PMC来测量每时钟周期内的CPU指令执行量(IPC)，以理解宏观层面CPU的阻塞情况。还有其他的PMC可以进一步帮助分析低缓存命中率(如BCC estat)、温控导致的阻塞等问题。
接下来的章节会详细解释这个过程中使用的工具。
6.2 传统工具
传统工具
| 工具 | 类型 | 介绍 |
|---|---|---|
| uptime | 内核统计 | 展示系统负载平均值和系统运行时间 |
| top | 内核统计 | 按进程展示CPU使用时间，以及系统层面的CPU模式时间 |
| mpstat | 内核统计 | 按每个CPU展示每种CPU模式的时间 |
| perf | 内核统计、硬件统计、事件跟踪 | (定时采样)调用栈信息、事件统计、PMC(性能监控计数器)跟踪、跟踪点、USDT probes(用户态跟踪点探针) 、kprobes(内核动态插桩) 以及uprobes(用户动态插桩)等 |
| Ftrace | 内核统计、事件跟踪 | 汇报内核函数调用统计，以及kprobes(内核动态插桩)和uprobes(用户动态插桩)事件跟踪 |
除了解决生产问题以外，传统工具同时可以为你深入使用BPF工具提供一些线索。
以下是基于信息源和测量类型的工具分类：内核统计、硬件统计和事件跟踪等。
下面的章节将针对每个工具简要介绍它们的关键功能。
更多的用例和解释请参考帮助文档(man page)，或其他信息，例如Systems Performancelfree这本书。
6.2.1内核统计
内核统计工具利用的是内核通过/proc接口显露的统计数据。这些工具的优势是，这些信息都是在内核中直接实现的，所以使用起来的额外消耗非常小。另外，这些工具经常可以由非root用户使用。
1)负载平均值
uptime(1)是能够打印系统负载平均值的工具之一 :
最后三个数字1.44、0.62、0.23分别是系统负载在1分钟、5分钟和15分钟内的平均值。
通过比较这些数据，可以分析系统负载在过去15分钟内是在上升、下降,还是维持不变。
上面这行输出，是在ubuntu-22.04.1-desktop-amd64上产生的，通过比较1分钟平均负载值1.44和15分钟平均负载值0.23展示了系统负载有轻微的下降。
负载平均值其实并不是简单的数学均值(mean)，而是按指数衰减的累加值，它们的实际含义要比1分钟、5分钟、15 分钟更广。
这条信息实际展示了系统中的负载需求：系统中处于可运行状态的，以及处于不可中断等待状态的任务的数量。
如果假设平均负载值是CPU负载值的话，那么将这个数量简单除以CPU的数量，如果比值超过1.0,那么系统中的CPU资源就处于饱和状态。然而，由于平均负载值通常包含了不可中断任务(处于I/0和锁等待状态)，所以不能简单地将其理解为CPU利用率。
这些值一般只能用来进行负载趋势分析。可以用例如基于BPF的offcputime(8)工具来分析系统负载到底是由CPU资源饱和导的，还是由不可中断状态的等待所导致的。针对offcputime(8)的信息可参见6.3.9节,有关如何测量不可中断的I/O的信息可参见第14章。
top
top(1)工具按表格形式展示了使用CPU的进程的信息，以及系统全局概况:
书作者给的示例——有一个进程正在大量占用CPU
我的示例——没有一个进程正在大量占用CPU
这是本人笔记本上虚拟机的输出，其中没有一个进程正在大量占用CPU：按所有的CPU累计，一个firefox(火狐)进程占用了1.3% 的CPU时间。
如图系统有2个CPU，那么这个输出展示了该firefox(火狐)进程消耗了(1.3÷2)%的全局CPU资源。这同时和系统中平均(1.7+2.4)%的CPU使用率相对应(在表头的概要中展示: 1.7%的user模式和2.4%的systerm模式)。
top(1)对识别某个意外进程占用大量CPU的情况非常有用。常见的一种情况是，某种软件bug导致某个线程进入死循环，通过top(1)工具可以很容易识别出来——CPU 占用率为100%。利用性能剖析器和BPF工具可以进一步确认该进程确实处于死循环中，而不是正在忙着处理请求。
top(1)在默认情况下会自动刷新屏幕，以便将整个屏幕用作一个实时仪表盘使用。但是这也是一个问题:系统中出现的问题，可能在你截屏之前就消失了。很多时候你需要将工具的输出和截屏填入工单系统中来跟踪性能问题。有一些工具，例如，pidstat(1),可以滚动打印某个进程的CPU使用量，这就很合适。同时，如果有监控系统的话，它们可能已经记录了每个进程的CPU用量信息。
top(1)工具有几个变体，例如htop(1),它提供了更多的定制选项。但是，很多top(1)的变体都关注于展示形式上的优化，而不是性能指标方面的进步，这导致它们可能看起来更漂亮，但是其实并不能比原始的top(1) 更有效地展示问题。
有几个特例: tiptop(1)，包含了PMC信息；atop(1),利用进程事件展示短期进程的信息；以及biotop(8)和tcptop(8)工具，利用了BPF技术(是由笔者开发的)。
mpstat
mpstat(1)可以用来检视每个CPU的指标：
上述输出被截断了，因为在这个48个CPU的系统上该工具每秒会输出48行数据：每个CPU一行。
这个输出可以用来识别负载均衡问题一某些CPU使用率高，而其他的CPU使用率低。
CPU负载不平衡可能由一系列原因导致，例如，应用程序配置问题、线程池过小不足以使用所有CPU，也可能是软件将某个进程和容器限制在某几个CPU之上，又或者是软件本身的bug导致的。
CPU时间按各种运行状态被进一步进行了分解，包括硬中断(%irq)、软中断(%soft)等。这些可以进一步用hardirq(8)和softirq(8)等BPF工具来调查。
lj@lj-virtual-machine:~/Desktop$ mpstat -P ALL 1
Command 'mpstat' not found, but can be installed with:
sudo apt install sysstat
lj@lj-virtual-machine:~/Desktop$ sudo apt-get install sysstat
[sudo] password for lj:
Reading package lists... Done
Building dependency tree... Done
....
....
Created symlink /etc/systemd/system/multi-user.target.wants/sysstat.service → /lib/systemd/system/sysstat.service.
Processing triggers for man-db (2.10.2-1) ...
lj@lj-virtual-machine:~/Desktop$ mpstat -P ALL 1
Linux 5.15.0-43-generic (lj-virtual-machine) 2022年10月12日 _x86_64_ (2 CPU)
11时05分09秒 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
11时05分10秒 all 1.01 0.00 0.50 0.00 0.00 0.00 0.00 0.00 0.00 98.49
11时05分10秒 0 1.01 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 98.99
11时05分10秒 1 1.00 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00 98.00
11时05分10秒 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
11时05分11秒 all 0.50 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 99.50
11时05分11秒 0 1.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 99.00
11时05分11秒 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
11时05分11秒 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
11时05分12秒 all 0.00 0.00 0.50 0.00 0.00 0.00 0.00 0.00 0.00 99.50
11时05分12秒 0 0.00 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00 99.00
11时05分12秒 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
11时05分12秒 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
11时05分13秒 all 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
11时05分13秒 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
11时05分13秒 1 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
11时05分13秒 CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
11时05分14秒 all 0.50 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 99.50
11时05分14秒 0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 100.00
11时05分14秒 1 1.01 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 98.99
^C
Average: CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
Average: all 0.40 0.00 0.20 0.00 0.00 0.00 0.00 0.00 0.00 99.40
Average: 0 0.40 0.00 0.20 0.00 0.00 0.00 0.00 0.00 0.00 99.40
Average: 1 0.40 0.00 0.20 0.00 0.00 0.00 0.00 0.00 0.00 99.40
lj@lj-virtual-machine:~/Desktop$
6.2.2硬件统计
硬件也能提供很多有用的统计信息——尤其是CPU提供的性能监控计数器(PMC),PMC在第2章中进行过一些介绍。
perf(1)
Linux中的perf(1)是一个支持从不同来源收集和展示的复合工具。它的第一版是在Linux 2.6.31 中加入的(2009年)， 这个工具是标准的Linux性能剖析器，代码存放在Linux代码树的tools/perf目录中。
笔者之前发布了一个perf的详细使用向导：https://www.brendangregg.com/perf.html。这个工具的多个高级功能之一，就是它可以以计数模式使用PMC :
“gzip file1”的性能计数器统计信息可以执行下图指令打印：
perf stat 命令带有-e参数统计各种事件的信息。如果没有参数，那么就默认统计一系列基本的PMC；如果有-d参数，那么就会加上一些更详细的PMC数据。该工具的输出和使用方式会根据Linux版本的不同而不同，同时还取决于你的CPU所提供的PMC。上面这个例子是基于 Linux 4.15的输出。你可以通过perf list命令获取当前处理器和perf工具支持的PMC列表:
下面的输出展示了你可以传入的-e的参数列表。例如，可以要求跨所有的CPU累计，(使用-a参数，这个参数最近刚刚成为默认开启)，同时每1000毫秒输出一次:
用以下命令进行安装perf：
apt-get install linux-tools-$(uname -r) linux-tools-generic -y
安装完成后，可以使用以下命令验证Perf的安装版本：
perf -v
lj@lj-virtual-machine:/usr/bin$ perf --help
usage(用法): perf [--version] [--help] [OPTIONS(选项)] COMMAND(命令) [ARGS]
The most commonly(通常地) used perf commands(命令) are:
annotate Read perf.data (created by perf record(记录)) and display(显示) annotated(带注释的) code
archive Create archive(文档) with(使用) object(目标) files with(带有.....的特征) build-ids found in(寻找) perf.data file
bench General(普遍的) framework(框架) for benchmark(基准，检测) suites(套)
[......]
list List(列清单) all symbolic(象征的，符号) event types
[......]
record Run a command and record its profile(配置文件) into perf.data
report Read perf.data (created by perf record) and display the profile(配置文件)
sched Tool to trace(追踪)/measure(计量) scheduler properties(性能) (latencies延迟)
script Read perf.data (created by perf record) and display trace output
stat Run a command and gather(收集) performance(表演，性能) counter(计数器) statistics(统计数据)
[......]
See 'perf help COMMAND' for more information on a specific(明确的) command.
lj@lj-virtual-machine:/usr/bin$
lj@lj-virtual-machine:~/Desktop$ perf stat -help
Usage: perf stat [<options>] [<command>]
-a, --all-cpus system-wide(宽的，全范围的) collection(搜集) from all CPUs
-A, --no-aggr disable CPU count aggregation
-B, --big-num print large numbers with thousands' separators
-C, --cpu <cpu> list of cpus to monitor in system-wide
-D, --delay <n> ms to wait before starting measurement after program >
-d, --detailed detailed run - start a lot of events
-e, --event <event> event selector(选择器). use 'perf list' to list(列表) available(可用的) eve>
-G, --cgroup <name> monitor event in cgroup name only
-g, --group put the counters into a counter group
-I, --interval-print <n>
print(打印) counts(计数) at regular(定时) interval(间隔) in ms(毫秒) (overhead(开销) is p>
[......]
lj@lj-virtual-machine:~/Desktop$
lj@lj-virtual-machine:/usr/bin$ sudo perf stat -e mem_load_retired.l3_hit -e mem_load_retired.l3_miss -a -I 1000
[sudo] password for lj:
# time(时间) counts(计数) unit events(单元事件)
1.001332528 0 mem_load_retired.l3_hit
1.001332528 0 mem_load_retired.l3_miss
2.003485100 0 mem_load_retired.l3_hit
2.003485100 0 mem_load_retired.l3_miss
3.005611212 0 mem_load_retired.l3_hit
3.005611212 0 mem_load_retired.l3_miss
4.008213533 0 mem_load_retired.l3_hit
4.008213533 0 mem_load_retired.l3_miss
^C 4.531837357 0 mem_load_retired.l3_hit
4.531837357 0 mem_load_retired.l3_miss
lj@lj-virtual-machine:/usr/bin$ ^C
查看perf list可知：
l1d.replacement [统计L1数据缓存中被替换的缓存行数]
mem_load_retired.l3_hit [内存加载指令完成，有三级缓存命中，作为数据源支持]
mem_load_retired.l3_miss [内存加载指令完成，没有三级缓存命中，作为数据源支持]
mem_load_retired.fb_hit [由于前一次未命中L1，但命中FB（填充缓冲区）的已完成请求加载请求数据缓存已启动要引入L1的行，但数据尚未在L1中就绪]
这个输出显示了系统中这些事件发生的速率(每秒)。
可用的PMC共有几百个，这些信息都被记载在处理器生产商的手册中。你也可以将PMC与模型特定的寄存器(MSR)配合使用来展示CPU内部部件的性能情况、CPU的时钟频率信息、温度信息、电量使用情况、CPU内部总线和内存总线的使用率等。
tlbstat
作为使用PMC的一个例子，笔者开发了tlbstat这个工具，其可用来统计地址转换缓存(TLB)相关的PMC信息。笔者的目标是分析为了绕过Meltdown安全问题对Linux内核内存页表隔离(KPTI) 相关补丁的性能影响：
tlbstat打印以下几个列。
- K_CYCLES:：CPU周期信息(单位为千个)。
- K_INSTR： CPU指令信息(单位为千个)。
- IPC：每周期的指令数量。
- DTLB_WALKS：数据TLB查询(计数)。
- ITLB_WALKS：指令TLB查询(计数)。
- K_DTLBCYC：进行数据TLB查询时，至少有一个缺页中断处理程序(PMH)活跃时的周期数量(单位为千个)。
- K_ITLBCYC：进行指令TLB查询时，至少有一个缺页中断处理程序(PMH)活跃时的周期数量(单位为千个)。
- DTLB%：数据TLB活跃周期与总周期数的比例。
- ITLB%：指令TLB活跃周期与总周期数的比例。
上述输出是在一个压力测试中、KPTI 额外消耗最高的时候产生的: DTLB占用了27%的CPU,ITLB占用了22%的CPU。
这意味着，一半以上的系统CPU都被内存管理单元进行虚拟地址和物理地址转换的过程所占用。如果tbstat在你的生产环境中输出了类似的结果，那么你就应该集中精力优化TLB了。
6.2.3 硬件采样
perf(1)还可以用另外一种方式读取PMC数据。在这种方式下，根据一个给定的数值N，每当PMC数值超过N的倍数时，便产生中断以便让内核抓取事件信息。正如下面这个例子，这条命令指示内核抓取所有CPUL3缓存未命中时的调用栈信息，抓取时长为10秒(这里用sleep 10作为一条无用指令来设置时长):
采样结果可以用perf report 指令来摘要输出，或者使用perf list指令来逐条输出：
6.2.4定时采样
很多性能剖析器都支持基于定时器的采样分析(以固定时间间隔截取指令指针位置或者程序调用栈信息)。这种类型的性能分析粒度比较粗，信息收集成本低，可以很容易看出哪些程序在占用CPU资源。这类性能剖析器有的只能在用户态运行，有的可以在内核态运行。一般来说，内核态的性能剖析器更好，因为它们可以同时截取用户态和内核态的程序调用栈，信息更为完整。
perf
perf(1)是一个运行于内核态的性能剖析器，同时支持基于软件定时器和基于PMC的定时采样:默认采用当前平台上最精确的定时模式。在下面这个例子中，该命令以99Hz (每秒采样99次)的频率在所有的CPU上采样，采样时长30秒:
lj@lj-virtual-machine:~/Desktop$ sudo perf record -F 99 -a -g -- sleep 30
[ perf record: Woken up 5 times to write data ]
[ perf record: Captured and wrote 2.028 MB perf.data (5940 samples) ]
lj@lj-virtual-machine:~/Desktop$
[perf记录：唤醒5次以写入数据]
[perf记录：已捕获并写入2.028 MB perf.data（5940个样本）]
这里选择了99Hz，而不是100Hz，是为了避免和程序内部的其他定时器相冲突，从而避免结果中产生偏差(在第18章中有更多解释)。
之所以选择大概100Hz，而不是10Hz或1000Hz，是基于额外消耗与信息粒度的双重考虑。如果频率设置得太低，那么样本数量不够，不能完全展现执行状态，可能会错过一些短的代码调用栈。如果频率设置得太高，那么高频采样本身的额外消耗会导致性能下降，使结果出现偏差。
当这条perf(1)指令运行时，会将结果写入perf.data文件中：这个过程会使用一个内核中的缓冲区，以便将信息批量写入文件统。输出结果显示，在这条命令执行过程中，只需被唤醒一次来写入数据 。
可以用perfreport命令摘要输出全部结果,或者使用perfscript来逐条输出。例如:
lj@lj-virtual-machine:~/Desktop$ sudo perf record -F 99 -a -g -- sleep 30
[ perf record: Woken up 5 times to write data ]
[ perf record: Captured and wrote 2.028 MB perf.data (5940 samples) ]
lj@lj-virtual-machine:~/Desktop$ perf report -n --stdio
failed to open perf.data: Permission denied
lj@lj-virtual-machine:~/Desktop$ sudo perf report -n --stdio
# To display the perf.data header info, please use --header/--header-only optio>
#
#
# Total Lost Samples: 0
#
# Samples: 5K of event 'cpu-clock:pppH'
# Event count (approx.): 59999999400
#
# Children Self Samples Command Shared Object >
# ........ ........ ............ ............... ..........................>
#
79.33% 0.00% 0 swapper [kernel.kallsyms] >
|
---secondary_startup_64_no_verify
|
|--40.51%--x86_64_start_kernel
| x86_64_start_reservations
| start_kernel
| arch_call_rest_init
| rest_init
| cpu_startup_entry
| do_idle
| cpuidle_idle_call
:...skipping...
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 5K of event 'cpu-clock:pppH'
# Event count (approx.): 59999999400
#
# Children Self Samples Command Shared Object Symbol
# ........ ........ ............ ............... ..................................... ....................................................
#
79.33% 0.00% 0 swapper [kernel.kallsyms] [k] secondary_startup_64_no_verify
|
---secondary_startup_64_no_verify
|
|--40.51%--x86_64_start_kernel
| x86_64_start_reservations
| start_kernel
| arch_call_rest_init
| rest_init
| cpu_startup_entry
| do_idle
| cpuidle_idle_call
| cpuidle_enter
| cpuidle_enter_state
| acpi_idle_enter
| native_safe_halt
|
--38.82%--start_secondary
cpu_startup_entry
do_idle
cpuidle_idle_call
cpuidle_enter
cpuidle_enter_state
acpi_idle_enter
native_safe_halt
79.33% 0.00% 0 swapper [kernel.kallsyms] [k] cpu_startup_entry
|
---cpu_startup_entry
do_idle
cpuidle_idle_call
cpuidle_enter
cpuidle_enter_state
acpi_idle_enter
native_safe_halt
# To display the perf.data header info, please use --header/--header-only options.
#
#
# Total Lost Samples: 0
#
# Samples: 5K of event 'cpu-clock:pppH'
# Event count (approx.): 59999999400
#
# Children Self Samples Command Shared Object Symbol
# ........ ........ ............ ............... ..................................... ....................................................
#
79.33% 0.00% 0 swapper [kernel.kallsyms] [k] secondary_startup_64_no_verify
|
---secondary_startup_64_no_verify
|
|--40.51%--x86_64_start_kernel
| x86_64_start_reservations
| start_kernel
| arch_call_rest_init
| rest_init
| cpu_startup_entry
| do_idle
| cpuidle_idle_call
| cpuidle_enter
| cpuidle_enter_state
| acpi_idle_enter
| native_safe_halt
|
--38.82%--start_secondary
cpu_startup_entry
do_idle
cpuidle_idle_call
cpuidle_enter
cpuidle_enter_state
acpi_idle_enter
native_safe_halt
79.33% 0.00% 0 swapper [kernel.kallsyms] [k] cpu_startup_entry
|
---cpu_startup_entry
do_idle
cpuidle_idle_call
cpuidle_enter
cpuidle_enter_state
[.......]
[.......]
[.......]
perf report的摘要结果以从父函数到子函数的形式展示了整棵调用树信息(在一些旧版本中，默认是以反序输出的)。不过，单从这条输出中无法得出有效的结论——完整输出超过了6000行。而perf script的输出结果，包含了每一条信息的详细内容，共计超过60 000行。在比较繁忙的系统中，这些命令的输出可能会更多，甚至达到目前的十倍以上。在这种情况下，可以用火焰图的形式更好地展示这些调用栈信息。
CPU火焰图
第2章中介绍过火焰图，可以用来可视化调用栈信息。这种火焰图非常适合展示CPU性能分析结果，现在已经很常见了。
图6-3所示的火焰图展示的就是上一节的输出结果。
当我们用火焰图的方式展示数据时，显而易见，一个名为iperf的进程消耗了很多CPU，而且可以看到具体的调用函数：socksendmsg(),这个函数的两个子调用占用了很多CPU时间，copy_user_enhanced_fast_string() 和move_freepages_block()， 在图中以一个长条的形式表现出来。而在图片右侧，则是一个高塔，展示了调用一直持续到内核的TCP接收处理器函数中。这个结果是iperf针对localhost进行性能测试时的采样信息。
以下是利用perf(1)指令以49Hz的频率采样30秒,并且产生CPU火焰图的全部命令:
stackcollapse- perf.pl将perf script的输出转化为flamegraph.pl可以接受的标准格式。FlameGraph代码仓库中有很多其他性能分析器的输出转化脚本。
FlameGraph.pl程序生成了一个SVG文件格式的火焰图，自带JavaScript以便在浏览器中交互。Flamegraph.pl命令有很多定制选项：用flamegraph.pl -help 可获取更多信息。
建议你将perf script --header的信息保留下来以备未来使用。Netfix 开发了基于d3的新的火焰图工具，以及对应的读取perf script输出的工具，FlameScope。该工具可以将性能分析结果展示为按秒聚合的热力图，以便可以按时间片段分析火焰图。
lj@lj-virtual-machine:~/Desktop$ git clone https://github.com/brendangregg/FlameGraph
Cloning into 'FlameGraph'...
remote: Enumerating objects: 1217, done.
remote: Counting objects: 100% (81/81), done.
remote: Compressing objects: 100% (49/49), done.
remote: Total 1217 (delta 43), reused 53 (delta 32), pack-reused 1136
Receiving objects: 100% (1217/1217), 1.93 MiB | 6.83 MiB/s, done.
Resolving deltas: 100% (700/700), done.
lj@lj-virtual-machine:~/Desktop$ cd FlameGraph
lj@lj-virtual-machine:~/Desktop/FlameGraph$ sudo perf record -F 49 -ag -- sleep 30
[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 1.428 MB perf.data (2939 samples) ]
lj@lj-virtual-machine:~/Desktop/FlameGraph$ perf script --header | ./stackcollapse-perf.pl | ./flamegraph.pl > flamel.svg
成功在上海时间23：20：21执行perf script --header | ./stackcollapse-perf.pl | ./flamegraph.pl > flamel.svg生成flamel.svg
周期采样
当perf(1)以定时采样方式运行时，首先会尝试使用基于PMC的硬件CPU周期溢出事件来进行采样，这个事件会产生一个不可以掩盖的中断(NMI)，在对应的中断处理函数中会进行调用栈采样。但是，很多云服务厂商的虚拟机都没有启用PMC,这可以通过dmesg命令来检查:
在这些系统上运行时，perf(1) 会改为采用基于hrtimer的软中断采样。可以通过
perf -V命令来看到:
软中断模式通常也可以应对大部分性能分析场景。但是，要注意，有一些内核代码路径是没法进行软中断的:这些函数的执行过程中明确禁止了IRQ。例子包括–些CPU调度器函数和- -些硬件事件处理函数，这会导致采样结果中缺少这种代码路径。有关PMC的更多信息，可以参看2.12节。
6.2.5事件统计 与 事件跟踪
一些事件跟踪器同样可以进行CPU性能分析。可以采用的传统的Linux工具有perf(1)和Ftrace,这些工具不仅能够跟踪事件、记录事件相关信息，还可以在内核态中进行事件统计。
perf
perf(1)命令可以跟踪跟踪点、kprobes(内核动态插针)和uprobes(用户态动态插针),最近还添加了对USDT probes(用户态跟踪点探针)的跟踪功能。这些信息可以用来分析到底是什么占用了CPU。
正如下面的例子所示，假设某种原因导致整个系统的所有CPU使用率都很高，但是top(1)命令却显示没有一个具体进程用量很高。造成这种现象的原因可能是系统中存在大量执行时间超短的进程。为了验证这种假设，我们可以用perf stat来跟踪系统中的sched_ process_exec 跟踪点，以便展示所有exec()这类系统调用的发生频率:
注：fork()和_exit()系统调用分别用来创建一个新进程和终止一个进程，而调用exec()类系统调用则是装入一个新程序。当这样一个系统调用执行以后,进程就在所装入程序的全新地址空间恢复运行。
结果展示，exec 每秒发生了超过160次。可以用perf record 来记录每个事件的具体信息，同时用perf script 来展示每条信息:
这个输出展示了运行的全部进程名字，包括make、sh、 cmake 等，这说明系统中可能正在编译程序。
这种大量短期程序消耗资源的现象非常普遍，以至于我们为此开发了一个专用的BPF工具——execsnoop(8)。 这个命令的输出包括进程名字、PID、 CPU、时间戳(秒级)、事件名字，以及事件参数。
perf(1)中还包括一个针对CPU调度器的专用分析命令——perf sched。这条命令采用先记录后分析的方式来分析CPU调度器的行为，同时提供了几种不同的报告形式：每次唤醒的CPU占用时长，调度器延迟的平均值和最大值，以及以ASCII格式展示的每个CPU线程执行和迁移情况。如下面这个例子:
输出信息很多，按行展示了所有CPU调度器上下文切换事件的摘要信息，包括休眠时长( wait time)、调度器延迟( sch delay)，以及CPU运行时长(run time)，单位均为毫秒。输出显示一条sleep(1)命令休眠了1秒，同时1条cc1进程运行了9.9毫秒，并且休眠了19.9 毫秒。
perf sched子命令可以分析很多类型的CPU调度器问题，包括内核中CPU调度器实现中的bug (内核中的CPU调度器实现是一段非 常复杂的代码，因为这段代码需要处理的需求非常复杂)，然而，这种先记录后分析的工作方式成本也很高：这个例子是在一个8CPU系统上记录了1秒的信息，产生了1.9MB的perf.data文件。在一个CPU更多、更忙的系统上长期记录，很可能会产生几百MB的文件，产生文件所消耗的CPU以及写入文件系统的过程可能就会对分析过程产生影响。
为了更好地理解各种调度器事件，perf(1) 的输出一般都需要进行可视化处理。perf(1)同时还有一个timechart子命令来专门生成各种视图。
如果可能的话，笔者建议避免使用perf sched，而应采用BPF工具。这是因为，BPF可以在内核态中直接进行摘要统计，直接输出结果(例如，在6.3.3 节和6.3.4节中介绍的runqlat(8)和runqlen(8)工具)。
Ftrace
Ftrace是一系列跟踪工具的集合,由Steven Rostedt开发,最早在Linux 2.6.27(2008 年)加入内核。正如perf(1)一样,它可以利用各种内核跟踪点和事件来跟踪CPU的使用情况。如下面所示的例子，笔者的perf-tools集https://github.com/brendangregg/perf-tools里面的很多工具都使用了Ftrace 的跟踪技术，并且包括用funccount(8)工具来统计函数调用。这个例子通过统计所有函数名开头为“ext”的调用来统计ext4文件系统的函数调用情况:
这里笔者已经将输出截断，只展示了那些最经常调用的函数。调用频率最高的是ext4_ getattr()， 在跟踪过程中一共被调用了7285 次。
每个函数调用都会消耗CPU资源,而这些函数的名字通常显示了它们的用途是什么。如果函数名称不够清楚，那么一般也很容易在网上找到这些函数的源代码，可直接查看。对Linux内核来说更是如此，因为所有的代码都是开源的。
Ftrace自带了很多非常有用的功能，最近还增加了直方图和更多的调用频率统计功能。但是，和BPF相比，Ftrace没有定制编程功能，所以不能用它来自定义获取和展示数据。
6.3 BPF工具
本节将描述哪些BPF工具可以用来进行CPU性能分析和问题调试，这些工具展示在图6-4里，在表6-3中也进行了展示。
这些工具要么来自第4章和第5章中提到的BCC和bpftrace代码库，要么是在写作本书的时候编写的。有些工具同时出现在BCC和bpftrace仓库中。表6-3列出了这些工具的来源(BT指代bpftrace)。
来自BCC和bpftrace的工具，请到代码库中获取全部的工具调用选项列表，以及它们的功能说明。下文摘选了一些重要的功能说明。
6.3.1 execsnoop
execsnoop(8)来自BCC和bpftrace工具集，是一个跟踪全系统中的新进程执行信息的工具。利用这个工具可以找到消耗大量CPU的短期进程，并且可以用来分析软件执行过程，包括启动脚本等。
BCC版本execsnoop
下面是BCC版本的输出例子:
groups(1)、mesg(1) 等。它还展示了系统行为记录仪(sar) 记录这个进程日志的情况，包括sal(8)和sadc(8)两个进程。
execsnoop(8)可以用来寻找高频出现、消耗资源的短期进程。这些进程由于执行时长非常短，可能在传统工具，例如top,或其他系统监控进程抓取信息之前就消失了。第1章展示了这样的一个例子：一个启动脚本循环不停地试图启动一个应用程序，导致了系统中的性能问题。这样的问题可以很轻易地用execsnoop(8)来发现。execsnoop(8)在多种生产环境问题调试中都发挥了作用：后台任务造成的性能浮动，应用程序启动过慢或者启动失败，容器启动慢或者启动失败问题等。
execsnoop(8)直接跟踪execve(2)系统调用（是最常用的exec(2)变体），可以直接打印execve(2)的调用参数和返回值。这样可以抓取那些通过fork(2)/clone(2)->exec(2)产生的新进程，以及那些自己主动调用exec(2)的进程。有些应用程序可以绕过exec(2)直接产生新进程，例如，某些利用fork(2)和clone(2)直接生成工作进程池的程序。这些输出不会被包含在execsnoop(8)里面,因为它们没有调用execve(2)。不过这种情况并不常见：应用程序通常应该创造线程池，而非进程池。
由于进程创建的频率一般很低 (小于每秒1000次)，因此这个工具的额外消耗是可以忽略不计的。
BCC
BCC版本支持以下几种选项。
- -x：包含exec()失败的情况。
- -npattern：只输出命令符合模式的结果。
- -lpattern：只输出命令参数符合模式的结果。
- –max args args：输出命令参数个数的上限，默认为20。
bpftrace版本execsnoop
下列代码描述了bpftrace 版本的execsnoop(8)的核心功能。这个版本只打印一些基本信息，并不支持任何选项:
BEGIN块中打印了一个表头。为了抓取exec()事件，我们跟踪了sysall:sys_enter_exeeve跟踪点来打印出进程起始运行事件、进程ID，以及命令名和参数值。调用join()函数可将跟踪点读取的args->agrv的信息合为一行，以便和命令一行输出。在bpftrace的未来版本中可能会将join()从直接输出改为返回一个字符串,这样可以将代码改为如下的样子:
join()是一个特殊的函数，用于将多个字符串使用空格进行连接并打印出来。
BCC版本同时跟踪execve()系统调用的起始点和返回点，这样可以输出调用的结果。bpftrace版本的程序也可以很容易地进行这样的扩展。
第13章中有一个类似的工具，threadsnoop(8)， 其可以用来跟踪线程的创建，而非进程的创建。
6.3.2 exitsnoop
exitsnoop(8)是一个BCC工具，可以跟踪进程退出事件，打印出进程的总运行时长和退出原因。运行时长是指进程从创建到终止的时长,包括CPU运行时间和非运行时间。正如execsnoop(8)那样，exitsnoop(8)可以帮助调试短时进程的问题，从另-一个角度理解问题。例如:
本输出展示了很多短期进程退出的情况，例如，cmake(1)、 sh()、 make(1): 系统上正在编译代码。一个sleep(1)进程在一秒之后成功退出(退出代码为0)，另外一个sleep(1)进程在7.31秒后收到KILL信号所以退出。这个输出中还包括一个DOM Worker线程，其在执行221.25秒后退出。
该工具使用的是sched:sched_process_exit 跟踪点和它的参数信息，同时利用bpf_get_current_task() 以便从task结构体中读取起始信息(这并不是一个稳定接口)。由于跟踪点本身的执行频率不高，所以这个工具的额外消耗可以忽略不计。命令行使用说明如下:
参数包括如下几项。
- -p PID：仅测量该进程。
- -t：包含时间戳信息。
- -x：仅关注失败情景(退出代码不为0)。
目前尚不存在bpftrace版本的exitsnoop(8)，不过这个可以作为学习bpftrace 编程的一个练习作业。
6.3.3 runqlat
runqlat(8)是基于BCC和bpftrace的CPU调度器延迟分析工具，CPU调度器延迟通常被称为运行队列延迟(实际上，目前的内部实现已经不再是简单的队列)。在需求超过供给，CPU资源处于饱和状态时，这个工具可以用来识别和量化问题的严重性。runqlat(8)统计的信息是每个线程(任务)等待CPU的耗时。
BCC版本runqlat
下面的输出是用BCC版本的runqlat(8)在48-CPU的生产API机器中，系统CPU使用率大约为42%的时候生成的。runqlat(8) 的参数是“10 1”，意为每10秒输出一次，仅输出一次:
上面的输出显示，在大部分时间内，线程的等待时间小于15微秒，分布在2微秒到15微秒之间。这说明延迟很低——表示系统状态正常——这也是一个CPU利用率处于42%的系统的正常行为。在上面的例子中，运行队列延迟偶尔会升高至8~ 16微秒这个区间，但是这明显是一些离群点。
runqlat(8) 利用对CPU调度器的线程唤醒事件和线程上下文切换事件的跟踪来计算线程从唤醒到运行之间的时间间隔。在一个比较繁忙的生产系统中，这类事件发生的频率可能很高，每秒可超过一万次。 即使BPF程序已经是最优化的实现，在这种频率下如果每个事件的处理过程超过一微秒， 也会对系统造成不小的影响，所以在 使用中要多加注意。
配置错误的软件编译过程
下面用另外一个例子做对比。这次的系统是一个有36个CPU的编译服务器，但是由于一个错误导致编译过程中的并行值被设置成了72，这导致了CPU超载的发生:
输出显示，现在延迟分布呈三峰状态，最高峰处于8~ 16毫秒区间，这说明每个线程的等待时间是很显著的。
这种问题也可以通过其他工具和系统性能指标观测出来。例如，sar(1)可以同时展示CPU利用率(-u)和运行队列性能指标(-q) :
上面的sar(1)命令输出显示CPU空闲时间为0%，平均运行队列长度为72(包括正在运行的线程和等待运行的线程)一这 已经超过了系统的36个CPU的数量。第15章有另外一个runqlat(8)的例子，可以按容器分别展示运行队列延迟值。
BCC
BCC版本的命令使用方式如下:
选项包括如下几个。
- -m：以毫秒为单位输出。
- -P：给每个进程ID打印一个分布图。
- –pidnss：给每个PID命名空间打印一个直方图。
- -P PID：仅跟踪给定的PID进程。
- -T：输出中包含时间戳。
在需要给定时输出结果加上时间戳时,-T选项就很有用了。例如，runqlat -T 1,可以每秒输出一次。
bpftrace版本runqlat
下面这段代码是基于bpfrace的runqlat(8) 实现，展示了该工具的核心功能。这个版本不支持任何选项:
#!/ure/bin/bpftrace /*在文件开始的位置放置一行这样的代码指定解释器*/
#include <linux/sched.h>
tracepoint:sched:sched_wakeup, /*在sched_wakeup和sched_wakeup_new两个跟踪点上记录内核线程ID(args->pid)和时间戳信息。*/
tracepoint:sched:sched_wakeup_new
{
@qtime[args->pid] = nsecs;/*用qtime[args->pid]映射nsecs*/
}
tracepoint:sched:sched_switch
{
if (args->prev_state == TASK_RUNNING) { /*如果线程状态仍然是可运行态*/
@qtime[args->prev_pid] = nsecs; /*用qtime[args->prev_pid]映射nsecs*/
}
$ns = @qtime[args->next_pid]; /*给临时变量ns赋一个qtime[args->next_pid]映射的nsecs值*/
if ($ns) { /*如果已经记录了下一个运行的线程的时间戳*/
@usecs = hist((nsecs - $ns) / 1000); /*hist((nsecs - $ns) / 1000)将(nsecs-$ns)/1000保存在一个以2的幂为区间的直方图中，当输出时(即按下ctrl+C时)，会打印桶的数值和ASCII字符形式的直方图。*/
}
delete(@qtime [args->next_pid]); /*delete()从映射表中刪除一个键值对*/
}
这段代码在sched_wakeup和sched_wakeup_new两个跟踪点上记录内核线程ID(args->pid)和时间戳信息。
在sched_switch 处理函数中，如果线程状态仍然是可运行态(TASK_RUNNING),则记录args->prev_pid 和对应的时间戳。这是为了处理被动上下文切换的情况，在这种情况下线程脱离CPU之后，马上返回到运行队列中。同时，在这个处理函数里检查了是否已经记录了下一个运行的线程的时间戳，如果是，则计算时间戳的差值并记录到@usec这个直方图中。
因为这里需要使用TASK_RUNNING常数，所以用#include linux/sched.h 包含了头文件。
BCC版本可以按PID分别输出结果，基于bpfrace的版本也可以通过在@usec映射中增加一个新的pid键名来做到。BCC版本的另外一个功能是可以忽略PID为0的线程的延迟值，因为这是内核的空闲线程。 同样地，bpfrace 版本也可以很容易地支持这个功能。
6.3.4 runqlen
runqlen(8)是一个基于BCC和bpftrace的工具，用来采样CPU运行队列的长度信息，可以统计有多少线程正在等待运行，并且以线性直方图的方式输出。这个结果可以作为一个成本较低的统计信息来分析运行队列延迟高的问题。
下面这个例子显示了在一个48-CPU、CPU利用率为42%左右的生产API机器上, 运行BCC版本的runqlen(8)的输出。(这和前面运行runqlat(8)例子的是同–台机器。)runqlen(8)的参数是“10 1"， 表示每10秒输出一次，仅输出一次:
输出结果显示，大部分时间运行队列的长度为0，意味着线程不需要等待可以立即执行。
笔者在这里将运行队列长度分类为二级指标，而运行队列延迟为一类指标。 因为运行队列延迟是直接地且按比例地影响系统性能，而运行队列长度则不一定。设想一下，在超市排队等待结账时，哪个指标对你来说更重要:是队伍的长度还是实际等待的时长?显而易见，runqlat(8) 的作用更大。那么为什么要使用runqlen(8) 呢?
首先，runqlen(8) 可以进一步定性分析runqlat(8)发现的系统问题，解释为什么运行队列延迟这么高。其次，runqlen(8) 的采样频率是99Hz，而runqlat(8)需要跟踪CPU调度器事件。相比runqlat(8)的事件跟踪消耗，定时采样的消耗几乎可以忽略不计。对7天24小时的监控来说，应该优先使用runglen(8)来识别问题(因为消耗较低)，再用runqlat(8)来量化延迟。
四个线程，一个CPU
在这个例子中，一个受限于CPU的进程有四个线程，固定在CPU0上运行。执行runqlen(8)的时候加上了-C参数，以便按CPU输出结果:
CPU 0的运行队列长度为3：一个线程在CPU上执行，另三个线程正在等待。这种按CPU进行的分别输出在识别CPU调度器的负载均衡问题上很有用。
BCC 版本runqlen
命令行使用说明如下:
命令选项包括如下几个。
- -C：每个CPU输出一个直方图。
- -O：运行队列占有率信息，运行队列不为0的时长百分比。
- -T：在输出中包括时间戳信息。
运行队列占有率展示了运行队列长度不为0 （有线程在等待时）的时间比例，如果你需要一个固定指标来进行监控、报警和绘图的话，这个指标很有用。
bpftrace版本runqlen
下面这段代码是bpftrace版本的runqlen(8)实现，展示了该工具的核心功能。这个版本不支持任何选项:
#!/ure/bin/bpftrace /*在文件开始的位置放置一行这样的代码指定解释器*/
#include <linux/sched.h>
struct cfs_rq_partial {
struct load_weight_load;
unsigned long runnable_weight;
unsigned int nr_running;
};
profile:hz:99 /*profile：对全部CPU进行时间采样的探针类型。hz:99表示采样频率为99赫兹。动作是下面中括号{}内的*/
{
$task = (struct task_struct *)curtask; /*给临时变量task赋值*/
$my_q = (struct cfs_rq_partial *)$task->se.cfs_rq; /*给临时变量my_q赋值*/
$len = $my_q->nr_running; /*给临时变量len赋值,nr_running:表示总共就绪的进程数*/
$len = $len > 0 ? $len - 1 : 0; /*若len小于0，给临时变量len赋值0，否则给len赋值len-1*/
@runqlen = lhist($len,0,100,1); /*用runqlen映射一个数据来源与len的区间宽度为1的线性直方图*/
/*lhist(数据，第一个区间尾点，最后一个区间起点，每个区间的宽度)将值保存为线性直方图，*/
/*当输出时(即按下ctrl+C时)，会打印线性直方图，用runqlen映射一个线性直方图 */
}
下列直方图可以看出：采到就绪的进程数为0有2740次。采到就绪的进程数为100有36次。
lj@lj-virtual-machine:~/Desktop$ sudo bpftrace test1.bt
Attaching 1 probe...
^C
@runqlen:
[0, 1) 2740 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[1, 2) 0 | |
[2, 3) 0 | |
[3, 4) 0 | |
[4, 5) 0 | |
[5, 6) 0 | |
[6, 7) 0 | |
[7, 8) 0 | |
[8, 9) 0 | |
[9, 10) 0 | |
[10, 11) 0 | |
[11, 12) 0 | |
[12, 13) 0 | |
[13, 14) 0 | |
[14, 15) 0 | |
[15, 16) 0 | |
[16, 17) 0 | |
[17, 18) 0 | |
[18, 19) 0 | |
[19, 20) 0 | |
[20, 21) 0 | |
[21, 22) 0 | |
[22, 23) 0 | |
[23, 24) 0 | |
[24, 25) 0 | |
[25, 26) 0 | |
[26, 27) 0 | |
[27, 28) 0 | |
[28, 29) 0 | |
[29, 30) 0 | |
[30, 31) 0 | |
[31, 32) 0 | |
[32, 33) 0 | |
[33, 34) 0 | |
[34, 35) 0 | |
[35, 36) 0 | |
[36, 37) 0 | |
[37, 38) 0 | |
[38, 39) 0 | |
[39, 40) 0 | |
[40, 41) 0 | |
[41, 42) 0 | |
[42, 43) 0 | |
[43, 44) 0 | |
[44, 45) 0 | |
[45, 46) 0 | |
[46, 47) 0 | |
[47, 48) 0 | |
[48, 49) 0 | |
[49, 50) 0 | |
[50, 51) 0 | |
[51, 52) 0 | |
[52, 53) 0 | |
[53, 54) 0 | |
[54, 55) 0 | |
[55, 56) 0 | |
[56, 57) 0 | |
[57, 58) 0 | |
[58, 59) 0 | |
[59, 60) 0 | |
[60, 61) 0 | |
[61, 62) 0 | |
[62, 63) 0 | |
[63, 64) 0 | |
[64, 65) 0 | |
[65, 66) 0 | |
[66, 67) 0 | |
[67, 68) 0 | |
[68, 69) 0 | |
[69, 70) 0 | |
[70, 71) 0 | |
[71, 72) 0 | |
[72, 73) 0 | |
[73, 74) 0 | |
[74, 75) 0 | |
[75, 76) 0 | |
[76, 77) 0 | |
[77, 78) 0 | |
[78, 79) 0 | |
[79, 80) 0 | |
[80, 81) 0 | |
[81, 82) 0 | |
[82, 83) 0 | |
[83, 84) 0 | |
[84, 85) 0 | |
[85, 86) 0 | |
[86, 87) 0 | |
[87, 88) 0 | |
[88, 89) 0 | |
[89, 90) 0 | |
[90, 91) 0 | |
[91, 92) 0 | |
[92, 93) 0 | |
[93, 94) 0 | |
[94, 95) 0 | |
[95, 96) 0 | |
[96, 97) 0 | |
[97, 98) 0 | |
[98, 99) 0 | |
[99, 100) 0 | |
[100, ...) 36 | |
lj@lj-virtual-machine:~/Desktop$
这段程序需要读取cfs_rq结构体的nr_running 成员变量，但是这个结构体的定义并不在标准的内核头文件中，所以这个程序定义了一个cfs_rq_partial 结构体，用来读取对应的成员变量值。在BTF可用之后就可能不需要这样做了(参见第2章)。
这段程序主要处理的事件是profile:hz:99探针，这个探针以99Hz的频率采样所有CPU的运行队列长度。读取方式是通过从当前task结构体找到当前的运行队列结构体，再读取其中的长度信息。这些结构体的名字和成员的名字可能要根据内核源代码的变动进行修改。
可以通过给@runqlen映射增加一个cpu键来扩展bpftrace版本，以便按每个CPU输出直方图。
6.3.5 runqslower
runqslower(8)是一个BCC工具，它可以列出运行队列中等待延迟超过阈值的线程名字，可以输出受延迟影响的进程名和对应的延迟时长。下面这个例子是在48-CPU、系统CPU利用率在45%左右的生产API机器中产生的:
这个输出展示了在13秒内，超过默认阈值10000微秒(10毫秒)的运行队列延迟发生了10次。这对一个还有55% CPU空闲率的服务器来说可能是有点出人意料的。服务器上运行了一个很繁忙的多线程应用程序，可能在CPU调度器将线程迁移到其他CPU之前会造成运行队列不均衡的问题。这个工具可以用来确认哪个应用程序受到了影响。
目前这个工具使用的是内核中的ttwu_do_wakeup()函数、wake_up_new_task() 函数和finish_task_switch()函数所对应的kprobes。未来的版本可能会像之前bpftrace版本的runqlat(8) 一样，改为使用CPU调度器跟踪点。这个程序的额外消耗与runqlat(8)类似，即使runqslower(8)不产生任何输出，在一个繁忙的系统上使用kprobes也会造成不可忽视的性能损耗。
命令行使用说明如下:
命令行选项包括以下一项。
- -pPID:仅测量给定的进程。
默认的阈值为10 000微秒。
6.3.6 cpudist
cpudist(8) 是一个BCC工具,用来展示每次线程唤醒之后在CPU上执行的时长分布。这可以帮助定性分析CPU的使用率，以便为未来设计和优化提供决策信息。例如，在一个48-CPU的生产机器上的输出如下:
这个输出显示了生产应用程序在CPU上执行的时间很短：在0到127微秒之间。这是一个大量使用CPU的任务，忙碌的线程数量超过可用的CPU数量，下面是按毫秒输出的直方图信息(-m):
这里显示了CPU使用时长分布的一个高峰在4~ 15亳秒区间：这很可能是因为线程超过了CPU调度器分配的运行时长，从而进行了被动上下文切换。
这个工具在分析某个Netlix的变更的性能影响时发挥了作用，如某个机器学习程序执行速度变快了三倍。perf(1) 命令展示了，上下文切换频率下降了，而cpudist(8)则解释了具体的性能变化。变更之前每个线程只能运行0~ 3微秒就被上下文切换中断了。
cpudist(8)在内部跟踪CPU调度器的上下文切换事件，这些事件在繁忙的生产环境中发生的频率非常高( 每秒可能超过一百万次)。和runqlat(8)一样，这个工具的额外消耗可能很显著，使用时需要多加小心。
命令行使用说明如下:
命令行选项包括如下几项。
- -m:以毫秒为单位输出(默认单位为微秒)。
- -O:输出脱离CPU的时间，而不是在CPU上执行的时间。
- -P:每个进程打印一一个直方图。
- -p PID:仅测量给定的进程。
目前没有bpftrace版本的cpudist(8)， 笔者想将这个实现作为一个作业留给你完成。
6.3.7 cpufreq
bcc版本cpufreq
cpufreq(8)采样CPU频率信息，可以作为全系统直方图显示，也可以按进程名分别输出直方图。这个命令只在使用支持频率调整的CPU调度器下才起作用，例如：powersave。这个命令可用来输出应用程序运行时的对应的CPU频率信息。例如:
上面这些输出，显示了整个系统的CPU频率处于1200~1400MHz区间，这显示了该系统基本上处于空闲状态。同样地，java 进程运行过程中的频率数据也类似，只有在少数采样点(共18个样本)，频率上升到3000 ~ 3200MHz区间。该应用程序大部分时间都在等待磁盘/O，导致CPU进入省电模式。而python3进程的大部分时间在全功率情况下运行。
这个工具通过跟踪内核中有频率变化的跟踪点来计算CPU的运算频率，并且以100Hz的频率采样。性能上的额外损耗可以低至忽略不计。之前的输出是在一个采用了powersave 频率调整器的系统之上运行得出的，这个可以通过/sys/devices/system/cpu/
pure/…/scaing. govemor来设置。当设置为performance频率调整器时，该工具将不会有任何输出，因为CPU永远处于最高频率，没有频率改变的事件，也就无从跟踪。
以下是笔者在一个生产系统上得出的结果:
该输出显示了生产环境中的一个应用程序nginx，大部分时间处于低CPU频率模式下运行。CPU频率调整器默认被设置为powersave,而不是performance模式。
bpftrace版本cpufreq
cpufreq(8)的bpftrace源代码如下:
该程序通过使用power:cpu_frequency 跟踪点来跟踪CPU频率的变化，以CPU为键存入@curfreq BPF映射表中，以供未来采样时读取。直方图范围为0 ~ 5000MHz，每200MHz为一个区间，如果有需要，这些参数可以在源代码中进行调整。
按进程名分别输出CPU频率直方图,英特尔® 酷睿™ i5-1135G7 处理器支持频率调整
#!/ure/bin/bpftrace /*在文件开始的位置放置一行这样的代码指定解释器*/
/*tracepoint探针类型是内核静态插桩点。power:cpu_frequency是跟踪点的全名，包括用来将跟踪点所在的类别(power)和事件名字(cpu_frequency)分隔开的冒号。*/
tracepoint:power:cpu_frequency //cpu_frequency:CPU的频率
{
@curfreq[cpu] = args->state;
}
/*profile：对全部CPU进行时间采样的探针类型。hz:100表示采样频率为100赫兹。动作是下面中括号{}内的*/
profile:hz:100
{
@system_mhz = lhist(@curfreq[cpu] / 1000,0,1000,20);
if(pid){
@process_mhz[comm] = lhist(@curfreq[cpu] / 1000,0,1000,20);
}
}
经过调试也许形成不了直方图，是因为数据全为0
总结应该是：通过tracepoint:power:cpu_frequency的@curfreq[cpu] = args->state;映射的数据，不是CPU的频率。应该是作者写书时，这样写可以跟踪cpu频率，几年后我现在看书无法跟踪cpu频率了
可以试一试看看关于跟踪点的更多信息，去看看内核源代码树下的Documentation/trace/tracepoints.rst文件，作者是Mathieu Desnoyers。看看跟踪点power:cpu_frequency的更多详情。
6.3.8 profile
bcc版本
profile(8)是一个定时采样调用栈信息并且汇报调用栈出现频率信息的BCC工具。这是BCC工具中分析CPU占用信息最有用的工具之一，因为该工具可以同时记录几乎所有占用CPU的代码调用栈。(有关其他的CPU占用分析请参看6.3.14节中的hardirq工具。)该工具的额外消耗几乎可以忽略不计，因为该工具是定时采样，采样频率可以随时调整。
默认情况下，该工具以49Hz(每秒49次)的频率同时采样所有CPU的用户态和内核态的调用栈。命令行参数可以被调整，所有的设置参数会同时首先输出在结果的第一行中。例如:
上面这段程序将调用栈信息按函数作为一个列表输出，列表之后有一个“一”短横线以及进程名，括号中包括进程PID信息，输出的最后是调用栈信息的个数。调用栈信息是按出现频率的高低输出的，从出现频率最低到最高。
上面的完整输出有17254行之多，这里笔者只节选了第一个调用栈信息，和最后两个调用栈信息。出现频率最高的调用栈，从vfis_write() 起始，一直到正在 CPU上运行的get_page_from_frelist()函数，在采样期间一共出现了 2673次。
CPU火焰图
火焰图是调用栈展示方式的一种， 可以帮助你快速理解profile(8)命令的输出。有关火焰图的介绍请参阅第2章。
要支持生成火焰图，profile(8) 的命令可以以-f参数调用，以便折叠输出:整个调用栈以一整行输出，每个函数以分号分割。
例如，下面的命令将30秒的采样信息输出到out.stacks01文件中，并且在输出中标记内核函数(-a) :
这里只显示了输出的后三行。完整的输出可以直接输入给之前的火焰图脚本，以生成CPU火焰图:
famegraph.pl支持多种调色板,这里选择的java调色板可按照内核函数标记(“_[k]”)选择不同的颜色，最终生成的SVG图片展示在图6-5中。
在图6-5中,消耗CPU时间最长的函数调用路径最终终结于get_page_from_freelist_()以及__freepages_ok_()——这是图中最宽的部分,宽度与采样结果中的出现频率成比例。在浏览器中，这个SVG图片支持单击缩放功能，可以单击较窄的部分查看完整的函数名称。
profile(8) 工具与其他性能分析工具的主要差别就是，其频率统计是在内核态中完成的，这十分高效。其他内核态的分析工具，例如，perf(1) 等，需要将所有的采样信息发送到内核态，进行处理后才能得出统计信息。这种处理过程会消耗很多CPU资源，同时根据不同的调用方式，记录采样信息的过程可能还会消耗文件系统与磁盘I/O。而profile(8)命令则避免了这些额外开销。
命令行使用说明如下:
命令行参数包括如下几项。
- -U:仅输出用户态调用栈信息。
- -K:仅输出内核态调用栈信息。
- -a:在函数名称上加上标记(例如，为内核态函数加上“[k]")。
- -d:在用户态和内核态调用栈之间加上分隔符。
- -f:以折叠方式输出。
- -P PID:仅跟踪给定的进程。
bpftrace版本
profile(8)的核心功能可以用下面的bpfrace单行程序得出:
这里，程序以用户态调用栈ustack、内核态调用栈kstack和进程名称(comm)为键保存出现频率信息。同时，过滤了PID 为0的情况，以便忽略CPU空闲线程。这行程序可以按需要进一步修改。
/* profile：对全部CPU进行时间采样的探针类型。hz:49表示采样频率为49赫兹(每秒49次动作)。动作是下面中括号{}内的 */
/* /pid/等价于/pid !=0/只在内置变量PID (进程ID)不等于0时才会触发执行后续动作。 */
/* 内置变量kstack和ustack以多行字符串文本形式返回内核态和用户态的调用栈信息。返回的栈深度最大为127。内置变量comm是进程名*/
/* count()对出现次数进行计数。 */
bpftrace -e 'profile:hz:49 /pid/ { @samples[ustack,kstack,comm] = count(); }'
lj@lj-virtual-machine:~/Desktop$ sudo bpftrace -e 'profile:hz:49 /pid/ { @samples[ustack,kstack,comm] = count(); }'
[sudo] password for lj:
Attaching 1 probe...
^C
@samples[
0x7f023589f933
,
clear_page_erms+7
get_page_from_freelist+851
__alloc_pages+382
alloc_pages_vma+157
shmem_alloc_page+135
shmem_alloc_and_acct_page+127
shmem_getpage_gfp+1181
shmem_fault+106
__do_fault+57
do_fault+431
handle_pte_fault+461
__handle_mm_fault+1029
handle_mm_fault+216
do_user_addr_fault+457
exc_page_fault+119
asm_exc_page_fault+38
,
gnome-terminal-]: 1
[......]
6.3.9 offcputime
offcputime(8)是一个BCC和bpfrace工具，用于统计线程阻塞和脱离CPU运行的时间，同时输出调用栈信息，以便理解阻塞原因。在CPU分析过程中，这个工具可以用来分析为什么线程没有在CPU上运行。这正好是profile(8)工具的对立面；这两个工具结合起来覆盖了线程的全部生命周期：profile(8) 工具覆盖在CPU之上运行的分析，而offcputime(8)则分析脱离CPU运行的时间。
下面这个例子展示了BCC版本的offcputime(8)跟踪5秒的输出:
输出被截断后只显示了几百个调用栈中的其中三个。每个调用栈首先展示内核态函数(如果有的话)，然后是用户态函数，之后是进程名字、PID，以及该调用栈出现的全部时间(单位是微秒)。上述第一个调用栈显示，iperf(1) 命令被阻塞在sk_stream_wait_memory()函数上，等待内存加载，等待时长为5毫秒。第二个调用栈显示iperf(1)正在通过sk_wait_data()函数等待socket数据，等待时长为1.02秒。最后一个调用栈显示offeputime(8)工具自已正在等待select(2)系统调用，时长为5.00秒。这应该就是命令行中指定的5秒超时时间。
注意，在所有的三个调用栈信息中，用户态调用栈信息是不完整的。这是因为它们都使用了libe，而当前版本不支持帧指针( frame pointer)。 这个问题在offcputime(8)中要比在profile(8)中更明显，因为大部分的阻塞调用都会经过类似libe和libpthread这样的系统库。有关不完整的调用栈信息和对应的解决方案，请参看第2章、第12章、第13章及第18章等，尤其请参见13.2.9节。
offeputime(8)可以用来调查各种各样的生产问题，这包括长时间锁等待之类的问题，可以通过对应的函数调用栈信息来分析。
offcputime(8)通过跟踪上下文切换事件来记录一个线程脱离CPU的时间和返回CPU的时间，同时记录调用栈信息。为了效率，这些时间和调用栈信息的记录是在内核中进行频率统计的。不论如何，上下文切换事件仍然是比较频繁的，该工具在比较繁忙的生产环境中的额外消耗可能比较显著(可能超过10%)。这个工具最好还是短期运行，以减少对生产环境的影响。
脱离CPU时间的火焰图
与profile(8)命令一样， offcputime(8) 的输出信息太多，可能以火焰图方式分析起来更好，不过，这里用到的火焰图和第2章中介绍的火焰图并不一样。 offcputime(8) 的输出可以以off-CPU时间火焰图的方式来展示。
下面这个例子生成了一个内核调用栈5秒的火焰图:
这里笔者用了–bgcolors参数来将背景颜色设置为蓝色，这样可与CPU火焰图相区别。同时，可以用–colors来改变调用栈的颜色，这是笔者习惯用的颜色，笔者公布的很多off-CPU火焰图都是以蓝色为背景的。
这些命令输出的是图6-6所示的火焰图。
该火焰图中的大部分时间主要由线程休眠等待任务组成。可以通过单击名字来缩放火焰图以详细检视具体的应用程序。有关off-CPU火焰图的更多例子，包括完整的用户态调用栈信息，请参看第12章、第13章和第14章。
BCC版本offcputime
命令行使用说明如下:
命令行参数包括如下几项。
■-f:以折叠的方式输出。
■-PPID:仅输出给定的进程。
■-u: 仅包括用户态线程。
■-k:仅包括内核态线程。
■-U:仅包括用户态调用栈信息。
■-K:仅包括内核态调用栈信息。
这些命令行参数可以通过仅跟踪某个进程或某类调用栈信息来降低额外消耗。
bpftrace版本offcputime
下面这段代码是bpftrace版本的offcputime(8)实现，展现了其核心功能。这个版本支持传入一个PID参数来跟踪某个特定进程:
这个程序使用finish_task_swtich( kprobe给脱离CPU的线程记录-一个时间戳，并且将启动的线程的所有脱离CPU的时间进行合计。
#!/ure/bin/bpftrace /*在文件开始的位置放置一行这样的代码指定解释器*/
#include <linux/sched.h>
kprobe:finish_task_switch /*内核动态插桩，对内核函数finish_task_switch的开始(入口)进行插桩*/
{
// record previous(先前的) thread sleep time(@start [$prev->pid])
$prev = (struct task_struct *)arg0; /*内置变量arg0某些探针的参数，进行强制类型转换为*task_struct */
if ($l == 0 || $prev->tgid == $1) { /*tgid(线程组leader的进程ID,$1代表第1个参数，$2代表第2个，以此类推,用符号“ || ”表示的 逻辑“或”运算符*/
@start [$prev->pid] = nsecs;
}
// get the current thread start time($last)
$last = @start[tid]; /*给临时变量last赋键start[tid]映射的值*/
if ($last != 0) {
@[kstack,ustack,comm] = sum(nsecs - $last);/*sum()是求和函数（将启动的线程的所有脱离CPU的时间进行合计）*/
delete(@start[tid]); /*delete()从映射表中刪除一个键值对。*/
}
}
lj@lj-virtual-machine:~/Desktop$ sudo bpftrace test1.bt
test1.bt:2-5: WARNING: finish_task_switch is not traceable (either non-existing, inlined, or marked as "notrace"); attaching to it will likely fail
Attaching 1 probe...
cannot attach kprobe, probe entry may not exist
ERROR: Error attaching probe: 'kprobe:finish_task_switch'
lj@lj-virtual-machine:~/Desktop$
6.3.10 syscount
syscount(8)是一个BCC和bpftrace工具，用来统计系统中的系统调用数量。在本章中我们加入了这个工具，因为这个工具可以用来调查系统CPU占用时间长的问题。下面这段输出展示了BCC版本的syscount(8)在一个生产系统中每秒系统调用的数量(-i 1):
上面这段输出展示了每秒之内的前10个系统调用，以及一个时间戳信息。最频繁的系统调用是futex(2)， 每秒调用超过150 000次。有关系统调用的更多信息，请参看man帮助文档，另外可以用其他的BPF工具来查看这些系统调用的参数信息(例如，BCC版本的trace(8)，或者bpftrace小程序)。在有些情况下，运行strace(1)是理解某个系统调用情况的最简单方式，但是一定要记住，目前基于ptrace的strace(1)实现会导致应用程序性能下降至不足原先的1%。这在很多生产环境中是会造成严重问题的，例如，导致系统延迟，上升，或者导致负载均衡系统自动迁移等。只有在BPF工具不能满足需求的时候，才考虑使用strace(1)。
可以用-P选项来指定跟踪某个进程:
从上述输出可看到，java 进程大概每秒执行300 000次系统调用。利用其他工具还可以看到这个进程在当前48-CPU的系统上只占用了1.6%的系统时间。
这个工具利用的是raw_ sysall:sys_ enter这个跟踪点，而没有使用常见的sysallsys_enter*跟踪点。使用这个跟踪点的原因是它能够看到全部的系统调用。缺点是，这个跟踪点只能提供系统调用的ID，必须要转换成具体的名字，BCC提供了一个库函数——syscall_name()——可解决这个问题。
在系统调用量很大的情况下，这个工具的额外开销也会上升。作为一个测试，笔者写了一个测试程序，系统中的一个CPU大概每秒可以处理320万次系统调用。当运行该程序时，这个测试程序的性能下降了30%。这可以推测出该工具在生产环境下的性能损耗:在一个48-CPU的系统中，如果系统调用每秒执行300 000次，那么平均每个CPU每秒处理6000次，那么预期的最终额外损耗大概是0.06% ( 30% X 6250/3200000)。笔者试图在生产系统中直接测量这个数据，但是数值实在太小，得不出结果。
BCC版本syscount
命令行使用说明如下:
命令行选项包括如下几项。
- -T TOP:仅打印调用频率最高的N个结果。
- -L:打印系统调用的总耗时(延迟)。
- -P:按进程分别统计。
- -P PID:仅统计给定的进程。
有关-L选项的例子参见第13章。
bpftrace版本syscount
syscount(8)有对应的bpfrace版本，覆盖了核心功能。但是你也可以使用以下这个小程序:
在这个示例中,跟踪了系统中的所有316个系统调用跟踪点(以当前内核版本为准)，同时按探针的名字分别进行了频率统计。在这个实现中，程序启动和退出时需要逐个注册每个跟踪点，这需要消耗一定的时间。 如果像BCC版本一样，使用单独的raw_syscall:sys_enter 跟踪点就更好了，但是这样需要增加从ID转换回名字的步骤。可参见第14章中的例子。
lj@lj-virtual-machine:~/Desktop$ bpftrace --help
USAGE:
bpftrace [options] filename
bpftrace [options] - <stdin input>
bpftrace [options] -e 'program'
OPTIONS:
-B MODE output buffering mode ('full', 'none')
-f FORMAT output format ('text', 'json')
-o file redirect bpftrace output to file
-d debug info dry run
-dd verbose debug info dry run
-e 'program' execute(执行) this program
-h, --help show this help message
-I DIR add the directory to the include search path
--include FILE add an #include file before preprocessing
-l [search] list probes
-p PID enable USDT probes on PID
-c 'CMD' run CMD and enable USDT probes on resulting process
--usdt-file-activation
activate usdt semaphores based on file path
--unsafe allow unsafe builtin functions
-q keep messages quiet
-v verbose messages
--info Print information about kernel BPF support
-k emit a warning when a bpf helper returns an error (except read functions)
-kk check all bpf helper functions
-V, --version bpftrace version
--no-warnings disable all warning messages
ENVIRONMENT:
BPFTRACE_STRLEN [default: 64] bytes on BPF stack per str()
BPFTRACE_NO_CPP_DEMANGLE [default: 0] disable C++ symbol demangling
BPFTRACE_MAP_KEYS_MAX [default: 4096] max keys in a map
BPFTRACE_CAT_BYTES_MAX [default: 10k] maximum bytes read by cat builtin
BPFTRACE_MAX_PROBES [default: 512] max number of probes
BPFTRACE_LOG_SIZE [default: 1000000] log size in bytes
BPFTRACE_PERF_RB_PAGES [default: 64] pages per CPU to allocate for ring buffer
BPFTRACE_NO_USER_SYMBOLS [default: 0] disable user symbol resolution
BPFTRACE_CACHE_USER_SYMBOLS [default: auto] enable user symbol cache
BPFTRACE_VMLINUX [default: none] vmlinux path used for kernel symbol resolution
BPFTRACE_BTF [default: none] BTF file
EXAMPLES:
bpftrace -l '*sleep*'
list probes containing "sleep"
bpftrace -e 'kprobe:do_nanosleep { printf("PID %d sleeping...\n", pid); }'
trace processes calling sleep
bpftrace -e 'tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }'
count syscalls by process name
lj@lj-virtual-machine:~/Desktop$
/*t是缩写，内核静态插桩，跟踪点syscalls:sys_enter_*。 */
/*count()对出现次数进行计数。 */
/*当前探针的全名 */
bpftrace -e 't:syscalls:sys_enter_* { @[probe] = count(); }'
lj@lj-virtual-machine:~/Desktop$ sudo bpftrace bpftrace -e 't:syscalls:sys_enter_* { @[probe] = count(); }'
Attaching 343 probes...
^C
@[tracepoint:syscalls:sys_enter_nanosleep]: 1
@[tracepoint:syscalls:sys_enter_rt_sigreturn]: 1
@[tracepoint:syscalls:sys_enter_syslog]: 1
@[tracepoint:syscalls:sys_enter_ftruncate]: 1
@[tracepoint:syscalls:sys_enter_ppoll]: 4
@[tracepoint:syscalls:sys_enter_rt_sigaction]: 8
@[tracepoint:syscalls:sys_enter_mprotect]: 16
@[tracepoint:syscalls:sys_enter_gettid]: 19
@[tracepoint:syscalls:sys_enter_getpid]: 19
@[tracepoint:syscalls:sys_enter_timerfd_settime]: 33
@[tracepoint:syscalls:sys_enter_inotify_add_watch]: 36
@[tracepoint:syscalls:sys_enter_pselect6]: 46
@[tracepoint:syscalls:sys_enter_newfstatat]: 56
@[tracepoint:syscalls:sys_enter_sendmsg]: 62
@[tracepoint:syscalls:sys_enter_rt_sigprocmask]: 82
@[tracepoint:syscalls:sys_enter_perf_event_open]: 153
@[tracepoint:syscalls:sys_enter_futex]: 192
@[tracepoint:syscalls:sys_enter_write]: 237
@[tracepoint:syscalls:sys_enter_recvmsg]: 268
@[tracepoint:syscalls:sys_enter_dup]: 312
@[tracepoint:syscalls:sys_enter_bpf]: 333
@[tracepoint:syscalls:sys_enter_openat]: 357
@[tracepoint:syscalls:sys_enter_epoll_wait]: 360
@[tracepoint:syscalls:sys_enter_poll]: 401
@[tracepoint:syscalls:sys_enter_times]: 608
@[tracepoint:syscalls:sys_enter_dup2]: 622
@[tracepoint:syscalls:sys_enter_read]: 678
@[tracepoint:syscalls:sys_enter_ioctl]: 942
@[tracepoint:syscalls:sys_enter_close]: 1025
lj@lj-virtual-machine:~/Desktop$
6.3.11 argdist 和trace
bcc版本
在第4章中，我们介绍了argdist(8)和trace(8)这两个BCC工具，它们可以针对每个事件自定义处理方法。作为syscount(8)工具的补充，如果你发现某个系统调用的调用频率很高，那么就可以使用这些工具来详细调查。
例如，在上文的syscount(8)输出中，read(2) 系统调用出现得很频繁，那么就可以使用argdist(8)来通过内核中的跟踪点或者内核函数来统计该调用的参数和返回值。要使用跟踪点，还需要知道参数的名字，可以通过tplist(8)工具的-v选项来输出:
参数中的count,是read(2)调用缓存的大小。接下来可以用argdist(8)输出直方图信息(-H) :
上述输出显示，很多read(2)调用集中在16~31字节的区间里，以及1024 ~ 2047字节的区间里。argdist(8) 还有一个-C选项，以便输出频率统计信息。
上面这个输出显示的是read(2)调用请求读取的数量，因为我们是在跟踪系统调用。接下来我们可以将这个值与系统调用的返回值进行对比，也就是实际读取的字节数量:
结果显示，有很多0字节或者1字节的读取结果。
由于argdist(8)使用的是内核态中的统计计数，所以它可以用于那些调用非常频繁的系统调用。
trace(8) 可以打印出每个事件，适合调查那些调用不频繁的系统调用，可以显示出每个事件的时间戳和其他一些信息。
bpftrace版本
这个级别的系统调用分析也可以用下面的bpftrace小程序来进行。例如，用直方图统计读取系统调用的请求字节数:
以及返回值:
bpftrace针对负值有一个单独的统计区间((… 0) )，read(2) 的返回值如果为负就说明出现了错误。接下来你可以用bpftrace单行程序来单独统计这些错误值出现的频率:
上面的输出显示出错的代码全部都是11。 根据Linux头文件内的定义(asm-generic/errno-base.h) :
错误值11的意思是“重试”，这个错误是在运行过程正常出现的错误。
6.3.12 funccount
bcc版本
第4章中介绍了funccount(8)，它是一个可以统计事件和函数调用频率的BCC工具。这个工具可以显示函数调用的频率，可以用来调查系统中软件占用CPU的问题。profile(8)可能可以显示哪个函数正在占用CPU，但是不能解释为什么：是因为这个函数执行过程很慢，还是因为这个函数每秒被调用了几百万次。
在下面的例子中，我们在一个繁忙的生产系统中统计了内核中以tcp_开头的所有函数，也就是TCP相关函数的调用频率:
上面的输出显示，tcp_md5_do_lookup()函数调用最频繁，跟踪过程中共计调用了510 322次。
可以利用-i 选项来定时输出结果。例如，之前profile(8)的输出中显示get page_from_freelist() 长期占据了CPU,那么到底是因为它执行慢，还是调用频繁呢?通过按秒统计调用次数可以看出:
这个函数每秒被调用超过50万次。
这个工具是通过函数动态跟踪来统计的：对内核态函数使用kprobes,对用户态函数使用uprobes (第2章中对kprobes和uprobes有详细介绍)。这个工具的额外消耗与函数的调用频率呈正比。对有些函数来说，例如，malloc() 和get page_from_freelist(), 一般调用次数都很频繁，所以如果跟踪这些函数有可能会降低目标应用程序的性能，性能损耗会超过10%，所以应该小心使用。有关额外消耗的计算请参看18.1 节。
命令行使用说明如下:
命令行选项包括如下两项。
- -r：使用正则表达式过滤。
- -P PID：仅跟踪给定的进程。
模式匹配如下所述。
- name或者p:name：跟踪内核名称为name0的函数。
- lib:name：跟踪用户态lib库中的name0函数。
- path:name：跟踪用户态path路径下的文件中的name(函数。
- t:system: name：跟踪系统中的system:name跟踪点。
- *：可以匹配任何字符串。
更多例子可参见4.5节。
bpftrace版本
funccount(8)的核心功能可以用下面的bpfrace单行程序来完成:
这段程序可以进一步修改， 例如，下面的调整可以定时输出结果:
探针interval:s:1 每秒激活1次，可以用于每秒打印事件。
和BCC版本一样，跟踪调用频繁的函数时要多加注意，额外消耗有可能会很高。
6.3.13 softrqs
bcc版本
sofirqs(8)是一个BCC工具，可以显示系统中软中断消耗的CPU时间。全系统的软中断消耗信息在很多工具中都能看到。例如，mpstat(1) 中以%soft这个值显示。同时，软中断事件的计数记录在/proc/sofirqs中。BCC版的softirqs(8) 与其他工具的不同之处在于，这个工具不仅可以处理计数，还可以输出每个IRQ的处理时间。
举例说明，对一个48-CPU的生产环境来说，下面是一个10秒的跟踪结果:
上面这个输出显示，大部分时间都消耗在处理net_ rx 软中断上,共计耗时1358毫秒。这个数字是很客观的，在这个48-CPU的系统上相当于3%的CPU时间。
softirqs(8)内部使用irq:softirq_enter 和irq:oftirq_exit 跟踪点。这个工具的额外消耗与事件发生的频率有关，在一个繁忙的生产环境、网络通信频繁的情况下可能会很显著，在使用的时候要小心。
命令行使用说明如下:
softirqs loptions] [interval [count]]
参数选项包括如下几项。
- -d:将IRQ时间以直方图显示。
- -T:输出中包含时间戳。
-d可以用来分析IRQ时间的分布情况，以便识别中断处理中某些耗时很长的情况。
bpftrace版本
bpfrace版本的sofirqs(8) 还不存在，但是是可以写出来的。下面这个单行程序可以作为一个起点，按向量ID来记录IRQ调用频率:
这些向量ID可以用查表的方式转换成软中断的名字，和BCC版本一样。记录IRQ处理时间需要用到irq:softirq_ exit 跟踪点。
6.3.14 hardirqs
hardirqs(8)是一个BCC工具，用来显示系统处理硬中断的时间。有很多其他工具提供了全系统的硬中断信息。例如，mpstat(1) 工具中以%irq输出了硬中断处理比例。硬中断事件计数记录在/pro/intererupts中。BCC版本的hardirqs(8)与其他工具的主要区别就在于其在计数之外，还可以显示每个硬中断的处理时间。
例如，在下面这个48-CPU的生产系统中跟踪10秒的结果
上面这个输出显示了几个名为eth0-Tx-Rx*的硬中断在10秒内总计处理时间为50毫秒。
hardirqs(8)可以提供那些CPU性能分析器看不到的CPU用量信息。请参看6.2.4 节，
介绍了如何在缺少硬件PMU的云系统上进行性能分析。
这个工具动态跟踪内核中的handle_irq_event_percpu() 函数，不过未来的版本可能会切换到irq:irq_handler_entry 和irq:irq_handler_exit 两个跟踪点。命令行使用说明如下:
命令行选项包括如下几项。
- -d:以直方图方式输出IRQ时间信息。
- -T:输出中包含时间戳。
-d选项可以用来分析处理时间的分布情况，找到是否有处理时间超长的情况。
6.3.15 smpcalls
smpcalls(8)是一个基于bpftrace的工具，可以用来跟踪系统中SMP(对称多处理：Symmetrical Multi-Processing）调用的时间(也称为跨CPU调用)。这个调用，可以让一个CPU在其他CPU之上执行程序，在多CPU系统上可能会是消耗很高的调用过程。例如，下 面这个36-CPU系统上的输出:
笔者第一次运行这个工具就发现了系统中的一个问题: aperfmperf_snapshot_khz 这个函数调用很频繁，并且消耗很高，达到了128 微秒。
smpcalls(8)的源代码如下:
#!/ure/bin/bpftrace /*在文件开始的位置放置一行这样的代码指定解释器*/
kprobe:smp_call_function_ single, /*内核动态插桩，对内核函数smp_call_function_ single的开始(入口)进行插桩*/
kprobe:smp_call_function_many /*内核动态插桩，对内核函数smp_call_function_many的开始(入口)进行插桩*/
{
@ts[tid] = nsecs; /*内置变量nsecs是时间戳*/
@func[tid] = arg1; /*内置变量tid线程ID*/
}
kretprobe:smp_call_function_single, /*内核动态插桩，对内核函数smp_call_function_ single的结束(返回)进行插桩*/
kretprobe:smp_call_function_many /*内核动态插桩，对内核函数smp_call_function_many的结束(返回)进行插桩*/
/@ts[tid]/ /*过滤器会检查内容是否为非零值(/@ts[tid]/ 等价于/@ts[tid] !=0 /)。*/
{
@time_ns[ksym(@func[tid])] = hist(nsecs - @ts[tid]);
/*ksym()分析内核地址并返回字符串形式的符号。 按下ctrl+C时停止统计，打印直方图@time_ns[ksym(@func[tid])]*/
delete(@ts[tid]); /*delete()从映射表中刪除一个键值对。*/
delete(@func[tid]);
}
kprobe:native_smp_send_reschedule
{
@ts[tid] = nsecs;
@func[tid] = reg("ip"); /*将返回值存储到指定的ip寄存器中*/
}
kretprobe:native_smp_send_reschedule
/@ts[tid]/
{
@time_ns[ksym(@func[tid])] = hist(nsecs - @ts[tid]);
delete(@ts[tid]);
delete(@func[tid]);
}
如下图不知道为什么：
直方图输出前输出@func[18153]: 18446744072560895232 ？
直方图输完后输出@ts[18153]: 44869937871669 ？
这样又引申出另一个问题，有哪些情况会打印信息？
应该是因为：当bpfrace结束时，默认会将全部映射表打印出来
大部分SMP调用是通过smp_call_function_single() 和smp_call_function_many() 两个内核态函数的kprobes来跟踪的。这些函数的第二个参数是要在其他CPU上运行的函数指针，bpftrace中的变量名是arg1,按线程ID为键保存在kretprobes里。然后由bpftrace的ksym()函数转化为函数名称。
这两个函数无法跟踪一个特殊的SMP调用一smp_send_reschedule(), 这个函数需要通过native_smp_send_reschedule()来跟踪。笔者希望在未来的内核版本中可以加入SMP调用的跟踪点，这样可以简化跟踪过程。
可以修改代码中的@time_ns直方图的键，以包含内核中的调用栈和进程名:
这样调用时间长的调用就被记录了更多的信息:
这个输出展示了snmp-pass进程(一个系统监控工具)，正在使用open()系统调用，最终调用到了cpuinfo_open()，导致执行了缓慢的跨CPU调用。
使用另外一个BPF工具，opensnoop(8)， 我们可以再次得到确认:
输出显示，snmp-paasS; 每秒读取一次/proc/cpuinfo， 这个文件中唯一 改变的是“cpuMHz”部分，另外的大部分信息都不会改变。
通过审查软件源代码，可以发现该程序读取/proc/cpuinfo只是为了统计系统中的CPU数量，根本没有使用“cpu MHz”这个值。这是一个做无用功的典型代表，解决了这个问题可以很容易提高性能。
在Intel处理器上，SMP 调用最终是以x2APIC IPI调用(跨处理器中断)实现的，包括x2apic_send_IPI()函数。这个函数也可以进行跟踪，详情参见6.4.2节。
6.3.16llcstat
Ilcstat(8)是一个BCC工具，其利用PMC来按进程输出最后一级缓存的命中率。有关PMC的介绍在第2章。
例如，在这个48-CPU的生产环境下的输出:
上面这个输出中显示，java 进程(线程)的缓存命中率非常高，超过99%。
这个工具是靠PMC的溢出采样功能工作的，当缓存命中，或者未命中时，根据采样频率，触发一个BPF程序以记录目前运行的进程，并且记录统计信息。默认阈值为100，可以用-c参数进行调整。这种1%的采样频率可以保证额外消耗相对较低(需要的话可以提高)；然而，单靠这种采样是有一些问题的。例如，一个进程有可能触发未命中计数超过了缓存查找的计数，这显然是不对的(因为从理论上来说，未命中肯定是缓存查找的一部分)。 .
命令行使用说明如下:
命令行选项包括如下项目。
- -c SAMPLE_ PERIOD:采样频率设置为N分之一 。
Ilcstat(8)的特殊之处除了它是定时采样之外，还是第一个使用PMC的BCC工具。
6.3.17其他工具
其他值得一提的BPF工具包括:
-
bpftrace 版本的cpuwalk(8)工具采样每个CPU上运行的进程名，并且以线性直方图的方式输出。这样可以统计CPU之间的负载均衡情况。
-
BCC中的cpuunclaimed(8) 工具采样CPU运行队列的长度，关注在某个CPU上有排队线程的情况下有多少其他CPU处于空闲状态。这有时候是由于进程的CPU黏合度设置导致的，但是如果这种情况出现得非常频繁，可能是由于CPU调度器的配置错误，或者是由于某种Bug导致的。
-
bpfrace中的loads(8) 工具展示了如何用BPF工具计算系统负载值。正如之前讨论过的，这些数字很有误导性。
-
vlrace是Intel开发的一个工具，是基于BPF的strace(1)替代品，可以用来分析消耗CPU时间的系统调用https://github.com/pmem/vltrace。
6.4 BPF单行程序
这一节提供了一些BCC版本和bpftrace版本的单行程序。这些程序尽可能地同时以BCC和bpftrace来实现。
6.4.1 BCC工具
跟踪新进程，包括进程参数:
execsnoop
输出哪个程序在执行哪个新的进程:
trace ‘t:syscalls:sys_enter_execve “->号s”， args->filename’
按进程统计系统调用的数量:
syscount -P
按系统调用名称来统计调用的数量:
syscount
以49Hz的频率采样进程ID为189的用户态调用栈:
profile -F 49 -U -p 189
采样所有的调用栈信息和进程信息:
profile
统计以“vfs_”开头的内核函数的调用频率:
funccount ‘vfs_ *’
跟踪通过pthread_ create( 创建的新线程:
trace /lib/x86_64-1inux-gnu/libpthread-2.27.so:pthread_create
6.4.2 bpftrace 版本
跟踪新进程，包括进程参数:
bpftrace -e ‘tracepoint:syscalls:sys_enter_execve { join (args->argv);}’
输出哪个进程执行了哪个新进程:
bpftrace -e ‘tracepoint:syscalls:sys_enter_execve { printf(“&s ->%s\n”, comm,str (args->filename));}’
按进程统计系统调用的数量:
bpftrace -e ‘tracepoint:raw_syscalls:sys_enter { @[comm] = count();}’
按进程ID统计系统调用的数量:
bpftrace -e ‘tracepoint:raw_syscalls:sys_enter { @[pid, comm] = count(); }’
按系统调用的探针名字来统计系统调用的数量:
bpftrace -e ‘tracepoint:syscalls:sys enter_* ( @[probe]. = count(); }’
按系统调用的函数名来统计系统调用的数量:
bpftrace -e 'tracepoint:raw syscalls:sys enter {@[sym(* (kaddr(“sys call table”) + args->id * 8))] = count();} ’
以99Hz的频率采样正在运行的进程名:
bpftrace -e ‘profile:hz:99 { @[comm] - count(); }’
以49Hz的频率采样进程ID为189的用户态调用栈信息:
bpftrace -e ‘profile:hz:49 /pid == 189/ { @[ustack] - count(); }’
采样所有的进程名和调用栈信息:
bptrace -e ‘profile:hz:49 { @[ustack, stack, comm] = count(); }’
按99Hz的频率采样正在运行的CPU,并且以线性直方图输出:
bpftrace -e ‘profile:hz:99 { @cpu - lhist(cpu, 0, 256, 1);}’
统计内核中以“vfs_ ”开头的函数调用频率: .
bpttrace -e ‘kprobe:vfs_ * { @Ifunc] = count(); }’
按名字和内核调用栈来统计SMP调用:
bpftrace -e 'kprobe:smp call* { @Iprobe, kstack(5)] = count();F’业也的5
按名字和内核调用栈来统计Intelx2APIC调用:.
bptrace -e 'kprobe:x2apic send IPI* ( @[probe, kstack(5)] = count(); '的面
跟踪通过pthread_ create() 创建的新线程:
bpftrace -e ‘u:/1ib/x86_64-1inux-gnu/libpthread-2.27. so:pthread_create {printf(“%s by %s (%d)\n”, probe, comm, pid); }’
6.5 可选练习
如果没有特别说明，以下练习都可以用bpftrace和BCC实现。
- 1.用execsnoop(8)来跟踪man ls命令产生的新进程。
- 2.用execsnoop(8)的-七参数来跟踪生产系统10分钟，并将结果输出到一个日志文件。找到了什么进程?
- 3.在一个测试系统上，给一个CPU进行压力测试。以下这个命令创建了两个CPU繁忙的线程，并将它们绑定在CPU0.上:
taskset -C 0 sh -C ‘while :; do :; done’ &
taskset -C 0 sh -C ‘while :; do :; done’ &
接下来用uptime(1) ( 负载平均值)、mpstat(1) (-P ALI). runqlen(8) 和runqlat(8)来分析CPU0.上的进程情况。(记得分析结束之后杀掉这些进程。) - 4.开发一个只采样CPU0的内核调用栈的工具/单行程序。
- 5.利用profile(8)抓取内核CPU调用栈信息，以分析下面这行程序的CPU使用量:
dd if=/dev/nvme0n1p3 bs=8k iflag=direct 1 dd of=/dev/null bs=1
把infile (if=)修改为本地磁盘(用df -h找一个可选项)。可以直接分析全系统的性能，或者过滤每个dd(1)进程。 - 6.给第5个练习的程序生成CPU火焰图。
- 7.利用offcputime(8)来抓取内核CPU调用栈，以分析第5个练习中哪里阻塞消耗了时间。
- 8.给第7个练习生成-一个off-CPU火焰图。
- 9.使用execsnoop(8)只能看到利用exec(2) (execve(2))创建的进程，有- - 些进程会使用fork(2)或者clone(2)，而不是exec(2) (例如，创建工作进程池)。书写一个新工具procsnoop(8)来尽可能地输出新进程的所有信息。可以跟踪fork()和clone()，或者使用sched跟踪点，或者用一些其他的方法做到。
- 10.开发一个bpfrace版本的softirqs(8)，让其可以输出软中断的名字。
- 11.用bpftrace开发- - 个cpudist(8)工具。
- 12.用cpudist(8) (任意版本)分别针对主动上下文切换和被动上下文切换输出直方图。
- 13.(高级功能，未解决的问题)开发-一个工具，输出线程等待在CPU黏合度上耗费的时间:线程处于可运行的状态，也有其他可用的CPU，但是由于缓存热度的原因没有进行迁移。(参看kermel.sched_ _migration cost. ns 和task. hot()一-这两个函数可能被内联了，无法直接跟踪一还 有can migrate task() 函数)。
5088
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
