坑爹啊,注释无用代码竟会导致bug!又被PageHelper坑了

大家好,我是程序员木木熊。今天来复盘一个由PageHelper引起的多线程复用问题的排查和解决过程。让人难以相信的是,最终定位的原因竟然是,一个同事注释无用代码的时候少注释的一行导致的。不禁让木木熊和一起排查问题的同事感叹一句,坑爹啊!!

问题描述

1. PageHelper使用ThreadLocal来记录分页信息。调用startPage方法之后,分页信息被记录到ThreadLocal中,当执行完SQL后,会进行清除。

2. 如果线程A,仅仅是调用了startPage,但是并没有执行SQL或者是在执行startPage之后到执行SQL之前发生异常,导致并没有进入SQL执行的流程,那么分页信息不会清除。

3. A线程被另一个请求复用(http请求或dubbo请求等),page信息依然可以被读取。如果恰好请求中有执行SQL查询的逻辑,就会拼接上对应的SQL分页信息。

4. PageHelper判断是否需要进行分页信息拼接的skip()方法,仅判断ThreadLocal中的分页信息是否为空。如果出现2-3中描述的情况,就会导致正常的SQL拼接上不必要的分页息,而导致各种各样的异常

排查过程

1.发现问题

事情的起因是,最近企微的告警群里,时不时会有一个SQL异常的告警。根据堆栈描述来看是SQL的语法错误(bad SQL grammar),仔细查看SQL语句,发现结束的分号(;)后面跟着LIMIT语句,最终导致异常。

根据告警消息,去监控平台定位到详细堆栈信息。

看异常信息,怀疑是写的SQL本身有问题,那么只需根据堆栈信息找到对应的Mapper位置,修改对应SQL就可以解决这个问题。

Mapper中对应的代码如下

可以发现SQL拼写的过程中结尾只有分号(;),并未拼接任何的分页信息,说明SQL书写并没有问题。

(PS: 虽然这里结尾写个分号也挺奇怪的,不过可能每个人的习惯不一样吧)

其实从告警的频率也不难发现,这个接口并不是一直会报错,只有某些时候才会出现告警中的异常。那么说明问题是偶发的,问题的触发需要满足一定的条件。

到底是什么条件呢?问题排查陷入了僵局。

虽然不知道具体是为什么,但是有一个大致的方向,一定是有一个类似于切面或者拦截器一样的代码逻辑把分页信息拼接到了SQL后面。

2.问题定位

2.1 MyBatis拦截器

说到拦截器,我们先介绍一下MyBatis的拦截器

MyBatis允许使用者在映射语句执行过程中的某一些指定的节点进行拦截调用,通过织入拦截器,在不同节点修改一些执行过程中的关键属性,从而影响SQL的生成、执行和返回结果。

实际工作中,可以使用Mybatis拦截器来做一些数据过滤、数据加密脱敏、SQL执行时间性能监控和告警等。

通过IDEA查看子类的功能,看到Interceptor接口在系统中只有下面几个实现

系统中由自己实现的拦截器,只有一个用来对数据进行脱敏的CryptInterceptor。

这个拦截器的逻辑,并不会对SQL进行修改和调整。

剩下的应该就是由PageHelper实现的PageInterceptor和QueryInterceptor。

虽然拼接上的是分页信息,并且项目中多处使用了PageHelper进行分页处理,但是出问题的代码附近,并没有使用到PageHelper,这就让人摸不着头脑了。问题排查又被中断,故决定先扒一扒PageHepler的源码。

2.2 PageHelper源码分析

从PageHelper.startPage方法开始入手,发现分页信息会被存储在LOCAL_PAGE中,而LOCAL_PAGE使用的是ThreadLocal来实现。具体代码如下:

这个时候开始怀疑,可能是ThreadLocal使用不当,导致没有被清除掉,而发生线程安全问题。

那么什么时候会清理LOCAL_PAGE呢?继续跟踪代码。

发现afterAll方法中会调用clearPage(),而清除分页信息。

