记一次后台性能调试过程

场景:

参与开发维护的etl web控制台出现监控消息读取非常慢的情况,检查队列正常,检查日志,某些情况下3s才输出一条消息详情日志(测试环境为调试方便将消息详情作INFO级别输出);

处理过程:

1.检查系统状态: jstat -gcutil [pid] 1000  (配图非实际场景)

当时的YGC比较频繁,但是平均每次GC时间0.3s,按领导的说法是没有影响.暂且不表;

2.检查内存状态: jmap -heap [pid] (配图非实际场景)

服务器MaxHeapSize 32G,Eden Space 用了1.4G, from space + to space 共用了 1G; 领导只是吐槽一下,浪费;

3.检查线程状态: jstack [pid] > jstack.log ; vi jstack.log

发现监控线程大部分处于BLOCKED状态,不仅是监控线程,包括传输线程阻塞在log4j打印日志的地方;而堆栈显示传输线程全部阻塞在打印error日志的地方.查看监控日志,震惊了,传输线程一天输出了50个日志文件;全部在打印一个错误;而监控日志打印基本被堵到不能输出的情况;  控制台用的是同步日志,在多线程大量输出日志的时候抢锁阻塞; 处理了bug之后,传输线程不再不停输出ERROR,调整日志等级,将监控线程输出日志等级由INFO调整至ERROR,重启后,监控线程消费消息速度立马打到1s 2W的速度;问题解决;