日志级别修改不慎引发的一场CPU灾难

背景

今天下午16.28有同事通过日志配置平台将某线上应用部分包的日志等级由error调为info，进而导致部分机器CPU升高，甚至有机器CPU达到100%，且ygc次数增加，耗时增加到80～100ms。

故障发现与排查

16.28陆续出现线上CPU使用率告警，先紧急扩容以保障线上稳定，同时摘掉了几台CPU100的机器。另外部分网关接口调下游RPC接口出现20%超时，可用率下降。
调用链路看板中有几个rpc接口tp999增加，网关超时对应的接口与rpc无关，为本地缓存 + 分布式缓存的数据。分布式缓存监控稳定，tp999在5ms之内。由此基本可以判断是机器内部的原因。
找到网关调用超时的一条记录，进行排查，发现日志打印合理，但接口出入参的时差很大，且所在机器ygc频繁，同时耗时增加。这里还无法找到问题根源，我们进一步分析。
选中某台CPU高的机器，观察实时日志，可以发现出现了大量的rpc接口超时，且日志输出迅速。由此基本可以判断是日志出了问题，检查日志平台的配置，发现在16.28有同事调整了某个包的日志配置，于是同步相关人员恢复原始配置，恢复后，观察10分钟，发现服务趋于稳定。

故障分析

我们这个应用日常CPU使用率在40%左右，有商详、搜索、百补等大流量渠道调用，资源利用率较高。
调用量包括：助手历史信息6k的qps，商详12k的qps，百补9k的qps以及搜索2k的qps和其他接口2kqps等。
随着日志级别的调整，大量的info日志输出到磁盘，这些额外的日志记录需要执行更多的代码逻辑，包括json序列化，磁盘IO等需要消耗更多的 CPU 资源。同时由于对象的序列化，导致内存占用增加，ygc增多，另外CPU利用率升高也导致了ygc耗时增加。继而触发CPU升高，导致部分服务可用率下降。

防范措施

在操作线上日志级别时一定先要分析预计的日志量以及可能涉及的日志范围。
有时为了排查线上问题，会将很多中间节点日志打成info，线上我们一般不需要关注这块，可以将其等级置为error，但是出入参日志需要保留，以防出现线上问题时可以通过预发环境进行复现。
另外，在日常的开发过程中，我们需要尽可能少的打印日志，同时避免重复的日志打印，比如前文打印了ABC，后文数据解析后又打印B，这完全没必要。但是注意，一些核心服务以及中间件的出入参日志需要保留。

总结

线上操作需谨慎，涉及配置调整要多人check再执行，操作后发现问题及时回滚。对于复杂结构的日志不要全文打印，关注核心信息即可。日志级别修改可采用一定的灰度策略，以减少故障影响。