继续跟踪代码,会发现,代码回到了前面提到得PageInterceptor中,这个类的核心逻辑在intercept方法中。

如图所示,这个方法中比较核心的流程,主要在三个部分

  1. skip方法-判断是否需要进行分页

  2. ExecutorUtil.pageQuery执行查询(内部会拼接分页SQL)

  3. finally中调用afterAll方法(清理对应的分页信息)

我们看看skip方法,判断比较简单,仅仅是判断skip中是否包含page信息,也即LOCAL_CACHE中是否包含分页信息

afterAll方法的逻辑就是前面看到的clearPage()

ExecutorUtil.pageQuery执行过程中,会进行分页信息的拼接。具体拼接的逻辑在数据库方言类的getPageSql方法中,以MySQL数据库举例

这个"LIMIT ?"和日志中的报错SQL完全一样,肯定就是这里没错。

但是,木木熊看到这里,又陷入了迷茫。

既然LOCAL_CACHE清除的逻辑在finally中,为什么会没执行呢?即使执行SQL报错了也应该会执行呀?为什么还会保留分页信息呢?那前面对于ThreadLocal使用不当的猜想就不能闭环?实在是想不通想不通。

2.3 具体错误代码定位

只剩下最后一个笨办法了,一处一处的排查使用PageHelper的代码,看看有什么使用不当的地方。还好运气比较好,差不多尝试了4-5次,发现了下图的代码

这个应该是同事之前注释掉的,下面查询SQL的部分已经没在使用了,这个代码的逻辑也没有对数据库的查询操作,改成了查询ES(具体代码未给出)。

看到这里,感觉答案已经接近了,新机子哇伊兹莫一多滋(真相只有一个)。

这里虽然调用了startPage,把分页信息设置到了ThreadLocal中,但是并没有真正执行SQL操作,也不会进入到MyBatis拦截器的调用链路,也不会走到finally中清理分页信息。

这样一来,当有新的请求复用了这个线程,并且有对数据库进行了查询操作,就会通过skip方法的校验,莫名其妙的拼接上分页信息。如果是简单的查询sql,可能会出现查询出来的数据和想要的不一致,或者查多查少。而上面报错的SQL,恰巧因为是以分号(;)结尾的,拼接上分页"LIMIT ?"就会导致SQL语法错误而告警。

解决办法

没想到啊,竟然是因为同事少注释了一行代码而导致了bug。这个bug其实非常危险且难于定位,一方面,是偶发的,不能稳定复现(而且我们的日志切面会更改线程id。。。这个其实不太好,所以通过日志也不是很好定位);另一方面,因为线程复用的原因,影响范围可能是所有执行SQL查询的逻辑的地方。

对于这个问题,我们的项目里只需要把未注释掉的startPage代码注释掉就可以解决。但是如果是针对通用的处理逻辑,也可以通过切面(拦截器或者过滤器也可以)进行处理。

1.dubbo接口通用解决方案(SPI)

利用dubbo的SPI机制,实现一个Filter,在代码结束部分统一调用一下PageHelper.clearPage(),

(PS:这里也可以在方法invoke前调用)

具体代码如下

2.Controller接口通用解决方案

http接口,通过对Controller所在目录进行切面处理,在进入接口前调用PageHelper.clearPage(),

具体代码如下

经验总结

1. 规范ThreadLocal的使用,使用完后一定要进行remove;PageHelper.startPage后一定要紧跟对应的查询逻辑

2. 对于常见的技术,不能仅仅停留在使用层面,一定要深入理解其使用原理。不然就会出现本文描述的,仅仅是少注释了一行无用代码,却对系统产生了重大的影响

3. 对于偶发性问题,需要考虑是否由线程安全和线程复用引起

4. 对于不需要的代码,直接删掉就行,不建议通过注释来隐藏,代码记录在git提交记录中都能找到

这是程序员木木熊,来优快云后的第一篇文章,欢迎大家指正批评,共同学习交流~~

也可以关注公众号程序员木木熊,了解更多后端技术知识

参考文章:

一次因PageHelper引起的多线程复用问题的排查和解决

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值