案例篇：服务吞吐量下降很厉害，怎么分析？

程序员小王

发布于 2020-06-28 16:32:23

2.3K0

发布于 2020-06-28 16:32:23

文章被收录于专栏：架构说架构说

回顾

在 Linux 系统中，常见的动态追踪方法包括 ftrace、perf、eBPF/BCC 以及 SystemTap 等。

使用 perf 配合火焰图寻找热点函数，是一个比较通用的性能定位方法，在很多场景中都可以使用。
如果这仍满足不了你的要求，那么在新版的内核中，eBPF 和 BCC 是最灵活的动态追踪方法。

而在旧版本内核，特别是在 RHEL 系统中，由于 eBPF 支持受限，

SystemTap 和 ftrace 往往是更好的选择

画外音：

perf教程请参考 http://www.brendangregg.com/perf.html

开始

Python

# 安装必备docker、curl和perf
$ apt-get install -y docker.io curl build-essential linux-tools-common
# 安装火焰图工具
$ git clone https://github.com/brendangregg/FlameGraph
# 安装wrk
$ git clone https://github.com/wg/wrk
$ cd wrk && make && sudo cp wrk /usr/local/bin/

Shell


$ docker run --name nginx --network host --privileged -itd feisky/nginx-tp
6477c607c13b37943234755a14987ffb3a31c33a7f04f75bb1c190e710bce19e
$ docker run --name phpfpm --network host --privileged -itd feisky/php-fpm-tp
09e0255159f0c8a647e22cd68bd097bec7efc48b21e5d91618ff29b882fa7c1f

Python


$ curl http://192.168.0.30
Hello World!

测试命令


# 默认测试时间为10s，请求超时2s
$ wrk --latency -c 1000 http://192.168.0.30
Running 10s test @ http://192.168.0.30
  2 threads and 1000 connections
  Thread Stats   Avg      Stdev     Max   +/- Stdev
    Latency    14.82ms   42.47ms 874.96ms   98.43%
    Req/Sec   550.55      1.36k    5.70k    93.10%
  Latency Distribution
     50%   11.03ms
     75%   15.90ms
     90%   23.65ms
     99%  215.03ms
  1910 requests in 10.10s, 573.56KB read
  Non-2xx or 3xx responses: 1910
Requests/sec:    189.10
Transfer/sec:     56.78KB

从 wrk 的结果中，你可以看到吞吐量（也就是每秒请求数）只有 189，并且所有 1910 个请求收到的都是异常响应（非 2xx 或 3xx）。

这些数据显然表明，吞吐量太低了，并且请求处理都失败了。这是怎么回事呢？

根据 wrk 输出的统计结果，我们可以看到，总共传输的数据量只有 573 KB，那就肯定不会是带宽受限导致的。

所以，我们应该从请求数的角度来分析。

画外音：

分析请求数，特别是 HTTP 的请求数，有什么好思路吗？

当然就要从 TCP 连接数入手

连接数优化

观察tcp连接数

Shell

# 测试时间30分钟
$ wrk --latency -c 1000 -d 1800 http://192.168.0.30
$ ss -s
Total: 177 (kernel 1565)
TCP:   1193 (estab 5, closed 1178, orphaned 0, synrecv 0, timewait 1178/0), ports 0
Transport Total     IP        IPv6
*    1565      -         -
RAW    1         0         1
UDP    2         2         0
TCP    15        12        3
INET    18        14        4
FRAG    0         0         0
  -s, --summary
              Print  summary  statistics.
$ dmesg | tail
[88356.354329] nf_conntrack: nf_conntrack: table full, dropping packet
[88356.354374] nf_conntrack: nf_conntrack: table full, dropping packet

从这里看出，wrk 并发 1000 请求时，建立连接数只有 5，而 closed 和 timewait 状态的连接则有 1100 多。

其实从这儿你就可以发现两个问题：一个是建立连接数太少了；另一个是 timewait 状态连接太多了。

Plain Text

$ dmesg | tail
[88356.354329] nf_conntrack: nf_conntrack: table full, dropping packet
[88356.354374] nf_conntrack: nf_conntrack: table full, dropping packet
possible SYN flooding on port 80. Sending cookies.

解决办法: centos没有找到该命令

两个内核选项——连接跟踪数的最大限制

C++

$ sysctl net.netfilter.nf_conntrack_max
net.netfilter.nf_conntrack_max = 200
$ sysctl net.netfilter.nf_conntrack_count
net.netfilter.nf_conntrack_count = 200
# 将连接跟踪限制增大到1048576
$ sysctl -w net.netfilter.nf_conntrack_max=1048576
# 默认测试时间为10s，请求超时2s
$ wrk --latency -c 1000 http://192.168.0.30
...
  54221 requests in 10.07s, 15.16MB read
  Socket errors: connect 0, read 7, write 0, timeout 110
  Non-2xx or 3xx responses: 45577
