利用火焰图排查热词服务性能问题

问题背景

最近在配合研究部门重构ezmt,顺手把热词服务训练相关的模块进行了重构(其实接手这个服务捋清了逻辑后早就想重构了,这次正好趁机搞一下)。在联调结束后,用wrk压了一下性能,结果大跌眼镜,开了6个worker, 但是提高压测的线程数和连接数,QPS始终不见上涨, 几轮压下来QPS只有16-17左右,随着压力的上升,timeout现象非常严重。

于是单独对上游的ezmt热词训练服务压了一下,QPS在29左右

1
2
3
4
5
6
7
8
9
10
11
12
13
14
[[email protected] /home/aidu35/work/third/wrk]$ ./wrk -t 2 -c 10  -d 30s --latency  -s scripts/hotword.lua http://10.12.8.19:8001
Running 30s test @ http://10.12.8.19:8001
2 threads and 10 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 341.88ms 46.86ms 520.05ms 69.14%
Req/Sec 15.19 6.48 40.00 89.67%
Latency Distribution
50% 341.40ms
75% 373.19ms
90% 403.02ms
99% 451.30ms
875 requests in 30.06s, 0.92MB read
Requests/sec: 29.10
Transfer/sec: 31.17KB

难道是重构后性能下降明显?于是我们将版本回退为重构前的版本又压测了一遍QPS还不到10

进入容器查看了一下压测时的情况,实际cpu和内存的占用都非常低,这种情况,怀疑有很大可能是网络进程中出现了阻塞调用,于是准备抓取网络进程的off-cpu火焰图。

环境准备

在抓取前需要做一些准备工作,具体参照《openresty最佳实践》中关于如何安装火焰图生成工具的步骤。

由于要排查的是网络进程阻塞,我们需要使用sample-bt-off-cpu 来绘制C代码执行过程中让出CPU 的时间(阻塞时间)的火焰图

将热词服务的worker调成1后,我们重新进行了压测,并用下面的工具抓取了 worker进程20s的火焰图

1
./sample-bt-off-cpu -t 20 -p 5449 -u > out.stap

接下来使用FlameGraph生成svg

1
2
./stackcollapse-stap.pl out.stap > out.folded
./flamegraph.pl out.folded > offcpu.svg

image

分析和优化

从火焰图可以看到,有三处阻塞的调用,一个是posix.access接口,另外两个是语义资源训练相关的调用,主要涉及semantic.so中文件的操作,这三处操作大约占用了53%的block时间

针对这两点,我们对代码进行了优化,

  1. access使用了posix的unistd动态库,目的是查看文件是否存在,我们使用一个shell命令来替代它,并使用官方的lua-resty-shell来调用
  2. 针对semantic.so提供的API, 预期希望lua接口能返回实际的数据,将文件写入操作由单独的进程处理,已经给相关同事提了需求。短期内,先将语义训练封装到单独的lua脚本中,再利用lua-resty-shell进行调用。

这两点修改完后,我们再次抓取了off-cpu的火焰图
image

可以看到原先3处的阻塞调用已经消失了,接下来信心满满地再次进行压测,但是测试下来QPS仍然没有上升,这时候网络进程的CPU使用率随着连接数增加也逐渐上升了,但是随着连接数的增多明显服务的超时是错误逐步增多的。

我们抓取了CPU的火焰图

1
2
3
./sample-bt -p 5449 -t 20 -u > a.bt
./stackcollapse-stap.pl a.bt > a.cbt
./flamegraph.pl a.cbt > a.svg

image

通过CPU的火焰图可以看到,网络进程约有70%的CPU时间消耗在了lua-resty-shell的__fork中。这些shell命令大多数是执行一些io操作,查看服务的错误日志,可以看到网络进程中有大量的resty-shell执行超时。

到这里基本上可以确认是系统I/O的瓶颈,当前测试环境使用的是NFS,要提升性能,需要从磁盘入手看如何提升并发写如的性能了, 我们准备把NFS切换成本地磁盘,让训练出来的文件写到本地磁盘,再测试一下性能

1
2
3
4
5
6
7
8
9
10
11
12
13
14
[[email protected] /home/aidu35/work/third/wrk]$ ./wrk -t 4 -c 40 -d 30s --latency  -s scripts/cinfo_hotword.lua http://10.12.6.199:18002
Running 30s test @ http://10.12.6.199:18002
4 threads and 40 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 1.33s 150.21ms 1.53s 93.72%
Req/Sec 13.24 9.68 40.00 68.50%
Latency Distribution
50% 1.35s
75% 1.39s
90% 1.43s
99% 1.49s
892 requests in 30.08s, 141.12KB read
Requests/sec: 29.66
Transfer/sec: 4.69KB

可以看到性能已经和测试环境的ezmt的QPS一致了, 下一步直接mock掉ezmt训练的这块的数据,再测试进行一次测试

1
2
3
4
5
6
7
8
9
10
11
12
13
14
[[email protected] /home/aidu35/work/third/wrk]$ ./wrk -t 4 -c 40 -d 30s --latency  -s scripts/cinfo_hotword.lua http://10.12.6.199:18002
Running 30s test @ http://10.12.6.199:18002
4 threads and 40 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 607.42ms 116.63ms 755.61ms 81.43%
Req/Sec 28.76 23.05 101.00 67.53%
Latency Distribution
50% 638.32ms
75% 692.35ms
90% 714.52ms
99% 741.81ms
1966 requests in 30.07s, 311.03KB read
Requests/sec: 65.39
Transfer/sec: 10.35KB

采用mock的train接口后, 单worker的CPU轻松跑到了100% QPS上升到了65,我们把worker数调成和线上一直的6个,进行最终的测试

1
2
3
4
5
6
7
8
9
10
11
12
13
14
./wrk -t 6 -c 60 -d 30s --latency  -s scripts/cinfo_hotword.lua http://10.12.6.199:18002
Running 30s test @ http://10.12.6.199:18002
6 threads and 60 connections
Thread Stats Avg Stdev Max +/- Stdev
Latency 198.59ms 111.60ms 819.18ms 77.58%
Req/Sec 52.73 19.63 202.00 73.75%
Latency Distribution
50% 171.61ms
75% 253.19ms
90% 344.32ms
99% 573.53ms
9406 requests in 30.10s, 1.45MB read
Requests/sec: 312.49
Transfer/sec: 49.44KB

可以看到, QPS上升到了300+, 基本按预期提升。

您的支持将鼓励我继续创作!