原文地址：https://www.zoucz.com/blog/2021/06/20/a596cf30-d1d7-11eb-9fe7-534bbf9f369d/，参与评论

1. 背景

去年有做一个项目，将一套tars服务迁移，跑在公司的云上k8s集群上，并在云上集群部署了100并发的资源，压测验证OK。
按业务计划，后续要开始使用1000并发级别的资源，于是提前两周开始扩容千并发资源并压测。
忙前忙后协调好了资源，和同事一起把服务部署好，本来准备压测一把完事的，结果意外出现了：千并发资源的集群，竟然压测到200并发不到的时候就跪了，具体表现为绝大部分片包、尾包在客户端超时。

和同事一起查了许久，直到最终解决问题，过程中走了一些弯路，也积累了一些经验，做了一个总结。
想来这是一次不错的性能问题排查经验，在自己的blog里边也同步一份吧。

2. Proxy服务网络问题排查

对于此结果，我之前是有过经验的——在工作机上往213环境压测，由于上行带宽限制比较小（8Mbps？），压测并发数根本就上不去，会因为带宽吃满而延时极大，客户端超时。

2.1 带宽分析

既然200并发都上不去，那么计算一下200并发大致所需带宽：

1	6400byte每次请求 * 5次请求/s * 200并发 * ≈ 50Mbps

说实话，并不大。

在压测机器上 ping一把:

PING xxx.xxx.xxx.xxx (xxx.xxx.xxx.xxx) 56(84) bytes of data.
64 bytes from xxx.xxx.xxx.xxx: icmp_seq=1 ttl=52 time=33.0 ms
64 bytes from xxx.xxx.xxx.xxx: icmp_seq=2 ttl=52 time=33.0 ms
64 bytes from xxx.xxx.xxx.xxx: icmp_seq=3 ttl=52 time=32.9 ms

相对于深圳→深圳，这个深圳→南京的延时挺高.

traceroute一把：

[running]mqq@:~$ traceroute x.xxx.123.149 12800
traceroute to x.xxx.123.149 (x.xxx.123.149), 30 hops max, 12800 byte packets
 1  x.xxx.152.193 (x.xxx.152.193)  3.175 ms  4.507 ms  6.207 ms
 2  x.xxx.105.242 (x.xxx.105.242)  5.680 ms  5.783 ms  5.859 ms
 3  x.xxx.184.174 (x.xxx.184.174)  1.130 ms  3.723 ms  6.107 ms
 4  x.xxx.2.101 (x.xxx.2.101)  5.987 ms x.xxx.2.37 (x.xxx.2.37)  1.983 ms x.xxx.2.101 (x.xxx.2.101)  2.174 ms
 5  x.xxx.14.73 (x.xxx.14.73)  0.618 ms 100.126.14.69 (x.xxx.14.69)  1.987 ms  1.309 ms
 6  * * *
 7  * * *
 8  * * *
 9  * x.xxx.33.234 (x.xxx.33.234)  31.874 ms *
10  * * *
11  * x.xxx.225.105 (x.xxx.225.105)  40.719 ms *
12  x.xxx.52.73 (x.xxx.52.73)  32.648 ms x.xxx.116.87 (x.xxx.116.87)  49.498 ms *
13  * * *
14  * * *
15  * * *
16  * * *
17  * * *
18  x.xxx.123.149 (x.xxx.123.149)  32.856 ms  32.965 ms  32.830 ms

中间网关挺多，速度也不快。

有理由怀疑是不是中间某个网关带宽不够，导致压测时延时不断增大，最终超时。

联系了运维助手，表示不太会是这种情况。另外上网查了下，使用 iperf 工具，分析了下带宽.

1	yum install -y iperf 服务端 iperf -s 客户端 iperf -c 服务端ip

最终得到的结果： 3.2Gbps ，相对于压测所需的 50Mbps，大了几个数量级了，排除带宽原因。

2.2 TCP报文分析

带宽没问题，排查停滞了，接下来怎么办呢？

对于这种必现的问题，考虑单case分析，延时长，那么就拿出一条实例来，看看为什么长。

200并发压起来，出现了大量超时，ok，拿出一条session，去查一下链路上报日志：

可以石锤，片包和片包之间的时间间隔非常大，而客户端压测程序发包，是200ms一片发送，返回后计算时间，至少间隔200ms发送下一片。

那么就有两种情况.

