linux性能优化服务吞吐量下降分析
Posted sysu_lluozh
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了linux性能优化服务吞吐量下降分析相关的知识，希望对你有一定的参考价值。
针对这种吞吐量下降问题，应该如何进行分析呢？
接下来，以最常用的反向代理服务器nginx为例，看看如何分析服务吞吐量下降的问题
一、案例准备
预先安装docker、curl、wrk、perf、FlameGraph等工具，比如：
# 安装必备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/
要分析的案例是一个Nginx + php应用，它们的关系如下图所示：
其中，wrk和curl是Nginx的客户端，而PHP应用则是一个简单的Hello World：
<?php
echo "Hello World!"
?>
为了方便运行，把案例应用打包成了两个Docker 镜像并推送到 Docker Hub 中，可以直接按照下面的步骤来运行
$ 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
同时，为了分析方便，这两个容器都将运行在host network模式中，这样就不用切换到容器的网络命名空间，而可以直接观察它们的套接字状态
执行docker ps命令查询容器的状态：
$ docker ps
CONTAINER ID IMAGE COMMAND CREATED STATUS
09e0255159f0 feisky/php‑fpm‑tp "php‑fpm ‑F ‑‑pid /o…" 28 seconds ago Up 27 seconds
6477c607c13b feisky/nginx‑tp "/init.sh" 29 seconds ago Up 28 seconds
从docker ps的输出只能知道容器处于运行状态，至于Nginx能不能正常处理外部的请求需要进一步确认
切换到终端二中，执行curl命令进一步验证Nginx能否正常访问
$ curl http://192.168.0.30
Hello World!
提示：如果看到不一样的结果，可以再次执行docker ps -a确认容器的状态，并执行docker logs <容器名> 来查看容器日志，从而找出原因
接下来，测试一下案例中Nginx的吞吐量
在终端二中，执行wrk命令测试Nginx的性能：
# 默认测试时间为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输出的统计结果，可以看到总共传输的数据量只有573KB，那就肯定不会是带宽受限导致
所以，应该从请求数的角度来分析。分析请求数特别是HTTP的请求数，有什么好思路吗？当然就要从TCP连接数入手
二、连接数优化
要查看TCP连接数的汇总情况，首选工具ss命令
2.1 启动服务
为了观察wrk测试时发生的问题，在终端二中再次启动wrk，并且把总的测试时间延长到30分钟：
# 测试时间30分钟
$ wrk ‑‑latency ‑c 1000 ‑d 1800 http://192.168.0.30
2.2 TCP连接数
然后，回到终端一中观察TCP连接数：
$ 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
从这里看出，wrk并发1000请求时，建立连接数只有5，而closed和timewait状态的连接则有1100+
其实从这儿可以发现两个问题：
- 建立连接数太少
- timewait 状态连接太
分析问题自然要先从相对简单的下手，先来看第二个关于timewait的问题
内核中的连接跟踪模块，有可能会导致timewait问题。今天的案例基于Docker运行，而Docker使用的iptables就会使用连接跟踪模块来管理NAT
那么，怎么确认是不是连接跟踪导致的问题呢？
2.3 dmesg查看系统日志
其实，最简单的方法就是通过dmesg查看系统日志，如果有连接跟踪出了问题，应该会看到 nf_conntrack相关的日志
继续在终端一中，运行下面的命令查看系统日志：
$ dmesg | tail
[88356.354329] nf_conntrack: nf_conntrack: table full, dropping packet
[88356.354374] nf_conntrack: nf_conntrack: table full, dropping packet
从日志中，可以看到nf_conntrack: table full, dropping packet的错误日志，这说明正是连接跟踪导致的问题
2.4 连接跟踪数
这种情况下，需要关注两个内核选项——连接跟踪数的最大限制nf_conntrack_max，以及当前的连接跟踪数nf_conntrack_count
执行下面的命令，可以查询这两个选项：
$ sysctl net.netfilter.nf_conntrack_max
net.netfilter.nf_conntrack_max = 200
$ sysctl net.netfilter.nf_conntrack_count
net.netfilter.nf_conntrack_count = 200
这次的输出中，可以看到最大的连接跟踪限制只有200，并且全部被占用了
200的限制显然太小，不过相应的优化也很简单，调大就可以了。执行下面的命令将nf_conntrack_max增大：
# 将连接跟踪限制增大到1048576
$ sysctl ‑w net.netfilter.nf_conntrack_max=1048576
2.5 测试优化后的性能
连接跟踪限制增大后，对Nginx吞吐量的优化效果如何呢？不妨再来测试一下。切换到终端二中，重新测试Nginx的性能：
# 默认测试时间为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
从wrk的输出中可以看到，连接跟踪的优化效果非常好，吞吐量已经从刚才的189增大到5382，性能提升将近30倍。不过，这是不是就能说明已经把Nginx的性能优化好了呢？
再来看看wrk汇报的其他数据。10s内的总请求数虽然增大到5万，但是有4万多响应异常，真正成功的只有8000多个(54221-45577=8644)
很明显，大部分请求的响应都是异常的。那么，该怎么分析响应异常的问题呢？
三、工作进程优化
由于这些响应并非Socket error，说明Nginx已经收到了请求，只不过响应的状态码并不是期望的2xx(表示成功)或3xx(表示重定向)。所以，这种情况下搞清楚Nginx真正的响应非常重要
3.1 查询Nginx容器日志
不过这也不难，切换回终端一执行下面的docker命令，查询Nginx容器日志：
$ docker logs nginx ‑‑tail 3
192.168.0.2 ‑ ‑ [15/Mar/2019:2243:27 +0000] "GET / HTTP/1.1" 499 0 "‑" "‑" "‑"
192.168.0.2 ‑ ‑ [15/Mar/2019:22:43:27 +0000] "GET / HTTP/1.1" 499 0 "‑" "‑" "‑"
192.168.0.2 ‑ ‑ [15/Mar/2019:22:43:27 +0000] "GET / HTTP/1.1" 499 0 "‑" "‑" "‑"
从Nginx的日志中，可以看到响应状态码为499
3.2 响应状态码分析
499并非标准的HTTP状态码，而是由Nginx扩展而来，表示服务器端还没来得及响应时客户端就已经关闭连接了
换句话说，问题在于服务器端处理太慢，客户端因为超时(wrk超时时间为2s)主动断开了连接
既然问题出在了服务器端处理慢，而案例本身是Nginx+PHP的应用，那是不是可以猜测是因为PHP处理过慢呢？
3.3 查看PHP容器日志
在终端中，执行下面的docker命令查询PHP容器日志：
$ docker logs phpfpm ‑‑tail 5
[15‑Mar‑2019 22:28:56] WARNING: [pool www] server reached max_children setting (5), consider raising
[15‑Mar‑2019 22:43:17] WARNING: [pool www] server reached max_children setting (5), consider raising
从这个日志中，可以看到两条警告信息：server reached max_children setting (5)，并建议增大 max_children
3.4 修改php-fpm子进程的最大数量
max_children表示php-fpm子进程的最大数量，当然是数值越大，可以同时处理的请求数就越多。不过由于这是进程问题，数量增大也会导致更多的内存和CPU占用。所以不能设置得过大
一般来说，每个php-fpm子进程可能会占用20 MB左右的内存。所以，根据内存和CPU个数估算一个合理的值。这儿把它设置成了20并将优化后的配置重新打包成了Docker 镜像
执行下面的命令：
# 停止旧的容器
$ docker rm ‑f nginx phpfpm
# 使用新镜像启动Nginx和PHP
$ docker run ‑‑name nginx ‑‑network host ‑‑privileged ‑itd feisky/nginx‑tp:1
$ docker run ‑‑name phpfpm ‑‑network host ‑‑privileged ‑itd feisky/php‑fpm‑tp:1
3.5 测试优化后的性能
切换到终端二，再次执行下面的wrk命令重新测试Nginx的性能：
# 默认测试时间为10s，请求超时2s
$ wrk ‑‑latency ‑c 1000 http://192.168.0.30
...
47210 requests in 10.08s, 12.51MB read
Socket errors: connect 0, read 4, write 0, timeout 91
Non‑2xx or 3xx responses: 31692
Requests/sec: 4683.82
Transfer/sec: 1.24MB
从wrk的输出中可以看到，虽然吞吐量只有4683，但测试期间成功的请求数却多了不少，从原来的8000增长到了15000(47210- 31692=15518)
不过，虽然性能有所提升，但4000多的吞吐量显然还是比较差的，并且大部分请求的响应依然还是异常
接下来，该怎么去进一步提升Nginx的吞吐量呢？
四、套接字优化
根据网络性能的分析套路以及Linux协议栈的原理，可以从从套接字、TCP协议等逐层分析
4.1 netstat是否有丢包现象
分析的第一步，自然是要观察有没有发生丢包现象
切换到终端二中重新运行测试：
# 用-d参数延长测试时间，以便模拟性能瓶颈的现场
# 测试时间30分钟
$ wrk ‑‑latency ‑c 1000 ‑d 1800 http://192.168.0.30
然后回到终端一中，观察有没有发生套接字的丢包现象：
# 只关注套接字统计
$ 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
根据两次统计结果中socket overflowed和sockets dropped的变化，可以看到有大量的套接字丢包，并且丢包都是套接字队列溢出导致的。所以，接下来分析连接队列的大小是不是有异常
4.2 ss查看套接字队列大小
执行下面的命令查看套接字的队列大小：
$ 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
LISTEN 7 10 *:9000 *:* users
可以看到Nginx和php-fpm的监听队列(Send-Q)只有10，而nginx的当前监听队列长度(Recv-Q)已经达到了最大值，php-fpm也已经接近了最大值。很明显，套接字监听队列的长度太小了，需要增大
4.3 调整套接字监听队列长度
关于套接字监听队列长度的设置，既可以在应用程序中通过套接字接口调整，也支持通过内核选项来配置
继续在终端一中执行下面的命令：
# 查询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
从输出中可以看到，Nginx和somaxconn的配置都是10，而php-fpm的配置也只有511，显然都太小了。优化方法就是增大这三个配置，比如可以把Nginx和php-fpm的队列长度增大到8192，而把somaxconn增大到65536
同样地，把这些优化后的Nginx重新打包成了两个Docker镜像，执行下面的命令运行：
# 停止旧的容器
$ docker rm ‑f nginx phpfpm
# 使用新镜像启动Nginx和PHP
$ docker run ‑‑name nginx ‑‑network host ‑‑privileged ‑itd feisky/nginx‑tp:2
$ docker run ‑‑name phpfpm ‑‑network host ‑‑privileged ‑itd feisky/php‑fpm‑tp:2
4.4 测试优化后的性能
然后，切换到终端二中重新测试Nginx的性能：
$ wrk ‑‑latency ‑c 1000 http://192.168.0.30
...
62247 requests in 10.06s, 18.25MB read
Non‑2xx or 3xx responses: 62247
Requests/sec: 6185.65
Transfer/sec: 1.81MB
4.5 netstat是否有丢包现象
现在的吞吐量已经增大到了6185，并且在测试的时候如果在终端一中重新执行netstat -s | grep socket，还会发现已经没有套接字丢包问题
4.6 查看Nginx日志
不过，这次Nginx 的响应再一次全部失败了，都是Non-2xx or 3xx
这是怎么回事呢？ 再去终端一中查看Nginx日志：
$ docker logs nginx ‑‑tail 10
2019/03/15 16:52:39 [crit] 15#15: *999779 connect() to 127.0.0.1:9000 failed (99: Cannot assign requested addres)
可以看到，Nginx报出了无法连接fastcgi的错误，错误消息是Connect时，Cannot assign requested address
这个错误消息对应的错误代码为EADDRNOTAVAIL，表示IP地址或者端口号不可用
在这里，显然只能是端口号的问题。接下来分析端口号的情况
五、端口号优化
根据网络套接字的原理，当客户端连接服务器端时需要分配一个临时端口号，而Nginx正是PHP-FPM的客户端。端口号的范围并不是无限的，最多也只有6万多
5.1 sysctl查询临时端口号范围
执行下面的命令查询系统配置的临时端口号范围：
$ sysctl net.ipv4.ip_local_port_range
net.ipv4.ip_local_port_range=20000 20050
可以看到临时端口的范围只有50个，显然太小了
5.2 增大临时端口号范围
优化方法很容易想到，增大这个范围即可。比如可以执行下面的命令把端口号范围扩展为"10000 65535"：
$ sysctl ‑w net.ipv4.ip_local_port_range="10000 65535"
net.ipv4.ip_local_port_range = 10000 65535
5.3 测试优化后的性能
优化完成后，再次切换到终端二中测试性能：
$ wrk ‑‑latency ‑c 1000 http://192.168.0.30/
...
32308 requests in 10.07s, 6.71MB read
Socket errors: connect 0, read 2027, write 0, timeout 433
Non‑2xx or 3xx responses: 30
Requests/sec: 3208.58
Transfer/sec: 682.15KB
这次，异常的响应少多了，不过吞吐量也下降到了3208，并且还出现了很多Socket read errors，显然还得进一步优化
六、火焰图
前面已经优化了很多配置，这些配置在优化网络的同时也带来其他资源使用的上升。这样来看，是不是说明其他资源遇到瓶颈了呢？
6.1 top查看cpu和内存使用
不妨在终端二中，执行下面的命令重新启动长时间测试：
# 测试时间30分钟
$ wrk ‑‑latency ‑c 1000 ‑d 1800 http://192.168.0.30
切换回终端一中，执行top观察CPU和内存的使用：
$ 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%左右
CPU使用率上升该怎么进行分析呢？可以使用perf配合火焰图，很容易就能找到系统中的热点函数
6.2 生成火焰图
保持终端二中的wrk继续运行，在终端一中执行perf和flamegraph脚本，生成火焰图：
# 执行perf记录事件
$ perf record ‑g
# 切换到FlameGraph安装路径执行下面的命令生成火焰图
$ perf script ‑i ~/perf.data | ./stackcollapse‑perf.pl ‑‑all | ./flamegraph.pl > nginx.svg
6.3 查看火焰图
使用浏览器打开生成的nginx.svg，可以看到下面的火焰图
根据火焰图原理，这个图应该从下往上、沿着调用栈中最宽的函数来分析执行次数最多的函数
6.3 火焰图函数分析
中间的do_syscall_64、tcp_v4_connect、inet_hash_connect这个堆栈，很明显就是最需要关注的地方
inet_hash_connect()是Linux内核中负责分配临时端口号的函数。所以，这个瓶颈应该还在临时端口的分配上
在上一步的"端口号"优化中，临时端口号的范围已经优化成了"10000 65535"。这显然是一个非常大的范围，那么端口号的分配为什么又成了瓶颈呢？
找不到原因没关系，可以暂且放下先看看其他因素的影响
再顺着inet_hash_connect往堆栈上面查看，下一个热点是__init_check_established函数。而这个 函数的目的是检查端口号是否可用。结合这一点可以想到，如果有大量连接占用着端口，那么检查端口号可用的函数不就会消耗更多的CPU吗？
6.4 ss查看连接状态
实际是否如此呢？继续在终端一中运行ss命令查看连接状态统计：
$ ss ‑s
TCP: 32775 (estab 1, closed 32768, orphaned 0, synrecv 0, timewait 32768/0), ports 0
...
可以看到，有大量连接(32768)处于timewait状态，而timewait状态的连接本身会继续占用端口号。如果这些端口号可以重用，那么自然就可以缩短__init_check_established的过程。而Linux内核中，恰好有一个tcp_tw_reuse选项用来控制端口号的重用
6.5 tcp_tw_reuse控制端口号重用
在终端一中，运行下面的命令查询它的配置：
$ sysctl net.ipv4.tcp_tw_reuse
net.ipv4.tcp_tw_reuse = 0
可以看到，tcp_tw_reuse 是0，也就是禁止状态
其实看到这里，就能理解为什么临时端口号的分配会是系统运行的热点了。当然，优化方法也很容易，把它设置成1就可以开启
6.6 测试优化后的性能
把优化后的应用打包成了两个Docker镜像，执行下面的命令来运行：
# 停止旧的容器
$ docker rm ‑f nginx phpfpm
# 使用新镜像启动Nginx和PHP
$ docker run ‑‑name nginx ‑‑network host ‑‑privileged ‑itd feisky/nginx‑tp:3
$ docker run ‑‑name phpfpm ‑‑network host ‑‑privileged ‑itd feisky/php‑fpm‑tp:3
容器启动后，切换到终端二中再次测试优化后的效果：
$ wrk ‑‑latency ‑c 1000 http://192.168.0.30/
...
52119 requests in 10.06s, 10.81MB read
Socket errors: connect 0, read 850, write 0, timeout 0
Requests/sec: 5180.48
Transfer/sec: 1.07MB
吞吐量已经达到了5000+，并且只有少量的Socket errors，也不再有Non-2xx or 3xx的响应，说明一切正常
七、小结
学习了服务吞吐量下降后的分析方法
其实从这个案例可以看出，性能问题的分析总是离不开系统和应用程序的原理
实际上，分析性能瓶颈最核心的也正是掌握运用这些原理
- 首先，利用各种性能工具收集想要的性能指标，从而清楚系统和应用程序的运行状态
- 其次，拿目前状态跟系统原理进行比较，不一致的地方就是我们要重点分析的对象
从这个角度出发，再进一步借助perf、火焰图、bcc等动态追踪工具找出热点函数，就可以定位瓶颈的来源，确定相应的优化方法
以上是关于linux性能优化服务吞吐量下降分析的主要内容，如果未能解决你的问题，请参考以下文章