性能压测诡异的Requests/second 响应刺尖问题

Posted 2020-10-08

最近一段时间都在忙着转java项目最后的冲刺，前期的coding翻代码、debug、fixbug都逐渐收尾，进入上线前的性能压测。

虽然不是大促前的性能压测要求，但是为了安全起见，需要摸个底心里有个数。

毕竟这次转java的服务都是集团核心公共服务(主要是订单域服务)。（等我们顺利上线了，我再来好好总结下其中的坎坷和壮举。）

废话不多说了，直接进入主题。

由于这次压测主要重点是关注正向的两个核心订单服务，下单服务、查单服务。查单服务初步压测下来问题不大，主要是db的索引和cache的问题。

下单服务有两个核心接口，预订单查询、创建订单。预订单查询主要是订单的前置状态的结算页汇总计算（不仅是结算页），不落具体订单，如，各种促销、卡券码、虚拟币的规则计算等等。

创建订单逻辑稍微复杂点，对周边的系统及中间件依赖也比较多，所以需要重点关注，至少心中要有数，哪怕下游的哪个服务的性能有问题，在下次大促的时候可以优化掉。

（并不是说所有性能问题都需要及时优化，只要保证能撑得起业务量的一定范围就好，因为性能优化无止境，需要把握好节奏。）

提交横向压测前我们需要自己先过一遍，这样才能加快压测的效率，由于时间比较紧再加上客观的环境问题，我将服务中几个没有压测环境的依赖去掉。（有关压测的一些实践我将在下篇文章好好总结下，这里就不展开了。）压测了几轮（时间差不多30分钟左右。），消除了一些环境、代码、依赖的障碍，提交横向走压测流程，接着就去忙其他的事情了。（诡异的问题比较多~_~，mybatis pagehelperplugin好像也有点并发问题，还没定位到，不知道是用的不对还是什么情况，继续排查，有结论了我在总结分享下。）

1.压测报告：

并发用户数没变化，平均响应时间没变化，但是request/second奇怪了。我相信大多数开发的直觉就是fullgc了，我也一样。

立马去看下服务器的GC监控，同时看下程序的GCer配置是CMS。（CMS主要解决低延迟问题《深入理解JAVA虚拟机》）

2.查看服务器监控情况：

JAVA GC：

没发现fullgc，再看下几个其他的系统资源是否有异样。

cpu:

刺尖的几个点CPU idle 基本都是100%，us也是0%，非常奇怪。再看下其他的资源。

network：

也是比较奇怪的，receive到是挺正常的，send基本为0了，感觉像是某个调用或者发送停止了，能接受请求，但是对下游的调用貌似停止了。

memory：

内存咋一看好像有点问题，但是了解linux 内存计算方式和使用原理都知道这其实问题不大。(下篇文章中会具体讲解关于压测的时候各个指标如何查看和计算，在压测时候重点关注top中的swap区。)

我程序里面基本上没有用到什么大量的磁盘操作，基本上就一个日志输出，别的没有了。（linux cache区不管是读还是写都会被cache住，会在cache里维护一个逻辑地址空间。我将在下篇文章中演示出来，每当我删除磁盘的日志文件，cache区都会瞬间释放。https://www.ibm.com/developerworks/cn/linux/l-cache/index.html）

重点是关注下JAVAGC 容量：（java程序的内存分配由“内存分配器+GC完成”《java性能优化权威指南》）

这是压测的下单服务机器资源情况。

3.查看DB情况：

看了下DB情况，也没啥异样，都是在相同的时间点，一下子负载没有了，时间都能对上。网络、磁盘、CPU都没有活动。

4.分析

上面图中有一幅图有点问题，不知道大家看出来了没有。就是我下单服务的应用服务器的网络流量有问题，receive、send对不上。

我们分析下，receive、send不配对意味着什么，我们有200并发，延迟1秒启动，基本上跑上个十几分钟，你能大概想象出200并发的请求空间路线图么。其实它会呈现出每秒钟都有请求进来，这是压力机的请求，每秒也会有请求出去，去访问它所依赖的服务或者中间件。如果，我们设想从压力机为开始点，把请求和响应想象成一个圆，那在圆的任何一个角度上都有请求和响应。

我们注意看下，DB的网络流量图，它就是比较正常的，没有请求没有发送。而应用服务器有点说不通，只有进来的没有出去的，这段时间内到底在干嘛，而且分布很平均。

5.排查

其实这个时候有一个结论，就是服务器其实没有瓶颈，不管是应用服务器还是DB、cache。那问题应该是在程序方面。（性能分析由上至下、由下至上集合分析《java性能优化权威指南》）。

开始尝试排查依赖服务，下单服务主要依赖商品、促销。cache不是问题，因为本地有一级缓存，而且缓存的过期时间对不上，压测环境的redis和mysql在一台机器上。所以DB没有问题，基本上redis应该也没啥问题。（这台机器很强悍）还有部分的依赖业务方的接口我已经注释掉了，不会有依赖。

开始怀疑商品、促销，但是我之前分别对这两个服务进行过压测，这两个服务基本上都是命中cache，QPS基本上接近18000。现在也只好对这两个服务再进行一轮详细的压测。

结果很遗憾，没啥线索，性能很好。

开始排查线程池问题，是否有block线程，通过jstack 打印出线程，基本上都是XNIO的condition wait，也没有啥不正常。因为下单服务的其他接口都挺正常的，线程池问题应该不大。下单成功之后有意个hold的场景，就是hold虚拟币、卡券码等等之类的逻辑，这里面使用了fiexd线程池（5个，设置了饱和策略及日志输出。），问题也不大。

