一、背景
由于推送业务的历史问题,推送业务代码比较散乱,推送日志也不方便查看,推送模型也不够统一,因此专门设计一个核心模块来逐步替换掉之前的推送业务代码,进行统一管理
二、问题描述
通过线程池抓取数据后进行组装然后推送给业务方,在推送过程中出现整个日志上下文打印错乱的问题,
如A线程持有的上下文参数对象,在B线程的日志中被打印出来了。
在测试case中,有三类数据要被推送,不同类型的数据被分到同一个线程池的不同线程处理,
如下(正常情况):
A类数据—>T1线程处理–>T1线程日志展示A类数据的上下文信息(如类型信息,list大小,查询条件内容等等)
B类数据—>T2线程处理–>T2线程日志展示B类数据的上下文信息(如类型信息,list大小,查询条件内容等等)
C类数据—>T3线程处理–>T3线程日志展示C类数据的上下文信息(如类型信息,list大小,查询条件内容等等)
但是在日志显示上是错乱的,如下:
A类数据—>T1线程处理–>T1线程日志展示A类数据的上下文信息(如类型信息,list大小,查询条件内容等等)+部分B类数据的上下文信息(如list大小,查询条件内容)
B类数据—>T2线程处理–>T2线程日志展示B类数据的上下文信息(如类型信息,list大小,查询条件内容等等)+部分A类数据的上下文信息(如list大小,查询条件内容)
C类数据—>T3线程处理–>T3线程日志展示C类数据的上下文信息(如类型信息,list大小,查询条件内容等等)
上面的是打印日志方面的问题,但是实际上在测试过程中整个数据推送流程没有问题,因此当时第一阶段上线前并没有太在意,上线之后也没有问题,但是至于为啥会错乱,肯定需要排查的。
三、排查思路
3.1 并发问题
第一印象是觉得可能出现了并发问题,因此在关键方法上加了锁,重新发了一版之后生效了,但是后面又出现了,所以这个方向不对。
3.2 trace问题
由于是xxljob触发调度,在调度过程中没有统一的trace信息,因此加上了,最初也是怀疑是因为aop+MDC trace导致的,另外之前也看过trace多线程日志错乱问题,但是明显跟我这个场景不一样,在业务代码中注释了引入的trace代码之后还是存在问题,所以这个方向也排除了。
3.3 其他问题
- 配置问题
- 嵌套调用
- …
另外也通过上面的方向排查了,没啥思路。
3.4 问题场景回归
每个线程只处理一类数据,上下文是隔离的,但是当前日志的内容却打印了别的类型的数据,明显出现错乱,所以可能是组装数据的上下文不是纯隔离的。如下代码:
/**
* 推送
* @param pushDataContext
*/
private void exePush(PushDataContext pushDataContext){
Map<Long, List<PushTaskMain>> pushTaskGroupMap = pushDataContext.getPushTaskList()