一次有趣的系统性能优化经历
最近的工作有些忙碌，除了AI相关的研究，还抽空做了一些系统相关的优化，其中就包含一个服务的性能调优。据说这个服务之前就一直存在问题，一个是内存占用高，二是偶尔服务僵死导致dubbo服务都注册不上了，三是数据延迟，偶尔的重启成了最有效的解决方案。 既然是程序会突然退出，就看前后的日志吧，但是也没有看到类似OutOfMemory相关的日志，查看系统日志也没有。由于java程序是通过wrapper启动的，于是找到了wrapper的日志，其中发现了hung关键词日志，也就是说jvm僵死导致和wrapper的心跳中止了，于是wrapper把程序重启了，至此找到了一点线索，到这又去忙别的去了。 之前看过一本书，提到对于一个系统来说，如果不能观测就像瞎子一样。也就是说一个系统还是要具备可观测的能力。于是抽了点时间在增加了一些定时任务，周期性收集所有线程池负载状况以及一些mqtt发送的统计。在mqtt发送的统计中发现有错误率而且都是短连接，每发送一个数据包都要连接发送断开，这一点我想不通，找到了原始的对接协议发现clientid是按照设备号来定义的。对于这种服务器转发的场景实际上也要建立这么多连接。沟通过扩展一个协议，但是历史原因，有计划但是时间不可控。 线程池的负载日志，分析下来，在高峰期还是有很多核心线程满，队列打满的情况。另外发现mqtt消息构建过程查询数据库有时候很快，有时候很慢。我去查了rds的负载，发现也不高啊。于是我又加了数据库连接池的日志，这一加不要紧，竟然发现druid的配置没有加载，仍然使用的是默认配置。因为日志清晰的打印，最大连接数是8。查了数据源相关的配置，找到地方通过AI修复了一下。通过这两天的观察，发现清晨高峰期并发数据库连接达到了三百多。这也就能解释之前内存居高不下的原因了，获取数据库连接默认是无限等待，线程死等，队列中的对象迟迟得不到处理堆积在内存里。 这里还出现一个小插曲，在pom里有两个地方配置的堆内存，都是wrapper配置的，最大堆内存32G，在高峰期出现过OutOfMemory报错，当我把gc日志扔给ai分析时，竟然发现最大堆内存是4g。仔细查看进程参数发现有两个 -Xmx，32G的被覆盖了。非常奇怪，应该是线上打包的问题，于是顺便修改成只用一个地方的配置。这一波优化完发现运行平稳，比之前的内存占用平均少了十几个G，数据处理速度提升了很多。当然还有一些细节的问题比如定时任务默认是单线程，偶发被卡住无法输出统计日志的情况等。 总结下来，你可能会发现，很多问题是灯下黑，你想当然的以为这么久没有解决的问题应该是比较深层次的问题。所以一开始你的注意力并不在此，尝试进行长连接优化、消费数据增加限流器预热、优化线程池失败策略等，起到的作用不是很明显。我的观点还是要增加系统的可观测，尽量多的指标输出到日志中，事后可以将关键信息通过AI进行辅助分析。况且现在加日志这种活交给AI很快就完成，成本小收益却很高。 处理完这些问题时已经到了下班时分，正值立秋，和好兄弟晚上吃的火锅，聊了很多生活的话题，整个的大环境真的不大好，当前还是做好自己的事，认真努力的生活。