原文:Linux Performance Analysis in 60,000 Milliseconds

当你登陆到一台性能出现问题的 Linux 服务器:你在第一分钟会检查什么?

在 Netflix,我们拥有一个庞大的 EC2 Linux 云和大量的性能分析工具,用于监控和调查其性能。其中包括 Atlas 用于云范围的监控和 Vector 用于按需实例分析。虽然这些工具帮助我们解决了大多数问题,但有时我们需要登录到一台实例并运行一些标准的 Linux 性能工具。

60秒摘要

这篇文章将介绍 Netflix 性能工程团队在命令行下使用标准 Linux 工具进行优化性能调查的前60秒,你也可以使用这些工具。在60秒内,你可以通过运行以下十个命令了解系统资源使用情况和正在运行的进程。查找错误和饱和度指标,然后查看资源利用率。饱和是指资源的负载超过其处理能力,可表现为请求队列的长度或等待时间。

uptime
dmesg | tail
vmstat 1
mpstat -P ALL 1
pidstat 1
iostat -xz 1
free -m
sar -n DEV 1
sar -n TCP,ETCP 1
top

其中一些命令需要安装 sysstat 软件包。这些命令输出的指标将有助于完成一些性能瓶颈的定位(USE 方法)。这涉及检查所有资源(CPU,内存,磁盘等)的利用率、饱和度和错误指标。还要注意何时检查和排除了资源,因为通过排除,可以缩小要研究的目标,并指导任何后续的分析。

以下部分总结了这些命令,在生产系统中给出了示例。有关这些工具的更多信息,请参阅它们的 man 页面。

1. uptime

$ uptime
23:51:26 up 21:31, 1 user, load average: 30.02, 26.43, 19.02

uptime 是快速查看平均负载的方法,平均负载指示要运行的任务(进程)的数量。Linux 系统中,包含了想要在 CPU 上运行的进程,同时也包含了阻塞在不可中断的进程 I/O 上的进程(通常是磁盘 I/O)。这给出了一个高层次视角的资源负载,在此之后可以使用其他工具进行进一步检查。

这3个数字是指数衰减移动和平均值,具有 1 分钟、5 分钟和 15 分钟常数。这三个数字可以让我们了解系统负载随时间的变化情况。如果在检查问题服务器时,1分钟的负载平均值远低于15分钟的负载平均值,那么可能是我们登录得太晚了,错过了实际问题。

在上面的示例中,负载平均值显示最近有所增加,1分钟值达到30,而15分钟值仅为19。这些数字如此之大意味着有很多东西占用了系统资源,很可能是 CPU 需求过高。可以通过运行命令3和命令4中的 vmstatmpstat 来确认 CPU 是否处于高负载状态。这两个命令将提供更多关于 CPU 使用情况的详细信息。

2. dmesg | tail

$ dmesg | tail
[1880957.563150] perl invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0
[...]
[1880957.563400] Out of memory: Kill process 18694 (perl) score 246 or sacrifice child
[1880957.563408] Killed process 18694 (perl) total-vm:1972392kB, anon-rss:1953348kB, file-rss:0kB
[2320864.954447] TCP: Possible SYN flooding on port 7001. Dropping request.  Check SNMP counters.

该命令可以查看系统的最后10条日志,如果有的话,需要查找可能导致性能问题的错误信息。上面的示例包括 oom-killer 和 TCP 丢弃请求的记录。

千万不要忽略这个步骤!始终值得检查 dmesg 命令的输出。

3. vmstat 1

$ vmstat 1
procs ---------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
34  0    0 200889792  73708 591828    0    0     0     5    6   10 96  1  3  0  0
32  0    0 200889920  73708 591860    0    0     0   592 13284 4282 98  1  1  0  0
32  0    0 200890112  73708 591860    0    0     0     0 9501 2154 99  1  0  0  0
32  0    0 200889568  73712 591856    0    0     0    48 11900 2459 99  0  0  0  0
32  0    0 200890208  73712 591860    0    0     0     0 15898 4840 98  1  1  0  0
^C

vmstat(8) 是 virtual memory stat 的缩写,是一种常用的工具(几十年前首次为 BSD 创建),该工具会在每一行打印服务器关键统计信息摘要。

