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

做者：王清培(Plen wang)  沪江Java资深架构师

最近一段时间都在忙着转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》)

这一点能够经过rabbtimq queue的dashboard 中的publish in 和 publish out才查看，publish out 是publish in * queue的数量。

也就是说发送消息不是发送给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、操做系统等等。

 

做者：王清培

出处：http://www.cnblogs.com/wangiqngpei557/

本文版权归做者和博客园共有，欢迎转载，但未经做者赞成必须保留此段声明，且在文章页面明显位置给出原文链接，不然保留追究法律责任的权利。