线上问题——一次几经反转惊心动魄的问题排查记录

本文主要是介绍线上问题——一次几经反转惊心动魄的问题排查记录，希望对大家解决编程问题提供一定的参考价值，需要的开发者们随着小编来一起学习吧！

背景简述

线上某业务由于查询大量数据频繁FullGc优化，依赖于用户完课进度，测试时需要造大量的用户和专栏内容发放数据，且需要用户完课触发，因此在FAT造了一个5000人的班级，这个班级只有3个课时，测试通过脚本调用接口让着5000人都完课，3个课时都完成会发送班级完成事件，最终发现只有4999人发送了班级完成事件。

分析过程

流程简述

上图是完课进度更新流程（数据初始化流程和本次问题无关），首先客户端上传环节分数，会先保存环节完成进度，之后会串行处理课时完成进度，判断课时先所有必学环节是否都已经完成，若都已完成，则更新课时进度为已完成，否则结束流程；课时完成则会注册异步任务，更新主题月和班级的完成数量以及完成状态，最后班级完成会发送班级已完成事件（在关键节点都加了分布式锁避免并发问题，只是上图未呈现）。

分析过程

主要问题分析

通过上面的流程很容易想到：既然是少发了一个用户的班级完成事件，那么就可以先看看上述几个进度表的状态和完成数量是否正确。

• 班级进度

• 主题月进度

• 课时进度

从数据结果很容易就发现了问题所在，课时有3个已完成，两个主题月都已完成，且完成数量正确，但班级进度表中完成数量只有2，状态也是学习中。
WTF！！！线上跑的好好的代码，又没改过，难道又发现隐藏BUG了？出于这个心理始终偏向于是数据问题，或是测试的操作方式不对（咳~锅是一定要先甩出去的）！
于是通过日志找出两个主题月的保存链路：


发现两条链路上最终更新班级进度数量都是2，且没有更新状态。下面是班级进度保存的代码：

public class UserClassRecordChain extends UserRecordBaseChain<UserClassRecord, Object> {@Override@Transactional(rollbackFor = Exception.class)protected boolean finish(UserClassRecord record) {UserClassRecord existRecord = userClassRecordService.queryOne(UserClassLessonStepQueryVo.builder().userId(record.getUserId()).classId(record.getClassId()).build());if (existRecord == null) {doRecord(record);existRecord = record;}if (ProgressStatus.FINISH.equals(existRecord.getStatus())) {return false;}// 班级排期的主题月List<Long> segmentIds = this.getClassSegmentIds(existRecord);// 学习了的主题月记录List<UserSegmentRecord> segmentRecords = this.getSegmentRecords(existRecord, segmentIds);// 完成的主题月idList<Long> finishedSegmentIds = this.getFinishedSegmentIds(segmentRecords);// 计算完成课时数int finishLessonCount = this.getSegmentFinishLessonCount(segmentRecords);record.setId(existRecord.getId());record.setCreateTime(null);record.setFinishCount(finishLessonCount);if (CollectionUtils.isEmpty(finishedSegmentIds) || !finishedSegmentIds.containsAll(segmentIds)) {userClassRecordService.update(record);processCacheAfterCommit(record);return false;}record.setStatus(ProgressStatus.FINISH);initCourseId(record);userClassRecordService.update(record);userRecordFinishNotifyService.notifyClassFinish(record);processCacheAfterCommit(record);return true;}public List<Long> getFinishedSegmentIds(List<UserSegmentRecord> segmentRecords){List<UserSegmentRecord> finishedSegmentRecords = segmentRecords.stream().filter(segmentRecord -> ProgressStatus.FINISH.getValue().equals(segmentRecord.getStatus().getValue())).collect(Collectors.toList());return finishedSegmentRecords.stream().map(UserSegmentRecord::getSegmentId).distinct().collect(Collectors.toList());}public int getSegmentFinishLessonCount(List<UserSegmentRecord> segmentRecords){int finishLessonCount = 0;for (UserSegmentRecord segmentRecord : segmentRecords) {finishLessonCount += segmentRecord.getFinishCount();}return finishLessonCount;}public List<UserSegmentRecord> getSegmentRecords(UserClassRecord userClassRecord, List<Long> segmentIds) {List<UserSegmentRecord> segmentRecords = userSegmentRecordService.queryList(UserClassLessonStepBatchQueryVo.builder().userIds(Lists.newArrayList(userClassRecord.getUserId())).classIds(Lists.newArrayList(userClassRecord.getClassId())).segmentIds(segmentIds).build());if (CollectionUtils.isEmpty(segmentRecords)) {return Lists.newArrayList();}return segmentRecords;}/*** 注册事务回调事件* @param record*/public void processCacheAfterCommit(UserClassRecord record) {try {if (TransactionSynchronizationManager.isSynchronizationActive()) {log.info("事务开启，注册事务提交后处理班级学习数据缓存回调");TransactionSynchronizationManager.registerSynchronization(new TransactionSynchronizationAdapter() {@Overridepublic void afterCommit() {userClassRecordCacheClient.deleteClassRecordCache(record.getUserId(), record.getClassId());}});} else {log.warn("事务未开启，直接处理班级学习数据缓存");userClassRecordCacheClient.deleteClassRecordCache(record.getUserId(), record.getClassId());}} catch (Exception e) {log.error("更新班级学习数据缓存，注册异步任务", e);timerTaskClient.startTask(JSON.toJSONString(record), BizType.USER_CLASS_RECORD_CACHE_PROCESS.name());}}}

这里的逻辑是先查出班级下所有的主题月id和主题月进度，累加题月进度完成数量，判断班期下所有主题月是否都已经完成，是则更新状态和数量，淘汰缓存，并发送事件，否则只更新数量和淘汰缓存。那么说明一定是走的下面这个条件分支去完成更新的：

if (CollectionUtils.isEmpty(finishedSegmentIds) || !finishedSegmentIds.containsAll(segmentIds)) {userClassRecordService.update(record);processCacheAfterCommit(record);return false;
}

而能进入这个if则说明一定是 !finishedSegmentIds.containsAll(segmentIds)这个条件不满足，即班级下主题月没有都完成。

那什么原因会导致这种问题的产生呢？

• 第一种可能：分布式锁没锁住，并发问题。

但入口处加了分布式锁呀？难道是锁的粒度有问题？于是查看代码发现锁粒度确实有问题：

