问题排查之--logback配置不合理（多线程尽量避免输出日志到控制台，无论什么情况下）

背景

最近小伙伴反馈执行导出效率较慢，现象是升级2.5.5之前速度还好，一小时可以导2万左右的案件，但是升级2.5.5之后导出效率下降了好几倍，现场导出了gc和agent日志，但还是未定位根因。
本来我感觉这不是啥大问题，以我对导出工具的了解，给现场调调参就搞定的事儿，没想到很快就打脸了！！！

过程

根据个人既往经验尝试定位问题

导出工具调优第一件事儿是先看fb_runlog.log（良好的架构设计真的可以让你在日后节省很多不必要的工作量），那么先跟现场要一份日志看一下吧，第一步就给我干懵了。
lf代表当前正在加载文件的线程数量，目前已知且暂时不好解决的就是这里，日志里既然此列数值很小，那代表加载文书不是瓶颈
bx代表当前正在构建xml的线程数量（正在工作的，不是存活的），现场配置的是6，可以从日志中看到目前构建xml在满负荷运行
elapsed time代表本次启动导出以来经过的时间，可以从日志看出来导出性能是在持续下降的，到后来差不多1分多才能完成一个zip（刚开始的几十个zip包很快，差不多在1、2分钟开始性能突然下降，并很平稳的持续很慢…）

虽然不用再继续看之前的运行日志也可以定位到问题出在buildxml环节了，但是还是扫一眼吧，看看差距到底有多大
done代表已生成的zip总数，从日志看效率很平稳，2.5.5半个小时了才导了将近70个zip，而2.5.4才16分钟就导完了将近250个包，这差距有点儿大呀
t(n/m)代表累计速度（total speed）
r(n/m)代表瞬时速度（recent speed）

根据个人既往经验二次尝试定位问题

考虑到之前有次因为另一个小伙伴不熟悉导出工具，增加一个特性时把整个构建xml的整个流程增加了一个独立参数，且没考虑多线程构建引发大量错误数据，修复这个补丁时给公用方法增加了synchronize关键字又导致性能急剧下降的先例（后来代码让我还原了…人家架构本来就可以简单扩展即可支持该特性，只需要自己增加一个转换关系类即可，所以不熟悉整个系统架构时，真的不推荐对现有系统进行大规模改造，除非你真的已经吃透了当前系统的架构，或者你技术特别牛逼）
然后看了一遍git的提交日志，然而并未发现有什么会引起性能急剧下降的可疑点。那咋办？老老实实想办法定位根因吧，捷径走不通了

根据现有信息进行再次定位

自己的捷径走不通，那试试小伙伴的捷径吧，问问小伙伴有啥可复用的信息，换个思路定位
小伙伴告诉我已经收集了两个版本的gc、agent日志，说好像定位到了一个问题代码，但看了下源码没发现有啥疑点

知道下面这里有个坑还没填，但看日志也被排除掉了（每个xml生成时都会触发一遍这个数据库查询，关键每次查询的结果都是完全相同的…我也是挺佩服写这段代码的人，不别扭吗？）。虽然是个坑，但还没到严重影响性能的地步（话说这个坑已经给产品列出来了，现在的导出工具还有N多坑没填，需要找时间持续优化，坑太多了）

后来陆陆续续发现几个疑似问题点，但都被排除了
甚至一度以为跟频繁的GC有关，还专门让现场修改了一次GC的输出格式，然鹅，最终又被排除了

定位根因

既然自己的经验和别人的现有成果都无效，那就按规矩来吧，先看一下那几个bx线程现在到底在干嘛（从刚开始咱们就定位到了瓶颈在bx，但一直想走捷径，现在发现，有时候捷径反而是远途呀）
瞬间定位问题！！！总共有6个线程，5个是WAITING，只有一个是RUNNING，关键争抢的是同一把锁…

让现场发一份logback.xml看一下，貌似也没啥特别的，无非级别是info而已，那问题出在哪儿呢？突然想起来，有没可能现场还有其他配置，先给现场要一份截图再说
不要截图不知道，一要截图吓一跳！啥情况？咋还有个logback-test.xml（logback-test.xml的优先级比logback.xml高，写在源码里面的，大家一定要注意，还有一个config-test.properties。另外springboot项目理论上应该搭配logback-spring.xml使用，但前提是没有logback-test.xml和logback.xml这俩文件，否则前面那俩文件的优先级比logback-spring.xml要高）？这个是为了方便开发调试用的，打包的时候应该会被排除的呀（应该是…发包的人应该是用IDE打包，没有用maven打包而导致该文件没有被排除，大家要注意这一点）。不管了，让现场先删掉这个文件让现场再试试，现场反馈快多了，问题解决（因为增加agent监控对性能还是有一些影响的，后来把增加的监控信息都删掉了，效率跟2.5.4版本无差异，但还有优化的空间，后续再跟进，现场小伙伴已经累趴了）

根因分析

but，到底啥原因导致的新版本效率降低呢？
重点就在下面这里了，就是因为红框中的这个配置导致了现场性能下降

通过源码我们可以看到ch.qos.logback.core.ConsoleAppender本身就会调用System.out，而这个对象是线程安全的，因为他把所有可能不安全的方法都加了synchronize代码块，所以多线程时就会出现等待的现象

而我们通过栈转储文件可以看到，目前buildxml线程争抢的还不是那个锁，而是另一把锁（不要问我为啥stack dump和源码中的行数不一致，我也不知道，不过猜测应该是Javaagent动态改变了对应class的字节码导致的，知道的同学可以说一下）

本来吧哪怕有锁竞争也不会那么慢的，偏偏2.5.5版本导出模板配错了一个转换类型，导致应用输出了大量的提示日志，而每行日志输出都要竞争同一把锁，综合因素导致了新版本导出工具性能下降那么厉害

结语

1、现场不要随意使用输出到控制台的配置，除非万不得已（调试的话，可以用logback-test.xml，想咋折腾都行，就是不要发到现场）
2、一定要用maven等辅助工具来打包，且确认打包结果是否正确（尤其是那些XXX-test的文件，一定不要发到现场）
3、一定要保证产品的发布质量（其实，就算现场日志配置有问题，这一版本要不是模板配错了，输出了大量相同的提示日志到控制台，效率也不会那么低下）
4、有时候捷径并不好走，jstack、jmap等自带的命令很方便，可以帮我们定位大部分问题，原生的搞不定了我们再用更高级的工具来辅助定位问题