业务日志异步输出优化记

Posted 2022-11-06 朝花有露

项目场景：

随着平台上日充电订单量达到四五十万单，企业订单查询订单业务需求也日益迫切，原先企业服务管理平台页面查询响应速度赶不上用户单击等待速度，越来越多的营业厅人员反馈，强烈要求进行优化。

---

问题描述

本公司企业服务管理平台沿用老方式直接查的mysql数据库，为了展示页面多维度信息，进行sql嵌套查询条件拼接，以至于出现三张或四张表嵌套查询

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

原因分析：

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

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

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

---

解决方案：

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

进行压测

发现问题并进行深入分析