①网络传输延时大，导致片包间隔大.

②服务端处理慢，导致片包间隔大.

对于情况①，看ping值挺稳定的，也不丢包，带宽也够，不像；对于情况②，查看链路上报日志，处理时间都很快，不像。

继续分析单条。200并发压起来，出现超时，然后单独启动一个1并发的压测程序，用 tcpdump 单独对其抓包，分析其报文。

1. ps -ef|grep ts-node  查看PID
2. lsof -p 进程ID -nP | grep TCP  查看本地端口
3. sudo tcpdump -i eth1 -s 68 -nn -vvv  port 本地端口 host 远端IP -w ./client.cap
  （对于同一条连接，同时在客户端、服务端分别抓包）

服务端抓包结果：被调收到的早、被调发送的迟4s。

到这里问题已经出现端倪，浮出纸面了 —— 日志显示处理的飞快、带宽足够、结果开始发送很慢。

2.3 修复Proxy服务问题

tars cpp rpc server处理请求的流程：

既然1不慢、3不慢、4不慢，那慢的肯定就是2了。

查看队列特性上报

果然，队列堆积很多，导致排队时间过长，看起来处理很快实际上整个耗时很长。

最头前的 Proxy 服务产生队列堆积，那只可能是流程没有异步化。检查配置，果然私有模板中没开启协程，原因是制作tars-stke上的业务镜像时，私有模板路径的环境变量忘配置了。

有点坑自己的感觉，不过排查问题的过程和方法，还是能一步一步最终走向真相，值得记录。

重新制作镜像，重建pod，再200并发怼起来，果然 —— 以之前同样的姿势跪了。

3. Asr Kaldi服务 CPU问题排查

开启Proxy服务协程后，可以看到Proxy处堆积的队列已经没了，但是响应还是很慢。

查看各个服务的监控和日志后发现，asrkaldisercer处理速度极慢，超时率极高，CPU占用极高。

经过一通分析，这就有点没道理了，南京集群和线上 abcmouse 所使用的广州集群，一模一样的CPU型号、核数、镜像、业务代码&配置，为啥表现差异那么大？

由于广州已经有线上流量了，找了个正常的深圳集群，AMD的CPU，running稳定在1，6并发CPU吃了2核左右。

从腾讯云助手处得知，南京云为eks集群，其它地区为tke集群。但是这也只能知道他们确实有差异而已，助手自身以及拉的一个20人群，也没人能说清楚为什么。

所以现在只能从唯一的变量——CPU占用来下手，好在，这是个必现的问题。

3.1 解码器线程数 & MKL线程数调整

在业务配置文件中修改解码器线程数，压测分析

在私有模板环境变量中调整MKL线程数 MKL_NUM_THREADS=1，压测分析

均无变化

3.2 MKL库CPU指令集调整

年初去上海给某客户做私有化部署时，曾经解决过类似问题，当时是通过调整MKL库的CPU指令集解决了类似的性能问题，将指令集由avx512调整到avx2，缩小每并发处理的size，能获得更好的计算性能。

查看cpu支持哪些指令集

1	cat /proc/cpuinfo

从flags中可以看到本机CPU支持的功能，里边有avx2也有avx512

查看服务进程使用的是哪个指令集的mkl

1	cat /proc/进程id/maps\|grep avx

在私有模板中修改mkl指令集

1	env=LD_LIBRARY_PATH=$LD_LIBRARY_PATH:/root/anaconda2/lib;MKL_ENABLE_INSTRUCTIONS=AVX2

这里最开始是avx512, 我修改后这里可以看到是avx2。

压测，还是有问题，看来不是指令集的问题。

3.3 cpu perf && 火焰图

开始对比正常集群和南京集群的CPU消耗有什么区别。

200并发同时对深圳、南京集群压起来。

分别抓取CPU执行任务记录

1	perf record -F 99 -p 进程ID -g -- sleep 30

用 perf report 进行报告分析

南京集群 ↑

深圳集群 ↑

可以很明显的看到，南京集群不对劲，深圳的CPU都用来干正事了——调用mkl库做计算。而南京的不知道拿来干啥了，so库中的逻辑。

通过 FlameGraph 工具生成南京集群CPU的火焰图。火焰图是一个svg文件，通过chrome打开文件，可以点击交互查看各个层级。

