这周在排查一个系统bug的过程中,遇到不少问题,首先说一下bug情况。
这个bug在数据量小的时候不会出现,比如客户端用户量在2000以内的时候,没有问题,2000个用户操作的时候就会出现bug。
系统设计:
1、客户端用户与服务端有心跳检测,如果3次心跳没有成功,则客户端变成下线状态。
2、客户端用户上线时会将用户信息存入redis,数据库也会同步更新为在线状态(假设status=1)
3、客户端用户上线后,如果重启服务端,这时候心跳失败,会清除redis和更新数据库状态为下线状态(status=0),但是清除redis是一条一条的删除,而不是直接deleteAll,而更新数据库是一次性全部删除,而且删除redis和更新数据库是同步操作,删除redis在前面,代码如下:
这就导致在数据量稍微大一些的时候删除redis需要的时间比较长,但是因为我们的删除操作是调用了springboot的ApplicationRunner接口方法,这个方法是容器启动后,回调执行的。所以当我们服务端启动后,客户端就开始上线,但是这时候redis还没有清除完,所以不能执行数据库update操作。
4、但是客户端上线,会将数据库再次更新成上线状态,所以部分上线了,但是当redis清除完后,可以执行update数据库的代码了,这时候将刚刚时间差里上线的客户端用户又一次性更新成下线状态了。这就导致redis和数据库两边在线用户量不一致,bug出现。
5、总结:
(1)在排查过程中,首先是打日志,发现的确有执行update数据库的代码,控制台打印也有那么多条update日志
(2)怀疑是否数据问题,开启数据库general_log日志记录,的确也没错
(3)最后只能再次重现bug,过程中发现重启服务端的时候,redis数据没有清理完,发现端倪
(4)然后排查清除redis部分的代码,分析了逻辑,发现客户端已经开始上线了,redis还在清理,可能是这个导致,然后开始做实验,验证猜想正确。
其实bug问题引起原因总结就是:同步删除redis,但是上线又是异步执行的,所以导致问题产生。修改代码后,也只是保证了数据的最终一致性。
因为代码是前人写的,所以不是很了解,只能一步步排查,所以本次bug排查过程走了很多弯路,用到知识点:
(1)控制台日志,因为数据量大,不是很好查
(2)数据库执行日志:general_log,开启比较耗性能