转自微信号：测试那点事

项目介绍

 

路由网关项目watchman ，接收前端http请求转发到后端业务系统，功能安全验证，限流，转发。

使用技术：spring boot+ nreflix zuul，最开始日志使用slf4j+log4j部署方式打成jar包，内部使用的是tomcat容器，设置线程数600。

工作原理

 

先介绍下zuul的工作原理，看图zuul中定义了四种filter分别是

1.pre 在请求到达origin之前执行，在这一步可以做认证，选择转发地址，记录日志

2.Routing 建立http请求，可以使用httpClient或者netflix的ribbon

3.Post 返回请求，可以在这一步做统计收集，设置response的http heder，把请求返回个客户端

4.Error当在以上三个步骤执行出错时执行

 

问题

性能压测时，tps只有400多，开启并发10个线程和100线程结果一致

分析

watchman中无任何业务逻辑，没有数据库连接操作，没有频繁io操作 只有安全验校验类和限流类，直觉上感觉肯定有问题，代码结构如下

 

 

使用jprofiler分析，首先查看CPU views下的call Tree，方法调用链路栈，

 

按调用时间算的百分比，最高的是WrappingRunable下面有10个百分比较高的http，这10个http就是本次压测的接口。每个接口的占用比都差不多，展开第一个9%的

同样是route为啥preroute耗时这么久，肯定有问题

一个请求进入会依次被三种filter处理，第一种prefilter，第二种route，第三组postroute，初步定为preroute有问题，结合代码看，本次开发pre包中只有两个prefilter一个是AppUrsTokenPreFilter，对app请求解签验签，另一个prefilter做流量控制，仔细检查了代码发现没有问题，spring源码包中有5个prefilter类，查看代码没有问题,没有找到问题换个方向

 

cpuload猜想

从cpu load看，一直很高，联想到cpu与计算有关，然后AppUrsTokenPreFilter filter中有动态md5的计算，可能与这个类有关系，验证把该类从容器中排除，继续压测，最终结果和之前一致，cpu并没有降下去，猜想错误

 

堆GC分析

一切正常，继续换方向

 

线程dump分析

通过观察thread监控，发现50个线程并发时只有5个线程处于runnable状态，其余BLOCKED和waiting,加到线程数到200， runnable还是只有个位数运行，194个BLOCKED，如图。到这可以猜测代码有大量锁竞争

使用jstack dump线程日志，全局搜索blocked 第12行 BLOCKED

其他先不管看到loadclass查看源码，同步锁。。。，问题已找到

接下来查看在哪里调用的，FormBodyWrapperFilter 137行，看代码，spring内置的一个prefilter 作用是针对form表单请求把参数进行转换，使用的是MappingJackson2HttpMessageConverter，其中在构造函数中是这样的

又调用了Jackson2ObjectMapperBuilder，继续看代码

继续看代码Jackson2ObjectMapperBuilder这个类

继续看代码，还是Jackson2ObjectMapperBuilder这个类里的

快到源头了，继续 ，这次到classutils类了

forname方法太长 我只截了关键部分

，这个就是源头，loadclass使用的是同步锁

解决问题方法禁用spring自带的prefilter类zuulzuul.FormBodyWrapperFilter.pre.disable=true，改完之后重新部署压测，瞬间上去了

 

还没有结束

之前把自己写的两个prefilter代码注释，加上去之后重新压测，tps瞬间只有一半(红线是kill)

继续线程dump查看。是的你没看错 log4j已经成为了瓶颈 

看log4j源码

从这边可以看到在转发loggingEvent到各个appender的时候，是同步的，即使你用asycAppender也没有效果，解决方法使用logback，再压测一把，平均4k+，可以接受