在Linux系统汇总,常见的动态追踪包含 ftrace perf eBPF/BCC 以及 SystemTap
首先使用perf配合火焰图查找热点函数
然后eBPF和BCC进行灵活的动态最终
如果eBPF受限,SystemTap 和 ftrace是更好的选择
之前,我们说过的一个网络延迟处理的问题,服务器端开启了TCP的Nagle算法,客户端开启了延迟确认导致的
接下来,我们用常见的Nginx为例,如何分析服务吞吐下降的问题
我们使用两台虚拟机,分别开启了docker中的Nginx镜像和PHP镜像
PHP是一个简单的Hello World
Doker在启动的时候,会直接设置为host network模式,接下来是启动Nginx应用,监听在80端口
$ docker run –name nginx –network host –privileged -itd feisky/nginx-tp
$ docker run –name phpfpm –network host –privileged -itd feisky/php-fpm-tp
对于Nginx的输出,我们使用如下的curl命令,然后进一步验证Nginx能够正确访问,如果可以看到
“Hello World”的输出,就说明Nginx + php已经启动了
接下来,我们测试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进行测试Nginx性能
wrk的输出中,吞吐量只有189个每秒,所有1910个请求都是异常响应,而且上面显示的read的总共大小是573.56KB
对于此,我们需要继续进行测试
我们需要首先查看TCP相关连接数
首选的工具是ss命令,而且为了观察wrk测试时的问题,我们需要继续启动wrk,并将总的测试时间延长到30分钟
wrk –latency -c 1000 -d 1800 http://192.168.0.30
我们继续观察ss的TCP得到
ss -s
| $ 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的太多了
对于timewait的问题,我们可以查看iptables,也就是通过dmsg查看系统日志,如果连接跟踪出现了问题,会看到nf_conntrack相关的日志
dmsg | tail – n 2
[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的错误日志,就是连接最终导致的问题
表已经满了,导致的问题,优化并不难,需要将连接跳到就可以
sysctl -w net.netfiulter.nf_conntrack_max=1048576
切换最终限制之后,对Nginx的性能是否有所改变呢?我们继续wrk的相关测试
| # 默认测试时间为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 |
虽然增加了吞吐量,但是异常响应还是没有减少,该怎么分析异常呢?
上面的非200和非300的情况下,需要我们查看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 “-” “-” “-“ |
响应码为499,是Nginx扩展的响应码,服务器还没有来得及响应,客户端就已经关闭连接了,服务器端处理的太慢了
那么是不是PHP的处理缓慢呢?
| $ docker logs phpfpm –tail 5
[15-Mar-2019 22:28:56] WARNING: [pool www] server reached max_children setting (5), consider raising it [15-Mar-2019 22:43:17] WARNING: [pool www] server reached max_children setting (5), consider raising it |
查看相关docker的容器日志
上面给出了警告信息
server reached max_children setting
上面显示,是子线程的最大数量达到了,我们可以考虑重设进程数量
我们重新打包了一下docker之后,进行wrk的测试
| # 默认测试时间为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相关的测试
# 测试时间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
上面显示,因为套接字队列溢出导致的
思考我们是否需要修改相关的套接字的大小
| $ 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 7 10 *:9000 *:* users:((“php-fpm”,pid=11084,fd=9),…,(“php-fpm”,pid=10529,fd=7)) |
上面显示Send-Q和Recv-Q都是10,说明监听队列实在是太小了
我们要分别查看系统,Nginx,php的套接字监听队列大小
| # 查询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的都是10,php只有511,显然套接字队列太小了,可以增大这三个配置
然后重新开启镜像测试
| $ 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 |
吞吐量已经上去了
然而现在发多少的包,就有多少的失败,发的包都是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 address) while connecting to upstream, client: 192.168.0.2, server: localhost, request: “GET / HTTP/1.1”, upstream: “fastcgi://127.0.0.1:9000”, host: “192.168.0.30” |
Nginx报出了无法连接fastcgi的错误,是EADDRNOTAVAIL,表示IP地址或者端口号不可用
这就是端口号的问题
根据网络套接字的原理,我们每次连接服务器端的时候,都是需要一个临时端口号的
那么端口号的范围我们先看下
$ sysctl net.ipv4.ip_local_port_range
net.ipv4.ip_local_port_range=20000 20050
这显示,临时端口的范围只有50个,显然太小了,优化方法很容易想到,增大范围就可以了
$ sysctl -w net.ipv4.ip_local_port_range=”10000 65535″
net.ipv4.ip_local_port_range = 10000 65535
然后切换到终端二,测试性能
| $ 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 |
这时候显示异常响应稍多了
现在少了不少的异常,但是还有一部分的存在,我们可以从资源上入手,进行相关的测试
我们不妨从终端二中,执行如下的命令,重新启动长时间的测试
# 测试时间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结果中看出来le,内存很足,cpu的系统使用率比较高
而且其中占用CPU最高的进程是nginx
那么,我们需要进一步分析,perf就可以做到,顺便结合之前说的火焰图
| # 执行perf记录事件
$ perf record -g # 切换到FlameGraph安装路径执行下面的命令生成火焰图 $ perf script -i ~/perf.data | ./stackcollapse-perf.pl –all | ./flamegraph.pl > nginx.svg |
上面的图中显示的几个栈比较宽的函数
分别是do_syscall_64、tcp_v4_connect、inet_hash_connect
其中inet_hash_connect负责分发临时端口号
那么为何这个函数占用时间如此长呢?
接下来的热点是 init_check_established函数,负责检查端口号是否可用
是不是分配之后,检查端口号失败了呢?
那么我们看下链接的状态及统计
$ ss -s
TCP: 32775 (estab 1, closed 32768, orphaned 0, synrecv 0, timewait 32768/0), ports 0
…
有大量的连接处于timewait的状态,我想,就是这个,导致的init_check_established函数占用过长的
对这个timewait的连接,一个优化的方案,就是将其的连接端口暴露出来,给端口使用
即,内核汇总的tcp_tw_reuse选项
| $ sysctl net.ipv4.tcp_tw_reuse
net.ipv4.tcp_tw_reuse = 0 |
显示为0,说明禁止,如果设置为1,就可以开启了
这样,最后测试一下,结果如下
| $ 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 |
总结一下,我们分析服务吞吐量下降的方法
分别是收集性能指标
利用性能工具,搞清状态
尝试进行利用其原理不一致的地方,进行调优