现象
某个应用,机器数增加到了150台,但是发现其load较高。
对于4核机器来说,负载率高峰期超过4,意味着高峰期几乎满载,这是一个不正常的现象。
<div class="lake-codeblock-content" style="border: 1px solid rgb(232, 232, 232); max-width: 750px; color: rgb(89, 89, 89); margin: 0px; padding: 0px; background: rgb(249, 249, 249);">
<div class="" style="color: rgb(89, 89, 89); margin: 0px; padding: 16px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);"><pre class="cm-s-default" style="color: rgb(89, 89, 89); margin: 0px; padding: 0px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);"><span class="lake-preview-line" style="color: rgb(89, 89, 89); margin: 0px; padding: 0px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);"><span class="lake-preview-line-number lake-lm-pad-level-0" style="color: rgb(191, 191, 191); margin: 0px 8px 0px 0px; padding: 0px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);"></span><span class="lake-preview-codeblock-content" style="color: rgb(89, 89, 89); margin: 0px; padding: 0px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);">经验法则如下:
当系统负荷持续大于0.7,你必须开始调查了,问题出在哪里,防止情况恶化;
当系统负荷持续大于1.0,你必须动手寻找解决办法,把这个值降下来;
当系统负荷达到5.0,就表明你的系统有很严重的问题,长时间没有响应或者接近死机了。
</div>
</div>
指标
首先确认系统无FullGC、Java线程符合预期。
查看CPU,CPU一直运行在较高的峰值。当然对于4核CPU来说,这个比例就不算太高。
分析
那么我们分析出来了比较明显的结论,CPU运行低和LOAD较高,则表示等待IO的进程比较多。我们进一步定位问题,我们DUMP线程,看看线程在等待什么了,为什么会导致如此高的IO。
<div class="lake-codeblock-content" style="border: 1px solid rgb(232, 232, 232); max-width: 750px; color: rgb(89, 89, 89); margin: 0px; padding: 0px; background: rgb(249, 249, 249);">
<div class="" style="color: rgb(89, 89, 89); margin: 0px; padding: 16px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);"><pre class="cm-s-default" style="color: rgb(89, 89, 89); margin: 0px; padding: 0px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);"><span class="lake-preview-line" style="color: rgb(89, 89, 89); margin: 0px; padding: 0px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);"><span class="lake-preview-line-number lake-lm-pad-level-0" style="color: rgb(191, 191, 191); margin: 0px 8px 0px 0px; padding: 0px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);"></span><span class="lake-preview-codeblock-content" style="color: rgb(89, 89, 89); margin: 0px; padding: 0px; background: none 0% 0% / auto repeat scroll padding-box border-box rgba(0, 0, 0, 0);">sudo /opt/taobao/java/bin/jstack -F 1908 > stack.log</span></span></pre>
</div>
</div>
经过统计,发现大量的线程都BLOCKED在红色的代码代码内,那么这段代码到底是做了什么,为什么会BLOCK大量的请求。
继续使用线程诊断,发现大量的线程都在等待状态,其中等待的代码段是logback的日志打印。
根据业务情况,我们就得到了结论,即本系统有大量线程的相同代码块同步打印同一个日志,导致加锁并行处理,进而导致多个没有取到锁的线程在等待上个线上打印日志释放资源。
优化
很简单的一个办法,就是利用Logback的异步打印日志,可以参考文档:
https://examples.javacodegeeks.com/enterprise-java/logback/logback-ayncappender-example/
核心原理是同步打印日志是直接对文件同步操作,而异步打印日志原理就是打印日志写将日志写到队列,然后将队列异步写到文件里去。
结果
优化后,发布线上观察机器的LOAD情况如下:
可以看到,发布优化后的LOAD已经小于昨日的同比LOAD,说明优化还是有一定的效果的。但是,同时发现,优化不明显,说明还有其他原因,还需要进一步排查是否有其他系统未知问题。
思考
系统调优是难度非常大的一个课题,也是需要具备非常深的基础底层知识,才能更快的定位和分析以及解决问题。