当Dubbo遇上Arthas:排查问题的实践

Apache Dubbo是Alibaba开源的高性能RPC框架,在国内有非常多的用户。

Arthas是Alibaba开源的应用诊断利器,9月份开源以来,Github Star数三个月超过6000。

当Dubbo遇上Arthas,会碰撞出什么样的火花呢?下面来分享Arthas排查Dubbo问题的一些经验。

dubbo-arthas-demo

下面的排查分享基于这个dubbo-arthas-demo,非常简单的一个应用,浏览器请求从Spring MVC到Dubbo Client,再发送到Dubbo Server。

Demo里有两个spring boot应用,可以先启动server-demo,再启动client-demo

 /user/{id} -> UserService -> UserServiceImpl Browser Dubbo Client Dubbo Server

Client端:

@RestController 
public class UserController { 
    @Reference(version = "1.0.0") 
    private UserService userService; 

    @GetMapping("/user/{id}") 
    public User findUserById(@PathVariable Integer id) {
       return userService.findUser(id); 
    } 
}

Server端:

@Service(version = "1.0.0") 
public class UserServiceImpl implements UserService { 
    @Override 
    public User findUser(int id) {
        if (id < 1) { 
            throw new IllegalArgumentException("user id < 1, id: " + id); 
        } 
        for (User user : users) { 
            if (user.getId() == id) {
               return user; 
            } 
        } throw new RuntimeException("Can not find user, id: " + id); 
    }
}

Arthas快速开始

$ wget https://alibaba.github.io/arthas/arthas-boot.jar

$ java -jar arthas-boot.jar

启动后,会列出所有的java进程,选择1,然后回车,就会连接上ServerDemoApplication

QQ20181220-101211@2x

Dubbo线上服务抛出异常,怎么获取调用参数?

当线上服务抛出异常时,最着急的是什么参数导致了抛异常?

在demo里,访问 http://localhost:8080/user/0UserServiceImpl就会抛出一个异常,因为user id不合法。

在Arthas里执行 watch com.example.UserService * -e -x 2 '{params,throwExp}' ,然后再次访问,就可以看到watch命令把参数和异常都打印出来了。

$ watch com.example.UserService * -e -x 2 ‘{params,throwExp}’

Press Ctrl+C to abort.

Affect(class-cnt:1 , method-cnt:4) cost in 230 ms.

ts=2018-12-05 16:26:44; [cost=3.905523ms] result=@ArrayList[

@Object[][

@Integer[0],

], java.lang.IllegalArgumentException: user id < 1, id: 0

at com.example.UserServiceImpl.findUser(UserServiceImpl.java:24)

at com.alibaba.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java)

at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:45)

at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:71)

at com.alibaba.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:48)

at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:52)

at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:61)

怎样线上调试Dubbo服务代码?

在本地开发时,可能会用到热部署工具,直接改代码,不需要重启应用。但是在线上环境,有没有办法直接动态调试代码?比如增加日志。

在Arthas里,可以通过redefine命令来达到线上不重启,动态更新代码的效果。

比如我们修改下UserServiceImpl,用System.out打印出具体的User对象来:

public User findUser(int id) {

    if (id < 1) {

       throw new IllegalArgumentException(“user id < 1, id: “ + id);

}

    for (User user : users) {

        if (user.getId() == id) {

System.out.println(user);

            return user;

}

}

    throw new RuntimeException(“Can not find user, id: “ + id);

}

本地编绎后,把server-demo/target/classes/com/example/UserServiceImpl.class传到线上服务器,然后用redefine命令来更新代码:

$ redefine -p /tmp/UserServiceImpl.class redefine success, size: 1

这样子更新成功之后,访问 http://localhost:8080/user/1 ,在ServerDemoApplication的控制台里就可以看到打印出了user信息。

怎样动态修改Dubbo的logger级别?

在排查问题时,需要查看到更多的信息,如果可以把logger级别修改为DEBUG,就非常有帮助。

ognl是apache开源的一个轻量级表达式引擎。下面通过Arthas里的ognl命令来动态修改logger级别。

首先获取Dubbo里TraceFilter的一个logger对象,看下它的实现类,可以发现是log4j。

$ ognl ‘@com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter@logger.logger’

@Log4jLogger[

FQCN=@String[com.alibaba.dubbo.common.logger.support.FailsafeLogger],

logger=@Logger[org.apache.log4j.Logger@2f19bdcf],

]

再用sc命令来查看具体从哪个jar包里加载的:

QQ20181220-101850@2x

可以看到log4j是通过slf4j代理的。

那么通过org.slf4j.LoggerFactory获取root logger,再修改它的level:

$ ognl ‘@org.slf4j.LoggerFactory@getLogger(“root”).setLevel(@ch.qos.logback.classic.Level@DEBUG)’ null $ ognl ‘@org.slf4j.LoggerFactory@getLogger(“root”).getLevel().toString()’ @String[DEBUG]

可以看到修改之后,root logger的level变为DEBUG

怎样减少测试小姐姐重复发请求的麻烦?

在平时开发时,可能需要测试小姐姐发请求过来联调,但是我们在debug时,可能不小心直接跳过去了。这样子就尴尬了,需要测试小姐姐再发请求过来。

Arthas里提供了tt命令,可以减少这种麻烦,可以直接重放请求。

QQ20181220-102056@2x

上面的tt -t命令捕获到了3个请求。然后通过tt --play可以重放请求:

QQ20181220-102352@2x

Dubbo运行时有哪些Filter? 耗时是多少?

Dubbo运行时会加载很多的Filter,那么一个请求会经过哪些Filter处理,Filter里的耗时又是多少呢?

通过Arthas的trace命令,可以很方便地知道Filter的信息,可以看到详细的调用栈和耗时。

QQ20181220-102432@2x

Dubbo动态代理是怎样实现的?

通过Arthas的jad命令,可以看到Dubbo通过javaassist动态生成的Wrappr类的代码:

QQ20181220-102524@2x

获取Spring context

除了上面介绍的一些排查技巧,下面分享一个获取Spring Context,然后“为所欲为”的例子。

在Dubbo里有一个扩展com.alibaba.dubbo.config.spring.extension.SpringExtensionFactory,把Spring Context保存到了里面。 因此,我们可以通过ognl命令获取到。

QQ20181220-102607@2x

  • SpringExtensionFactory@contexts.iterator.next 获取到SpringExtensionFactory里保存的spring context对象
  • #context.getBean("userServiceImpl").findUser(1) 获取到userServiceImpl再执行一次调用

只要充分发挥想像力,组合Arthas里的各种命令,可以发挥出神奇的效果。

总结

本篇文章来自杭州Dubbo Meetup的分享《当DUBBO遇上Arthas – 排查问题的实践》,希望对大家线上排查Dubbo问题有帮助。

分享的PDF可以在 https://github.com/alibaba/arthas/issues/327 里下载。

推荐文章

沪公网安备 31010702002009号