在本示例中,vmstat 命令带有参数1,表示输出每一秒的统计数据摘要。vmstat 的第一行输出的一些列显示的是自开机以来的平均值,而非前1秒的值。暂时跳过第一行,除非您想了解并记住哪一列是哪一列。

检查如下的一些列:

  • r:CPU 上正在运行和等待轮换的进程数量。相比于平均负载来说,其更能确定 CPU 饱和的情况,因为它不包括 I/O。可以这样解释:如果 r 值大于 CPU 数量,则表示 CPU 处于饱和状态。
  • free:空闲内存,单位为 KB。如果位数太多,一眼数不过来,那么说明有足够的可用内存。free -m命令(作为第 7 个命令包含在内)会更好地解释了可用内存的状态。
  • siso:换入和换出。如果这些不为零,则说明内存不足。
  • us, sy, id, wa, st: 这些是 CPU 时间的细分,是对所有 CPU 取平均之后的结果。它们是用户时间、系统时间(内核)、空闲、等待 I/O 和被其他客户机窃取的时间(虚拟化环境下,被其他客户机挤占的时间;或使用 Xen 时,客户机自己隔离的驱动程序域运行时间 )。

CPU 时间的分解通过将用户时间+系统时间相加确认 CPU 是否忙碌。持续的等待 I/O 表明存在磁盘瓶颈;这就是 CPU 处于空闲状态的原因,因为任务被阻塞等待挂起的磁盘 I/O。你可以将等待 I/O 视为另一种 CPU 空闲的形式,可以从中得出它们为什么处于空闲状态的线索。

系统时间对于 I/O 处理是必要的。如果系统时间平均值较高,超过 20%,可能需要进一步探索:也许内核正在低效地处理 I/O。

在上述示例中,CPU 时间几乎完全在用户级别,指向应用程序级别的使用。CPU的利用率平均超过90%。这不一定是问题,使用 r 列检查饱和度的程度。

4. mpstat -P ALL 1

$ mpstat -P ALL 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015  _x86_64_ (32 CPU)

07:38:49 PM  CPU   %usr  %nice   %sys %iowait   %irq  %soft  %steal  %guest  %gnice  %idle
07:38:50 PM  all  98.47   0.00   0.75    0.00   0.00   0.00    0.00    0.00    0.00   0.78
07:38:50 PM    0  96.04   0.00   2.97    0.00   0.00   0.00    0.00    0.00    0.00   0.99
07:38:50 PM    1  97.00   0.00   1.00    0.00   0.00   0.00    0.00    0.00    0.00   2.00
07:38:50 PM    2  98.00   0.00   1.00    0.00   0.00   0.00    0.00    0.00    0.00   1.00
07:38:50 PM    3  96.97   0.00   0.00    0.00   0.00   0.00    0.00    0.00    0.00   3.03
[...]

此命令打印每个 CPU 的 CPU 时间细分,可用于检查不平衡。单个热 CPU 可能是单线程遇到瓶颈的特征。

补充:对于较高的 %iowait 时间也要注意,可以使用磁盘 I/O 工具进一步分析;较高的 %sys 可以使用系统调用跟踪和内核跟踪,以及 CPU 剖析等手段进一步分析。

5. pidstat 1

$ pidstat 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015    _x86_64_    (32 CPU)

07:41:02 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
07:41:03 PM     0         9    0.00    0.94    0.00    0.94     1  rcuos/0
07:41:03 PM     0      4214    5.66    5.66    0.00   11.32    15  mesos-slave
07:41:03 PM     0      4354    0.94    0.94    0.00    1.89     8  java
07:41:03 PM     0      6521 1596.23    1.89    0.00 1598.11    27  java
07:41:03 PM     0      6564 1571.70    7.55    0.00 1579.25    28  java
07:41:03 PM 60004     60154    0.94    4.72    0.00    5.66     9  pidstat

07:41:03 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
07:41:04 PM     0      4214    6.00    2.00    0.00    8.00    15  mesos-slave
07:41:04 PM     0      6521 1590.00    1.00    0.00 1591.00    27  java
07:41:04 PM     0      6564 1573.00   10.00    0.00 1583.00    28  java
07:41:04 PM   108      6718    1.00    0.00    0.00    1.00     0  snmp-pass
07:41:04 PM 60004     60154    1.00    4.00    0.00    5.00     9  pidstat
^C

