路由网关项目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+,可以接受