Requests/sec:   5382.21
Transfer/sec:      1.50MB

画外音：

吞吐量已经从刚才的 189 增大到了 5382。看起来性能提升了将近 30 倍，

大部分请求的响应都是异常的。那么，该怎么分析响应异常的问题呢？

工作进程优化

主要多线程多进程参数调整。

套接字优化

分析的第一步，自然还是要观察有没有发生丢包现象。

# 测试时间30分钟
$ wrk --latency -c 1000 -d 1800 http://192.168.0.30
  这次还是要用 -d 参数延长测试时间，以便模拟性能瓶颈的现场：
# 只关注套接字统计
$ netstat -s | grep socket
    73 resets received for embryonic SYN_RECV sockets
    308582 TCP sockets finished time wait in fast timer
    8 delayed acks further delayed because of locked socket
    290566 times the listen queue of a socket overflowed
    290566 SYNs to LISTEN sockets dropped
# 稍等一会，再次运行
$ netstat -s | grep socket
    73 resets received for embryonic SYN_RECV sockets
    314722 TCP sockets finished time wait in fast timer
    8 delayed acks further delayed because of locked socket
    344440 times the listen queue of a socket overflowed
    344440 SYNs to LISTEN sockets dropped
$ ss -ltnp
State     Recv-Q     Send-Q            Local Address:Port            Peer Address:Port
LISTEN    10         10                      0.0.0.0:80                   0.0.0.0:*         users:(("nginx",pid=10491,fd=6),("nginx",pid=10490,fd=6),("nginx",pid=10487,fd=6))
LISTEN  
-t, --tcp
              Display TCP sockets.
   -l, --listening
              Display only listening sockets (these are omitted by default).

这次可以看到，Nginx 和 php-fpm 的监听队列（Send-Q）只有 10，而 nginx 的当前监听队列长度（Recv-Q）已经达到了最大值，php-fpm 也已经接近了最大值。很明显，套接字监听队列的长度太小了，需要增大。
根据两次统计结果中 socket overflowed 和 sockets dropped 的变化，你可以看到，有大量的套接字丢包，并且丢包都是套接字队列溢出导致的。所以，接下来，我们应该分析连接队列的大小是不是有异常。

如果短时间内存在大量的这种恶意连接，对服务端来说压力就会很大，这就是所谓的 SYN FLOOD 攻击。

http://jaseywang.me/2014/07/20/tcp-queue-%E7%9A%84%E4%B8%80%E4%BA%9B%E9%97%AE%E9%A2%98/

https://blog.csdn.net/plokmju88/article/details/103884145

补充Recv-Q/Send-Q 理解

Plain Text

可以看到，整个 TCP stack 有如下的两个 queue:
1. 一个是 half open(syn queue) queue(max(tcp_max_syn_backlog, 64))，用来保存 SYN_SENT 以及 SYN_RECV 的信息。
2. 另外一个是 accept queue(min(somaxconn, backlog))，保存 ESTAB 的状态，但是调用 accept()。
注意，之前我对 Recv-Q/Send-Q 的理解有些误差，
使用 ss 获取到的 Recv-Q/Send-Q 在 LISTEN 状态以及非 LISTEN 状态所表达的含义是不同的。
从 tcp_diag.c 源码中可以看到二者的区别:
LISTEN 状态: Recv-Q 表示的当前等待服务端调用 accept 完成三次握手的 listen backlog 数值
也就是说，当客户端通过 connect() 去连接正在 listen() 的服务端时，
这些连接会一直处于这个 queue 里面直到被服务端 accept()；Send-Q 表示的则是最大的 listen backlog 数值，这就就是上面提到的 min(backlog, somaxconn) 的值。
其余状态:
非 LISTEN 状态之前理解的没有问题。Recv-Q 表示 receive queue 中的 bytes 数量；
Send-Q 表示 send queue 中的 bytes 数值
通过 "SYNs to LISTEN sockets dropped" 以及 "times the listen queue of a socket overflowed" 这两个 netstat -s 获取到的 TCP 状态，可以很快的发现系统存在的一些问题。
任何一个包含 "dropped" 或者 "overflowed" 并且数值一直居高不下的 metric 从字面含义理解来看，都不是一个好现象。
对于 Nginx 来说，backlog 的默认值为 511，这个可以通过 ss/netstat 的 Send-Q 确认:
State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      511                       *:80                       *:*
可以通过适当的增大 nginx 的 backlog 以及 somaxconn 来增大队列:
listen 80 backlog=1638

解决办法：

从输出中可以看到，Nginx 和 somaxconn 的配置都是 10，而 php-fpm 的配置也只有 511，显然都太小了。

