17

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

 4 years ago
source link: http://www.ai-freedom.org/2019/08/20/use_flame_graph_optimize_hotword_server_performance/?
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
neoserver,ios ssh client

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

发表于 2019-08-20

| 分类于 性能优化

| 0

| 阅读次数: 439

最近在配合研究部门重构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
[gerrard@gerrard /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
[gerrard@gerrard /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
[gerrard@gerrard /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+， 基本按预期提升。


report

Recommend

About Joyk


Aggregate valuable and interesting links.
Joyk means Joy of geeK