案例篇:服务吞吐量下降很厉害,怎么分析?

用户头像
王传义
关注
发布于: 2020 年 06 月 23 日
案例篇:服务吞吐量下降很厉害,怎么分析?

回顾





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

  • 使用 perf 配合火焰图寻找热点函数,是一个比较通用的性能定位方法,在很多场景中都可以使用。

  • 如果这仍满足不了你的要求,那么在新版的内核中,eBPF 和 BCC 是最灵活的动态追踪方法。

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

SystemTap 和 ftrace 往往是更好的选择



画外音:

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



开始





# 安装必备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/



$ 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



$ 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连接数

# 测试时间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 状态连接太多了。




$ 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没有找到该命令

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

$ 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).



  1. 这次可以看到,Nginx 和 php-fpm 的监听队列 (Send-Q)只有 10,而 nginx 的当前监听队列长度 (Recv-Q)已经达到了最大值,php-fpm 也已经接近了最大值。很明显,套接字监听队列的长度太小了,需要增大。

  2. 根据两次统计结果中 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 理解



可以看到,整个 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。



# 查询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

火焰图



  • 问题:

$ 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记录事件
$ 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 吗?

$ 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



你可以看到,tcp_tw_reuse 是 0,也就是禁止状态。

其实看到这里,

我们就能理解,为什么临时端口号的分配会是系统运行的热点了。

当然,优化方法也很容易,把它设置成 1 就可以开启了。





用户头像

王传义

关注

希望每一位来访的朋友都能有所收获! 2017.11.30 加入

如果有疑问 wang_cyi@163.com 联系

评论

发布
暂无评论
案例篇:服务吞吐量下降很厉害,怎么分析?