转载

记一次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

正文到此结束