Logback日志输出踩坑记

Posted 2022-07-28 幸福遇见_1993

项目场景：

本人在一家电车充电应用类服务新能源公司上班，是一名程序媛。随着疫情的解封，油价的上涨，电车已经成为当今社会大趋势，在我公司平台上日充电订单量达到四五十万单。

---

问题描述

近日在上午十点左右、夜里十一点左右，这两个时间段频繁接收日志监控系统的接口响应超时告警信息，过了这两个充电高峰期后，又恢复正常。针对这种接口超时情况，进行问题排查。

• 问题定位一：
  分析日志异常信息，从异常信息找出原因
• 问题定位二：
  排查是否存在查库操作，是否由于慢sql影响接口性能。
• 问题定位三：
  排查超时接口中系统调用链路，定位是否由于调用三方接口响应超时导致该接口整体响应时间延长。

原因分析：

参考以上问题定位思路，逐步攻克，通过日志平台分析，访问调用时出现hsf 线程池满情况，hsf默认配置720个线程，当请求量过大则会出现线程池满，当前系统配置允许情况下，调整hsf线程数为900，机器重启，观察几日。

貌似问题好像解决了…但在高峰期偶尔还是会出现超时现象，问题依旧存在，按照上次的思路再继续排查，梳理代码排查是否由于慢sql影响性能，执行explain 执行计划，查询数据走索引，响应时间快。在继续梳理调用链路，可能由于调用三方接口，响应时间过长，需要三方接口优化，在进行沟通后，三方接口几乎是在十几毫秒返回，但发现很奇怪的现象，请求时间和三方接口接收到请求时间相差5s,即使三方接口在十几毫秒内返回，但总响应时间大于接口设置的超时时间2s，需要进一步定位问题，为啥三方接口在5s后才接收到请求。

根据代码分析此处并无复杂业务逻辑，因为日志输出耗时长。
因为日志打印到控制台及同步输出到文件，日志输出到控制台及同步输出到文件时，必须独占，因此，并发线程数越多，输出的日志行数越多，越容易形成阻塞，同时还会造成CPU使用率飙升。

---

解决方案：

将同步输入日志方式调整为异步方式输出，线上环境日志输出只进行输出到文件，不输出到控制台

进行压测

发现问题并进行深入分析