记一次性能问题诊断-log4j对应用性能的影响

Posted 2021-04-20 阳光非测

1、 性能现象：（1）业务预期要求TPS达到100笔/秒，实际最高30笔/秒；（2）应用服务器CPU很低

2、问题排查：本次测试关联系统使用了真实的测试环境，数据流向为LR->前置->应用->网关->账务前置->核心。先调整了应用的jvm内存，weblogic线程数，连接数，没有效果，然后跨过前置，直接调用应用提供的webservice接口，发现TPS达到了预期，运气比较好，可以断定问题出现在前置上。随后，在前置后加设挡板，TPS的仍旧很低，再次确认需要对前置进行分析和优化。

3、问题定位：通过jvisualvm对前置进行监控，发现许多线程是“监视”状态，说明有线程锁。

 进行threaddump(jstack -l pid 或者 kill -3 pid),发现blocked的线程很多，锁被其中一个线程持有，其余线程都在等待释放资源。

- waiting to lock<50f65821> (a org.apache.log4j.spi.RootLogger) owned by "[ACTIVE]ExecuteThread: '22' for queue: 'weblogic.kernel.Default (self-tuning)'"t@38

问题找到了，可以进行针对性优化。

4、调优过程：发现log4j的问题，网上查找资料发现log4j2配置全异步（all async）模式性能最好，但项目组反馈应用使用的不是log4j，是logback开源日志组件，是log4j的升级版本，代码根本没有用到log4j。奇怪了，明明抓到的是log4j，而开发却反馈没有用到log4j,经过2天查找确认，应用中有log4j相关jar包，该项目经过多次升级，许多不再使用的jar仍然存在于项目中，将log4jjar包删除之后重新上包测试，发现TPS随并发增加而增加，响应时间下降，CPU也上来了。Nohup.out里不再狂写日志。问题解决！

5、结语：本次测试发现日志组件对性能有很大影响，不仅仅是日常测试中日志级别的不同导致性能差异，开发过程中随着项目多次升级，同一功能组件引用不同的jar导致版本混乱，也是导致性能下降的原因。其实log4j不同版本以及不同的使用方式对性能都有影响，后续继续介绍。