开始排查日志，restful-slow.log，jdbc-slow.log、错误日志等等，一顿cat… grep…wc –l，啥也没有异常。(shit开始冒汗了。。。)

只能上大招了，开始尝试注代码，然后压测，逐个尝试，先注释DB、然后线程池hold逻辑、然后发送消息。(无赖之举。。。)

6.浮出水面

等我尝试注释掉发送消息的逻辑时候发现问题不出现了，有希望了。开始进去看代码，没啥逻辑，走的是spring 的RabbitTemplate.convertAndSend 方法。（这是个同步方法，没有任何声明说他是async的。）

/**发送消息*/
template.convertAndSend(messageConfig.getExchangeName(), routingKey, message, amqpMessage -> {

翻了下资料，没啥特殊的使用要求。

顺便看了下配置文件，发送消息走的是qa环境，这个我知道，因为当时压测环境的rabbitmq一时还没好，而且我们走的是先定义再使用queue的流程，所以如果要用我需要先上去配置好才能使用。当时图省事就先用了，自己压测下来也没啥问题，毕竟MQ的设计吞吐量都很高的，TPS足够我们用的，再加上我之前也压过qa的MQ没啥问题。

（资源没隔离是因为一些客观原因，有时候压测环境是临时搭建的。用到qa环境的中间件还有codis，但是codis基本是二级缓存，所以问题不大，先过。(回头没辙再来找它。)

搞来了qa环境的rabbitmq服务器账号，同时打开rabbtimq管理界面中的dashboard。开始重点关注这台服务器。(top命名打开，P\M看下rabbitmq各项指标。)

问题一如既往的出现了（我已经能接受了~_~，它要是不出现我才想死尼，已经来回折腾很久了。）很好，rabbtimq dashboard也出现刺尖了。

现在基本上是rabbtimq服务器的性能问题了，可能你会觉得问题找到了。但是我还是无解，为什么出现这个问题，为什么时间这么规律，肯定有蹊跷，继续排查，到底是rabbtimq服务器的CPU问题还是disk问题，还是network问题。这次重点看下top。

同样问题的出现CPU不正常，而且wait 率比较高。是不是可以这样推理，wait率高了，导致大量线程（子进程）挂起，所以看起来CPU利用率占的就高，也说的通。（先这么假设，来验证它就知道了）

有一点我可以肯定，根据rabbtimq推送消息原理，一个消息必须发送给所有监听的queue，这些queue必须落盘才算这次publish成功，才会返回。(可以参考《Rabbitmq in Action》)

也就是说发送消息不是发送给exchange就结束了，我们配置的是topic模式，这个消息类型后面有4个queue，同时这几个queue都有消费者在获取消费消息。但是由于获取消息的方式是pull模式，也不会存在多大的并发获取消息的情况。而且这些queue里面的消息都非常多，当我不压的时候CPU也不高，pull消息的开销对服务器来说network多点，CPU不会太多。

上图中的cpu wait率有点不正常是因为exchange同步写4个queue且落盘，所以有这个问题。

基于这个推理，我考虑用一个空exchange来接受消息，根据原理指导，exchange收到消息之后如果发现没有任何queue可以投递就直接丢弃了。

压测下来一切正常，没有出现刺尖情况（真爽~_~），cpuwait 正常0。基本上定位到问题了。是因为rabbtimq本身的负载不够了，性能跟不上所以导致这个问题，这也算加深了rabbtimq的部分原理。

在基于这个推理，我用了一个不持久化的queue来接受消息，也就是说这个消息是不会持久化的，cpuwait应该是0。

压测下来一切正常，cpuwait为0（心情无比的顺畅）。

提交横向第二轮压测。

7.打脸

等我在开会的时候，压测兄弟找我，哥哥那个问题又出现了。

（我一时蒙蔽，我擦什么情况。）调整了下，仔细看了下那个刺尖的出现的时间比以前长了。原来大概十五分钟，现在要半小时。由于qa环境机器没有安装压测监控工具，不知道那段时间里发生了什么。（压测执行时间1小时）

我之前都是30分钟，我尝试用空exchange压了一小时（已是周五晚24:00点左右，洗澡睡觉，明早上看结果)。

早上起来看没出现那个问题。为什么我用不持久的queue还有问题，而且这个queue是没有任何consumer的，这已经涉及到rabbtimq的底层原理了。rabbtimq用的是erlang语言写的，看源码一时半会估计路都找不到。还是想其他办法。

又尝试用持久化queue来压测一把，看下到时候啥情况，仔细盯着rabbtimq dashboard，果然又出现了。（计算机问题永远不存在巧合，不确定。）

注意看下图中的In memory，shit原来落盘了，哪怕你设置不持久化为了内存利用率，它会将消息落盘，注意看Persistent没有任何消息。消息总量1.1G，内存中只有119MB。

为什么会有那么大的disk write。由于大量的磁盘写入，导致publish消息的时候block了。具体为什么会这样就要去研究rabbtimq源码了。这些在rabbtimq的配置中应该有策略的，由于不是太熟悉rabbtimq，所以这里就只好先告一段落了。

8.总结

能隔离环境的尽量隔离，排查环境问题最头疼，但是有时候又无法避免。（下篇压测文章分享下，环境问题的排查方式和工具）

遇到问题一定要搞清楚根源，就算找不到根源也知道把它限定在某个范围内，比如限制到DB、操作系统等等。