pidstat有点像 top的进程汇总,但是以滚动的方式打印。这对于随时间观察模式以及记录调查中看到的内容(复制粘贴)非常有用。

上面的例子确定了两个 Java 进程负责消耗 CPU。%CPU 列是所有 CPU 的总和;1591%表示 Java 进程消耗了近16个 CPU。

6. iostat -xz 1

$ iostat -xz 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015  _x86_64_ (32 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          73.96    0.00    3.73    0.03    0.06   22.21

Device:   rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
xvda        0.00     0.23    0.21    0.18     4.52     2.08    34.37     0.00    9.98   13.80    5.42   2.44   0.09
xvdb        0.01     0.00    1.02    8.94   127.97   598.53   145.79     0.00    0.43    1.78    0.28   0.25   0.25
xvdc        0.01     0.00    1.02    8.86   127.79   595.94   146.50     0.00    0.45    1.82    0.30   0.27   0.26
dm-0        0.00     0.00    0.69    2.32    10.47    31.69    28.01     0.01    3.23    0.71    3.98   0.13   0.04
dm-1        0.00     0.00    0.00    0.94     0.01     3.78     8.00     0.33  345.84    0.04  346.81   0.01   0.00
dm-2        0.00     0.00    0.09    0.07     1.35     0.36    22.50     0.00    2.55    0.23    5.62   1.78   0.03
[...]
^C

这是了解块设备(磁盘)、应用的工作负载和产生的性能的一个很好的工具。

检查如下一些列:

  • r/sw/srkB/swkB/s:这些是每秒向设备传递的读取次数,写入次数,读取 KB 数和写入 KB 数。使用它们可以对业务负载画像。性能问题可能仅仅是由于过度负载造成的。
  • await: I/O 的平均响应时间(以毫秒为单位)。这是应用需要承受的时间,因为它包括等待时间和服务时间。超过预期的平均时间可能是设备饱和或设备问题的信号。
  • avgqu-sz:发往设备的平均请求数。大于1的值可能是饱和的证据(尽管设备通常可以并行处理请求,尤其是面向多个后端磁盘的虚拟设备)。
  • %util:设备利用率。这是设备繁忙程度百分比,显示每秒设备正在执行工作的时间。尽管这取决于设备,但是大于 60% 的值通常导致性能差(这应该能在 await 中看到)。接近 100% 的值通常表示饱和。

如果存储设备是连接多个后端磁盘的逻辑磁盘设备,那么100%的利用率可能只意味着某些 I/O 正在100%的时间内进行处理,但是后端磁盘可能远未饱和,并且可能能够处理更多的工作。

请注意,性能不佳的磁盘 I/O 不一定是应用程序问题。通常使用许多技术来异步执行 I/O,以便应用程序不会直接阻塞和遭受延迟(例如,读取预取和写入缓冲)。

7. free -m

$ free -m
              total        used        free      shared  buff/cache   available
Mem:         128808       50061       75407         440        3340       77787
Swap:        130946        1589      129357

这个命令显示了以 MB 为单位的可用内存。检查可用内存 available 是否接近0;该值显示了系统中还有多少实际内存可用,包括缓冲区和页缓冲区。将一些内存用于缓存可提升文件系统的性能。

8. sar -n DEV 1

$ sar -n DEV 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015     _x86_64_    (32 CPU)

12:16:48 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
12:16:49 AM      eth0  18763.00   5032.00  20686.42    478.30      0.00      0.00      0.00      0.00
12:16:49 AM        lo     14.00     14.00      1.36      1.36      0.00      0.00      0.00      0.00
12:16:49 AM   docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00

12:16:49 AM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
12:16:50 AM      eth0  19763.00   5101.00  21999.10    482.56      0.00      0.00      0.00      0.00
12:16:50 AM        lo     20.00     20.00      3.25      3.25      0.00      0.00      0.00      0.00
12:16:50 AM   docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
^C

使用此工具检查网络接口吞吐量:rxkB/s 和 txkB/s,作为工作负载的度量,以及检查是否已达到任何上限。在上面的示例中,eth0 接收达到 22 Mbytes/s,即176 Mbits/s(远低于1 Gbit/s的上限)。

此版本还具有 %ifutil 的设备利用率(全双工的两个方向的最大值),这也是我们使用 Brendan 的 nicstat 工具来测量的东西。与 nicstat 一样,这很难正确实现,并且在此示例中似乎无法正常工作(为0.00)。

9. sar -n TCP,ETCP 1

$ sar -n TCP,ETCP 1
Linux 3.13.0-49-generic (titanclusters-xxxxx)  07/14/2015    _x86_64_    (32 CPU)

12:17:19 AM  active/s passive/s    iseg/s    oseg/s
12:17:20 AM      1.00      0.00  10233.00  18846.00

12:17:19 AM  atmptf/s  estres/s retrans/s isegerr/s   orsts/s
12:17:20 AM      0.00      0.00      0.00      0.00      0.00

12:17:20 AM  active/s passive/s    iseg/s    oseg/s
12:17:21 AM      1.00      0.00   8359.00   6039.00

12:17:20 AM  atmptf/s  estres/s retrans/s isegerr/s   orsts/s
12:17:21 AM      0.00      0.00      0.00      0.00      0.00
^C

这是一些关键TCP指标的概要。

关键指标如下:

  • active/s:每秒钟本地启动的 TCP 连接数(例如通过connect())。
  • passive/s:每秒钟远程启动的 TCP 连接数(例如通过accept())。
  • retrans/s:每秒钟 TCP 重传的次数。

Active 和 passive 计数通常作为服务器负载的大致测量很有用:新接受连接的数量(passive),和下游连接的数量(active)。想象 active 为出站,passive为入站可能有所帮助,但这并不严格正确(例如,本地主机到本地主机的连接)。

重传是网络或服务器问题的标志;这可能是由于不可靠的网络(例如公共互联网),或者是由于服务器过载而丢失数据包。上面的示例仅显示每秒一个新的TCP连接。

10.top

$ top
top - 00:15:40 up 21:56,  1 user,  load average: 31.09, 29.87, 29.92
Tasks: 871 total,   1 running, 868 sleeping,   0 stopped,   2 zombie
%Cpu(s): 96.8 us,  0.4 sy,  0.0 ni,  2.7 id,  0.1 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem:  25190241+total, 24921688 used, 22698073+free,    60448 buffers
KiB Swap:        0 total,        0 used,        0 free.   554208 cached Mem

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 20248 root      20   0  0.227t 0.012t  18748 S  3090  5.2  29812:58 java
  4213 root      20   0 2722544  64640  44232 S  23.5  0.0 233:35.37 mesos-slave
 66128 titancl+  20   0   24344   2332   1172 R   1.0  0.0   0:00.07 top
  5235 root      20   0 38.227g 547004  49996 S   0.7  0.2   2:02.74 java
  4299 root      20   0 20.015g 2.682g  16836 S   0.3  1.1  33:14.42 java
     1 root      20   0   33620   2920   1496 S   0.0  0.0   0:03.82 init
     2 root      20   0       0      0      0 S   0.0  0.0   0:00.02 kthreadd
     3 root      20   0       0      0      0 S   0.0  0.0   0:05.35 ksoftirqd/0
     5 root       0 -20       0      0      0 S   0.0  0.0   0:00.00 kworker/0:0H
     6 root      20   0       0      0      0 S   0.0  0.0   0:06.94 kworker/u256:0
     8 root      20   0       0      0      0 S   0.0  0.0   2:38.05 rcu_sched

top 命令包括了我们之前检查的许多指标。运行它可以很方便地查看是否有任何与之前不同的异常指标,这可能表明负载是变化的。

top 的缺点是难以看到随时间变化的模式,这可能在 vmstatpidstat 等提供滚动输出的工具中更加清晰。如果没有及时暂停输出并清屏(Ctrl-S 暂停,Ctrl-Q 继续),那么间歇性问题的证据也可能会丢失。

推荐阅读

[1] Linux Performance Analysis in 60,000 Milliseconds. https://netflixtechblog.com/linux-performance-analysis-in-60-000-milliseconds-accc10403c55.

[2] Linux Performance Tools tutorial. https://netflixtechblog.com/netflix-at-velocity-2015-linux-performance-tools-51964ddb81cf.