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

问题背景

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

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

[[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的火焰图

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

接下来使用FlameGraph生成svg

./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的火焰图

./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切换成本地磁盘,让训练出来的文件写到本地磁盘,再测试一下性能

[[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训练的这块的数据,再测试进行一次测试

[[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个,进行最终的测试

./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+, 基本按预期提升。


wechat
微信扫一扫,订阅我的博客动态^_^