    @Override@Transactional(rollbackFor = Exception.class)protected boolean finish(UserSegmentRecord userSegmentRecord) {return RedisLockTemplate.doTemplate(() -> this.doSegmentFinish(userSegmentRecord), RedisLockKeyGenerator.generateSegmentRecordFinishLockKey(userSegmentRecord));}public static String generateSegmentRecordFinishLockKey(UserSegmentRecord userSegmentRecord) {return LOCK_KEY_PREFIX+ USER_SEGMENT_RECORD_FINISH+ userSegmentRecord.getUserId() + COMBINE_STR+ userSegmentRecord.getClassId() + COMBINE_STR+ userSegmentRecord.getSegmentId();}

锁的粒度是在主题月维度，两个主题月同时完成确实会导致上面的问题（其实这里的代码还有一个问题，稍后再说）。小小的兴奋一下，以为找到了根因？

看完成时间，两个主题月完成时间足足差了半个小时…

• 第二种可能：主题月进度更新的事务与班级进度更新的事务非同一个事务，在班级进度更新前查询时，主题月进度更新的事务还未提交。

上面截图都是最后一个主题月保存链路上的，第一条SQL说明主题月进度更新成功，完成数量为1，状态是FINISH（该主题月下只有一个课时），紧接着查询该表，第二张截图说明确实查到了两条数据，但最后保存班级进度数量时数量却只有2，那说明前面更新的数量1没有被查到，查到的是初始化的数据。这看起来真的像是事务引起的，对吗？但排除，因为这里是一个串行的链路，主题月和班级进度使用的也是同一个事务。
至此，排查陷入了困局…

• 第三种可能：主从读写延迟，查询走的从库，导致未查询到最新的更新结果。

从一开始就没往这方面想，因为线下环境未配置从库。直到都想把锅甩给MySQL、甩给Vitess连接池时，才终于决定看下数据库配置。这不看不知道，一看真吓一跳，DBA啥时候配了从库了！！！（所以锅又甩到了DBA身上？）
问题确实是由于读写分离+主从延迟导致的，但你以为到此就结束了么？No，年轻人，从上面的代码也可以看出两个finish都是加了事务注解的，我们的项目早就接入了基础架构的SDK，开启事务后，该事务中的所有SQL就会强制走主库，避免主从延迟的问题，那这里的事务竟然没有生效！

其实一开始也注意到日志里打印了“事务未开启的日志”，只是是否开启事务都不会导致查询不到刚更新的结果的问题产生，所以选择性先忽视了，现在可以来详细分析下这个问题了。

延申问题分析

事务为什么没生效？

一开始就说了从主题月进度保存开始就是异步任务触发的，所以主题月进度和班级进度保存需要确保在一个事务中，事务的入口则是应该在异步任务开始执行的地方，下面是主要代码：

public class SegmentRecordFinishHandler implements TimerTaskHandler {@Autowiredprivate UserSegmentRecordChain userSegmentRecordChain;@Overridepublic void handle(String data) throws Exception {UserSegmentRecord userSegmentRecord = JSON.parseObject(data, UserSegmentRecord.class);userSegmentRecordChain.doFinish(userSegmentRecord);}@Overridepublic boolean needHandle(JojoTimerTask task) {return BizType.SEGMENT_CHAIN_FINISH.name().equals(task.getTaskType());}
}

public abstract class UserRecordBaseChain<T, R> {/*** 结束记录** @param record*/public void doFinish(T record) {if (finish(record) && nextChain() != null) {R nextRecord = assembleNextRecord(record);nextChain().doFinish(nextRecord);}}
}

public class UserSegmentRecordChain extends UserRecordBaseChain<UserSegmentRecord, UserClassRecord> {@Override@Transactional(rollbackFor = Exception.class)protected boolean finish(UserSegmentRecord userSegmentRecord) {return RedisLockTemplate.doTemplate(() -> this.doSegmentFinish(userSegmentRecord), RedisLockKeyGenerator.generateSegmentRecordFinishLockKey(userSegmentRecord));}public boolean doSegmentFinish(UserSegmentRecord userSegmentRecord) {.......}
}

在SegmentRecordFinishHandler中首先会调用userSegmentRecordChain.doFinish(userSegmentRecord)方法，这里实际会调用UserSegmentRecordChain抽象父类中的方法doFinish，该方法中又会调用子类的finish。
我相信有经验的老司机应该已经发现问题所在了，对吧？没发现也没关系，我们接着往下看。
因为在SegmentRecordFinishHandler中是直接调用的父类中的doFinish方法，该方法中是通过隐含的this调用子类的finish方法，事务注解是加在finish方法上的，该注解又是通过动态代理实现的，所以doFinish没有被事务切面增强，通过this调用也只会调用到非代理类的finish方法，因此导致了事务失效（发现这个问题时真想给自己两嘴巴子，因为这个注解是前不久因为发现这里竟然一直没有加事务，才加上的，但当时却没有注意这个细节，顺手就加上了，没有仔细思考，也没有验证事务是否成功加上，啪！啪！啪！老司机也翻车了）。

到这里所有问题都分析完毕了吧！
小伙子，还是太年轻了，忘记了刚刚遗留的坑了吗？

这里有什么问题呢？看官且先思考下再往下看哦！

填坑

上面事务的使用还有一个小细节，仔细的看官应该已经发现了，finish方法中使用了分布式锁，而该方法上又标记需要开启事务，没错，事务内加锁！！！锁释放了，但事务可能会卡住未提交，其它线程也查不到该事务的更新结果。
又是一个老问题了，想到这里又想再给自己几个嘴巴子！当时在搞个啥子，这么明显的问题居然没发现。
到这里分析是真的结束了，但还得把线上所有数据全部重新跑一遍，所幸目前该表在业务上没有强依赖。下面再总结一下本次排查心得。

总结

本次排查暴露的技术问题如下：

• 读写分离架构下的主从延迟问题，需要时刻注意是否需要强制走主库
• Spring声明式事务失效问题，应该尽量使用编程式事务，使用声明式事务时要确保事务正常开启（同时也要注意事务范围，避免大事务）
• 不要在事务内加锁！
• 使用锁时需要考虑清除锁的粒度，考虑锁中业务范围扩大的影响。像本例中的业务因为线上不可能出现同一个班级下两个主题月同时完成的情况，所以锁放在主题月维度是没有问题的，但反过来说，既然不存在同一个班级下两个主题月同时完成，那锁粒度放在班级维度其实也不会影响什么。所以使用锁时一定要根据业务仔细考虑锁的粒度

而对于个人工作习惯和态度的方式反思如下：
读写分离+主从延迟，并不是新面孔，自己或团队中其他小伙伴踩过不止一次的坑了，也都曾将在团队中分享强调过，那为什么这次还是排查了一两个小时呢？主要是由于先入为主的认为线下环境是没有从库的，花了大量的时间和精力在其它方向上进行排查，最终没有思路时才从头想想还有什么遗漏的，所以在此告诫各位看官，警惕先入为主的陷阱呀，可能的原因都应该依次排查一遍。除此之外，同类或父子类中方法A this调用使用了声明式事务的方法B会导致事务失效以及事务内加锁问题也暴露了我在之前的开发中不仔细、不谨慎的问题，也再次提醒了我对于任何的改动都不应该抱有轻视之心。

最后，遗留一个小问题，针对本文发现的问题，这个代码应该如何优化呢？

这篇关于线上问题——一次几经反转惊心动魄的问题排查记录的文章就介绍到这儿，希望我们推荐的文章对编程师们有所帮助！

---