那么，优化方法就是增大这三个配置，比如，可以把 Nginx 和 php-fpm 的队列长度增大到 8192，而把 somaxconn 增大到 65536。

Shell

# 查询nginx监听队列长度配置
$ docker exec nginx cat /etc/nginx/nginx.conf | grep backlog
        listen       80  backlog=10;
# 查询php-fpm监听队列长度
$ docker exec phpfpm cat /opt/bitnami/php/etc/php-fpm.d/www.conf | grep backlog
; Set listen(2) backlog.
;listen.backlog = 511
# somaxconn是系统级套接字监听队列上限
$ sysctl net.core.somaxconn
net.core.somaxconn = 10

补充：somaxconn

cat /proc/sys/net/core/somaxconn

128

Specifies the maximum listen backlog.

socket tcp的backlog的上限是min(backlog,somaxconn)，

其中backlog是应用程序中传递给listen系统调用的参数值，somaxconn是内核规定的最大连接数。

accept() call is used by a server to accept a connection request from a client.

端口号优化

问题：

可以看到，Nginx 报出了无法连接 fastcgi 的错误，错误消息是 Connect 时， Cannot assign requested address。

这个错误消息对应的错误代码为 EADDRNOTAVAIL，表示 IP 地址或者端口号不可用。

解决办法：

当客户端连接服务器端时，需要分配一个临时端口号，而 Nginx 正是 PHP-FPM 的客户端。

端口号的范围并不是无限的，最多也只有 6 万多

$ sysctl net.ipv4.ip_local_port_range
net.ipv4.ip_local_port_range=20000 20050
$
sysctl -w net.ipv4.ip_local_port_range="10000 65535"
net.ipv4.ip_local_port_range = 10000 65535

火焰图

问题：

Shell

$ top
...
%Cpu0  : 30.7 us, 48.7 sy,  0.0 ni,  2.3 id,  0.0 wa,  0.0 hi, 18.3 si,  0.0 st
%Cpu1  : 28.2 us, 46.5 sy,  0.0 ni,  2.0 id,  0.0 wa,  0.0 hi, 23.3 si,  0.0 st
KiB Mem :  8167020 total,  5867788 free,   490400 used,  1808832 buff/cache
KiB Swap:        0 total,        0 free,        0 used.  7361172 avail Mem
  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
20379 systemd+  20   0   38068   8692   2392 R  36.1  0.1   0:28.86 nginx
20381 systemd+  20   0   38024   8700   2392 S  33.8  0.1   0:29.29 nginx
 1558 root      20   0 1118172  85868  39044 S  32.8  1.1  22:55.79 dockerd
20313 root      20   0   11024   5968   3956 S  27.2  0.1   0:22.78 docker-containe
13730 root      20   0       0      0      0 I   4.0  0.0   0:10.07 kworker/u4:0-ev

从 top 的结果中可以看到，可用内存还是很充足的，但系统 CPU 使用率（sy）比较高，两个 CPU 的系统 CPU 使用率都接近 50%，且空闲 CPU 使用率只有 2%。

再看进程部分，CPU 主要被两个 Nginx 进程和两个 docker 相关的进程占用，使用率都是 30% 左右。

解决

# 执行perf记录事件3
$ perf record -g
# 切换到FlameGraph安装路径执行下面的命令生成火焰图
$ perf script -i ~/perf.data | ./stackcollapse-perf.pl --all | ./flamegraph.pl > nginx.svg

这儿中间的 dosyscall64、tcpv4connect、inethashconnect 这个堆栈，很明显就是最需要关注的地方。inethashconnect() 是 Linux 内核中负责分配临时端口号的函数。

所以，这个瓶颈应该还在临时端口的分配上。在上一步的“端口号”优化中，临时端口号的范围，已经优化成了 “10000 65535”。这显然是一个非常大的范围，那么，端口号的分配为什么又成了瓶颈呢？

一时想不到也没关系，我们可以暂且放下，先看看其他因素的影响。再顺着 inethashconnect 往堆栈上面查看，下一个热点是 _initcheck_established 函数。而这个函数的目的，是检查端口号是否可用。结合这一点，你应该可以想到，如果有大量连接占用着端口，

下一个热点是 _initcheck_established 函数。

而这个函数的目的，是检查端口号是否可用。

结合这一点，你应该可以想到，如果有大量连接占用着端口，那么检查端口号可用的函数，不就会消耗更多的 CPU 吗？

Shell

$ ss -s
TCP:   32775 (estab 1, closed 32768, orphaned 0, synrecv 0, timewait 32768/0), ports 0
...
$ sysctl net.ipv4.tcp_tw_reuse
net.ipv4.tcp_tw_reuse = 0