图中平顶的部分代表着可能存在性能瓶颈，点开后发现，一个是 ThreadWorkerManager中的runEnv，一个是 kaldi::ThreadWorkerManager::EnQueueTask。

3.4 代码分析

明确了问题可能出在哪，就可以开始翻代码了，这个是kaldiwrapper动态库里边的代码，有性能瓶颈的地方其实没有做任何操作疑似runEnv的地方

{
    std::unique_lock<MutextType> lock(mtx_);
    cond_.wait(lock, [this] {
        return ((!active_logic_threads_.empty()) || stop_);
    });
  // xxx

EnQueueTask函数

bool ThreadWorkerManager::EnQueueTask(WorkerID id, TaskInfo task_info) {
    bool need_notify = false;
    {
        std::lock_guard<MutextType> lock(mtx_);
		//xxx
    }
	//xxx
}

除了锁，没有任何造成阻塞吃CPU的地方。这里的锁如果是 std::mutex，也不会有任何问题，即使一直锁住，线程也会进入内核态，不会吃满CPU。

这里注意到，锁类型是 MutexType，不是 std::mutex，最终使用的锁是自己基于原子量实现的一个自旋锁

class SpinLock {
 public:
    SpinLock() { m_lock.clear(); }
    SpinLock(const SpinLock&amp;) = delete;
    ~SpinLock() = default;

    void lock() {
        while (m_lock.test_and_set(std::memory_order_acquire)) {}
    }
    bool try_lock() {
        return !m_lock.test_and_set(std::memory_order_acquire);
    }
    void unlock() {
        m_lock.clear(std::memory_order_release);
    }

 private:
    std::atomic_flag m_lock;
};

那么问题就初现端倪了，自旋锁由于始终处在用户态中，不会让出CPU，在某些情况下是有可能吃满CPU的。

在一些场景下，自旋锁由于其能够省掉线程上下文切换的开销（单次耗时最高可达0.06ms），在一些性能极度敏感的场景下，能带来一些性能提升。

但是这个东西，多位c++大牛都表示过非专家难以控制。它可能受服务器硬件、操作系统、编译器、业务代码等多种因素影响。要对c++并发编程、memory order有非常深入的了解，可能才能充分的玩转它。

那么到底是不是它出问题了呢，可以用perf工具继续验证。

3.4 perf调用关系

还是使用 perf report，查看代码的调用图

通过工具能看到一些汇编调用顺序，下面还有部分标准库函数打出了函数名(没截出来)

能发现，有一个循环里边的test逻辑，占用了全部CPU，前后对比代码定位，应该属于下面一段逻辑

1
2
3

void lock() {
    while (m_lock.test_and_set(std::memory_order_acquire)) {}
}

比较明显了，应该就是由于某些未知的原因，导致自旋锁锁住的逻辑耗时边长，自旋锁长时间处于用户态，吃满CPU。从压测程序表现上来看，就是请求处理响应慢。

3.5 修复自旋锁问题

将自旋锁替换为 std::mutex，自定义条件变量 std::condition_variable_any 替换为 std::condition_variable，重新压测。

60并发，16核的CPU吃了11核，70%+。

貌似不仅解决了问题，还带来了2倍的性能提升。上深圳集群验证，也是如此。

通过 perf stat 对比修改前后的统计指标

修改前 ↑

修改后 ↑

对比不是很严谨，但是可以很明显的发现，修改后上下文切换（context-switches）的开销变大了。
但是相对于声学服务涉及的大量计算，这里的线程上下文切换带来的开销可以忽略不计。

4. 后续

此处当时引入自旋锁应该是有原因的，因为它通过节省上下文切换开销确实是能带来一定程度的性能提升。只是由于某些未知的原因，这里反而导致了性能的下降。

后续可能的优化方向

参考《C++ Concurrency in Action》尝试把这个问题的原因搞明白，最终换回自旋锁。
较新的编译器会对std::mutex做优化，在某些情况下不做内核态切换，性能对齐自旋锁。
proxy→logic→acoproxy→asrkaldi→feature，缺少从整个链路上成体系的过载保护和降级策略等，这里后续需要花时间来逐环节压测、调整代码或者配置。

本文链接：https://www.zoucz.com/blog/2021/06/20/a596cf30-d1d7-11eb-9fe7-534bbf9f369d/

☞ 参与评论

一次tars c++服务性能问题排查经历 —— 网络与CPU分析