Arthas 灵异事件 tt、watch、monitor 执行两次问题排查

一、事件还原

我在做项目的性能测试，用 arthas 查询耗时接口方法。监控 DocHandler 接口耗时，它有多个实现类。

我们都知道，正常情况下，trace、tt、monitor、watch 都是只会有一个请求结果，而这个方法，每次却都是两次，这就让人很疑惑了。

monitor 两次请求

tt 两次请求

tt -i xx 结果是一样，只是每次请求的耗时不一样。

watch 两次请求

二、代码还原

接口定义

public interface DocHandler<T> {
    T execute(DocParam param) throws Exception;
    List<DocColumn> columns();
}

其中一个实现类
/**
 * 商品-基本信息
 *
 * @author tingfeng
 */
@Component
public class ItemBaseHandler implements DocHandler {

    @Override
    public ItemBaseModel execute(DocParam param) throws Exception{
        ItemBaseModel model = new ItemBaseModel();
        // ...
        return model;
    }

    @Override
    public List<DocColumn> columns() {
        return DocUtil.getDocColumn(new ItemBaseModel());
    }
}

接口有个 execute 方法，返回一个泛型对象。
实现类实现 execute 方法，返回一个自身处理业务逻辑的 ItemBaseModel。

从代码上来看，结构非常的简单，没什么可以的地方。

三、排查之路

（1）新增实现类测试

新增 DemoHandler 同样实现 DocHandler 接口。

@Component
public class DemoHandler implements DocHandler {

    @Override
    public Object execute(DocParam param) throws Exception {
        TimeUnit.SECONDS.sleep(1);
        logger.info("xxx");
        return "";
    }

    @Override
    public List<DocColumn> columns() {
        System.out.println("come in demo columns");
        return null;
    }
}

修改调用方法，保持和其他实现类环境一样

DocHandler demo = handlerFactory.generate("demoHandler");
demo.execute(null);

DocHandler item = handlerFactory.generate("itemBaseHandler");
item.execute(null);

（2）重新 arthas 监控测试

trace 各一次，正常

tt demoHandler 一次、ItemBaseHander 两次

monitor demoHandler 一次、ItemBaseHander 两次

watch ItemBaseHander 两次

结论：从这次的测试来看，DemoHandler 都是正常的一次，但是同样的环境 ItemBaseHandler 确是两次，这就奇了怪了。是哪里出了问题呢？

（3）查看加载类方法

观察 DemoHandler 和 ItemBaseHandler 代码编译后的加载

使用 sm 命令：查看已加载类的方法信息

[arthas@89141]$ sm com.helijia.platform.search.index.handler.DocHandler | grep ItemBaseHandler
com.helijia.platform.search.index.handler.impl.ItemBaseHandler <init>()V
com.helijia.platform.search.index.handler.impl.ItemBaseHandler execute(Lcom/helijia/platform/search/index/model/DocParam;)Ljava/lang/Object;
com.helijia.platform.search.index.handler.impl.ItemBaseHandler execute(Lcom/helijia/platform/search/index/model/DocParam;)Lcom/helijia/platform/search/index/handler/model/ItemBaseModel;
com.helijia.platform.search.index.handler.impl.ItemBaseHandler columns()Ljava/util/List;

[arthas@89141]$ sm com.helijia.platform.search.index.handler.DocHandler | grep DemoHandler
com.helijia.platform.search.index.handler.impl.DemoHandler <init>()V
com.helijia.platform.search.index.handler.impl.DemoHandler execute(Lcom/helijia/platform/search/index/model/DocParam;)Ljava/lang/Object;
com.helijia.platform.search.index.handler.impl.DemoHandler columns()Ljava/util/List;

由此可以看出：当返回值与接口定义返回的 Object 不一致时候，会编译成两个方法。

（4）是不是这个问题呢？

再次测试，把返回的 Object 类型调整为返回一个Java Bean（Demo）

@Data
public class Demo {
    private String id;
}

@Override
public Demo execute(DocParam param) throws Exception {
    TimeUnit.SECONDS.sleep(1);
    logger.info("xxx");
    return new Demo();
}

再次测试，果然，是这个问题没错了。

四、总结

由此猜测 arthas 应该是对两个方法都做了耗时统计。（是否如此还需要官方解答）

[arthas@89141]$ sm  -d com.helijia.platform.search.index.handler.impl.DemoHandler execute
 declaring-class  com.helijia.platform.search.index.handler.impl.DemoHandler
 method-name      execute
 modifier         public
 annotation
 parameters       com.helijia.platform.search.index.model.DocParam
 return           java.lang.Object
 exceptions       java.lang.Exception
 classLoaderHash  4a6b5156

Affect(row-cnt:1) cost in 59 ms.
[arthas@89141]$
[arthas@89141]$ sm  -d com.helijia.platform.search.index.handler.impl.ItemBaseHandler execute
 declaring-class  com.helijia.platform.search.index.handler.impl.ItemBaseHandler
 method-name      execute
 modifier         public,volatile
 annotation
 parameters       com.helijia.platform.search.index.model.DocParam
 return           java.lang.Object
 exceptions       java.lang.Exception
 classLoaderHash  4a6b5156

 declaring-class  com.helijia.platform.search.index.handler.impl.ItemBaseHandler
 method-name      execute
 modifier         public
 annotation
 parameters       com.helijia.platform.search.index.model.DocParam
 return           com.helijia.platform.search.index.handler.model.ItemBaseModel
 exceptions       java.lang.Exception
 classLoaderHash  4a6b5156

Affect(row-cnt:2) cost in 57 ms.
[arthas@89141]$

总结

arthas 你真是个小宝贝儿。

未经允许请勿转载：程序喵 » Arthas 灵异事件 tt、watch、monitor 执行两次问题排查

程序喵