转载

记一次AOP问题排查

背景和问题

情况是这样的:

由于某业务上的需求,需要数据库表T的数据发生变化时,通知给其它系统。

改造前,在各数据发生变化的业务节点,直接调用通知方法,将数据同步给其它系统;

改造后,使用了spring aop,基于抽象出的update方法,进行数据同步。

于是代码改成了这样:

##切面类
class NotifyXSystemAOP{
    //切面定义
    @Pointcut("execution(* com.xxx.updateMethod(com.xxx.XBean)) && args(record)")
    public void updatePointcut(XBean xBean){}

    //切面逻辑
    @After(value = "updatePointcut(record)",argNames = "xBean")
    public void afterUpdate(XBean xBean){
        //要将全量数据同步给兄弟系统,所以查了库
        xBean = xBeanMapper.selectByPrimaryKey(xBean.getId());
        
        //利用线程池,将数据同步至兄弟系统`XSystem`
        ThreadManager.executeTask(()-> {
            sendToXSystem(xBean);
        });
    }
}

##业务类关键方法
public void keyMethod(){
    ...
    xBean.setPropertyA(999);
    com.xxx.updateMethod(xBean);    //修改动作
    ...
}

看着一副还算合理的样子,测试时却发现 推送的 xBean 对象与数据库表T中的数据不一致 (比如 库中PropertyA字段=999,推送数据PropertyA=1

分析

发现问题后,先检查了切面中的逻辑,发现 切面中确实没有任何修改 XBean 的痕迹

而且从日志观察, 业务中的修改方法确实已经成功执行了 ,才进入了切面。

所以越发的觉得这个问题很诡异!

推理1:事务设置

众所周知,mysql默认的事务隔离级别是 可重复读 (Repeatable read),有没有可能是这样的?

业务方法中执行了修改,由于事务还没提交,所以切面中查询时没有获取到最新的属性值,而把旧版本数据推送给兄弟系统了。

有了思路,就进行求证喽。于是在切面方法中增加了日志:

@After(value = "updatePointcut(record)",argNames = "xBean")
public void afterUpdate(XBean xBean){
    log.info("查询前xBean={}",xBean);    //增加日志——查询前
    xBean = xBeanMapper.selectByPrimaryKey(xBean.getId());
    log.info("查询后xBean={}",xBean);   //增加日志——查询后

    ThreadManager.executeTask(()-> {
        sendToXSystem(xBean);
    });
}

如果确实如我们猜测,问题是由事务引起的,那么查询后和查询前的 PropertyA 属性值会不一样。

重新执行,观察日志,结论是:查询前后,PropertyA的值一样!也就证明——推论错误,凶手不是事务。

其实仔细想想,也能想明白。

代码里是在切面主线程中做的数据库查询。而切面AOP的本质是动态代理,那么一个代理对象,又在同一个线程中,先执行业务方法逻辑,再执行切面中切入的逻辑,如果没有什么特殊的事务控制,这些逻辑理应在一个事务当中。

通过新增的日志,发现xBean确实已经修改过了——新增日志中的xBean和数据库表的数据完全一致。

问题在于,只是到推送时( sendToXSystem(xBean)方法 处),某些属性,如PropertyA就发生了改变。

推理2:对象传递

于是有了第二种猜测,会不会切面在 推送数据过程中,业务方法中有修改逻辑

先来复习一波java参数传递的问题:

# 参数传递demo
void methodK(){
    Person person = new Person();
    person.setName("zhang3");

    changeName(person);    //传递person对象
    System.out.println(person);    //重写了person的toString方法
}

void changeName(Person person){
    person.setName("li4");    //方法内部修改了name属性
}

程序并不复杂,输出结果中:

name=li4

这不难解释,由于 changeName方法 中的person和 methodK方法 中的person 指向同一个对象 ,所以changeName的修改会导致name属性的变化。

记一次AOP问题排查

基于此,我猜测问题就出在这里,于是搜索了业务方法:

##业务类关键方法
public void keyMethod(){
    ...
    xBean.setPropertyA(999);
    com.xxx.updateMethod(xBean);    //修改动作
    ...
    xBean.setPropertyA(1);    //真的找到了这货
}

正所谓“成也参数传递,败也参数传递”。

思考一下好像有些不对,因为在切面方法中,一开始就重新修改了xBean对象的引用:

xBean = xBeanMapper.selectByPrimaryKey(xBean.getId());    //查库,修改了xBean的引用

还用前面的demo模拟,这相当于作了如下修改:

# 对象传递demo
void methodK(){
    Person person = new Person();
    person.setName("zhang3");

    changeName(person);    
    System.out.println(person);
}

void changeName(Person person){
    person = new Person();    //修改引用
    person.setName("li4");    
}

执行结果会变成:

name=zhang3

也就是说, 随着changeName方法重新修改了引用指向,致使 changeName方法 中的person和 methodK方法 中的person指向不同对象,因此changeName不能再改变methodK-person指向的对象了

记一次AOP问题排查

这个理论同样适用于我们遇到的问题,所以这也不能解释为什么推送数据发生变化了。

推理3:真正的凶手

不死心的我再次翻看了业务方法:

##业务类关键方法
public void keyMethod(){
    ...
    xBean.setPropertyA(999);
    com.xxx.updateMethod(xBean);    //修改动作,触发切面
    ...
    xBean.setPropertyA(1);    //赋值
}

PropertyA最终被赋值为1,而切面中最终推送的数据里PropertyA也等于1。

这有些过于巧合了吧,于是耐着性子再仔细找找:

##业务类关键方法
public void keyMethod(){
    ...
    xBean.setPropertyA(999);
    com.xxx.updateMethod(xBean);    //修改动作,触发切面
    ...
    xBean = xBeanMapper.selectByPrimaryKey(xBean.getId());    //又找到了这个
    ...
    xBean.setPropertyA(1);    
}

业务方法中,调用了和切面中同样的查询方法。我们用的orm框架是mybatis,而mybatis似乎有个一级缓存?

科普下什么是mybatis的一级缓存:

  • 在同一个sqlsession中,如果某查询sql已经执行过了,会将结果缓存,再次执行此查询sql时直接从缓存中获取结果,以提升性能。(当然,update等操作会作废一级缓存)

结合spring之后,sqlsession默认会和事务绑定。

那么情况应该是这样的:

代码中切面先从db中查询了结果,放入一级缓存中;之后业务逻辑再次执行同样的sql,由于缓存中已有结果,直接从缓存中获取(这里获取的对象和切面中相同)。之后业务逻辑重新赋值PropertyA,再之后切面中用另一个线程推送被修改的对象,完成绝杀。

解决方式简单粗暴,直接在切面中搞个副本就好:

@After(value = "updatePointcut(record)",argNames = "xBean")
public void afterUpdate(XBean xBean){
    xBean = xBeanMapper.selectByPrimaryKey(xBean.getId());
    
    xBean = BeanUtils.cloneBean(xBean);    //查询后创建副本

    ThreadManager.executeTask(()-> {
        sendToXSystem(xBean);
    });
}

最后总结一下吧:

这是一篇以aop勾引你进来,主打惊悚悬疑,中间夹杂事务隔离级别、对象参数传递和mybatis一级缓存的奇葩文章……

原文  https://segmentfault.com/a/1190000020446708
正文到此结束
Loading...