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

一、事件还原

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

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

monitor 两次请求

图像2020-6-4 下午5.34.jpeg

tt 两次请求

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

watch 两次请求

图像2020-6-4 下午5.34 (2).jpeg

二、代码还原

接口定义

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 各一次,正常

图像2020-6-4 下午5.34 (3).jpeg

tt demoHandler 一次、ItemBaseHander 两次

图像2020-6-4 下午5.35.jpeg

monitor demoHandler 一次、ItemBaseHander 两次

图像2020-6-4 下午5.35 (1).jpeg

watch ItemBaseHander 两次

图像2020-6-4 下午5.35 (2).jpeg

结论:从这次的测试来看,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;

图像2020-6-4 下午5.35 (3).jpeg

由此可以看出: 当返回值与接口定义返回的 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();
}

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

图像2020-6-4 下午5.35 (4).jpeg

四、总结

由此猜测 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 执行两次问题排查

点  赞 (0) 打  赏
分享到: