V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
hengyunabc
V2EX  ›  Java

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

  •  
  •   hengyunabc ·
    hengyunabc · 2018-12-07 10:22:23 +08:00 · 1916 次点击
    这是一个创建于 1938 天前的主题,其中的信息可能已经有所发展或是发生改变。

    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

    $ java -jar arthas-boot.jar
    * [1]: 43523 ServerDemoApplication
      [2]: 22342
      [3]: 44108 ClientDemoApplication
    1
    [INFO] arthas home: /Users/hengyunabc/.arthas/lib/3.0.5/arthas
    [INFO] Try to attach process 43523
    [INFO] Attach process 43523 success.
    [INFO] arthas-client connect 127.0.0.1 3658
      ,---.  ,------. ,--------.,--.  ,--.  ,---.   ,---.
     /  O  \ |  .--. ''--.  .--'|  '--'  | /  O  \ '   .-'
    |  .-.  ||  '--'.'   |  |   |  .--.  ||  .-.  |`.  `-.
    |  | |  ||  |\  \    |  |   |  |  |  ||  | |  |.-'    |
    `--' `--'`--' '--'   `--'   `--'  `--'`--' `--'`-----'
    
    wiki: https://alibaba.github.io/arthas
    version: 3.0.5
    pid: 43523
    time: 2018-12-05 16:23:52
    
    $
    

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

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

    在 demo 里,访问 http://localhost:8080/user/0,UserServiceImpl就会抛出一个异常,因为 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 包里加载的:

    $ sc -d org.apache.log4j.Logger
     class-info        org.apache.log4j.Logger
     code-source       /Users/hengyunabc/.m2/repository/org/slf4j/log4j-over-slf4j/1.7.25/log4j-over-slf4j-1.7.25.jar
     name              org.apache.log4j.Logger
     isInterface       false
     isAnnotation      false
     isEnum            false
     isAnonymousClass  false
     isArray           false
     isLocalClass      false
     isMemberClass     false
     isPrimitive       false
     isSynthetic       false
     simple-name       Logger
     modifier          public
     annotation
     interfaces
     super-class       +-org.apache.log4j.Category
                         +-java.lang.Object
     class-loader      +-sun.misc.Launcher$AppClassLoader@5c647e05
                         +-sun.misc.Launcher$ExtClassLoader@59878d35
     classLoaderHash   5c647e05
    
    Affect(row-cnt:1) cost in 126 ms.
    

    可以看到 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命令,可以减少这种麻烦,可以直接重放请求。

    $ tt -t com.example.UserServiceImpl findUser
    Press Ctrl+C to abort.
    Affect(class-cnt:1 , method-cnt:1) cost in 145 ms.
     INDEX      TIMESTAMP              COST(ms)      IS-RET     IS-EXP    OBJECT       CLASS              METHOD
    ----------------------------------------------------------------------------------------------------------------
     1000       2018-12-05 17:47:52    1.56523       true       false     0x3233483    UserServiceImpl    findUser
     1001       2018-12-05 17:48:03    0.286176      false      true      0x3233483    UserServiceImpl    findUser
     1002       2018-12-05 17:48:11    90.324335     true       false     0x3233483    UserServiceImpl    findUser
    

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

    $ tt --play -i 1000
     RE-INDEX       1000
     GMT-REPLAY     2018-12-05 17:55:50
     OBJECT         0x3233483
     CLASS          com.example.UserServiceImpl
     METHOD         findUser
     PARAMETERS[0]  @Integer[1]
     IS-RETURN      true
     IS-EXCEPTION   false
     RETURN-OBJ     @User[
                        id=@Integer[1],
                        name=@String[Deanna Borer],
                    ]
    Time fragment[1000] successfully replayed.
    Affect(row-cnt:1) cost in 4 ms.
    

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

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

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

    $ trace com.alibaba.dubbo.rpc.Filter *
    Press Ctrl+C to abort.
    Affect(class-cnt:19 , method-cnt:59) cost in 1441 ms.
    `---ts=2018-12-05 19:07:26;thread_name=DubboServerHandler-30.5.125.152:20880-thread-10;id=3e;is_daemon=true;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@5c647e05
        `---[8.435844ms] com.alibaba.dubbo.rpc.filter.EchoFilter:invoke()
            +---[0.124572ms] com.alibaba.dubbo.rpc.Invocation:getMethodName()
            +---[0.065123ms] java.lang.String:equals()
            `---[7.762928ms] com.alibaba.dubbo.rpc.Invoker:invoke()
                `---[7.494124ms] com.alibaba.dubbo.rpc.filter.ClassLoaderFilter:invoke()
                    +---[min=0.00355ms,max=0.049922ms,total=0.057637ms,count=3] java.lang.Thread:currentThread()
                    +---[0.0126ms] java.lang.Thread:getContextClassLoader()
                    +---[0.02188ms] com.alibaba.dubbo.rpc.Invoker:getInterface()
                    +---[0.004115ms] java.lang.Class:getClassLoader()
                    +---[min=0.003906ms,max=0.014058ms,total=0.017964ms,count=2] java.lang.Thread:setContextClassLoader()
                    `---[7.033486ms] com.alibaba.dubbo.rpc.Invoker:invoke()
                        `---[6.869488ms] com.alibaba.dubbo.rpc.filter.GenericFilter:invoke()
                            +---[0.01481ms] com.alibaba.dubbo.rpc.Invocation:getMethodName()
    

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

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

    $ jad com.alibaba.dubbo.common.bytecode.Wrapper1
    
    ClassLoader:
    +-sun.misc.Launcher$AppClassLoader@5c647e05
      +-sun.misc.Launcher$ExtClassLoader@59878d35
    
    Location:
    /Users/hengyunabc/.m2/repository/com/alibaba/dubbo/2.5.10/dubbo-2.5.10.jar
    
    package com.alibaba.dubbo.common.bytecode;
    
    public class Wrapper1
    extends Wrapper
    implements ClassGenerator.DC {
    
        public Object invokeMethod(Object object, String string, Class[] arrclass, Object[] arrobject) throws InvocationTargetException {
            UserServiceImpl userServiceImpl;
            try {
                userServiceImpl = (UserServiceImpl)object;
            }
            catch (Throwable throwable) {
                throw new IllegalArgumentException(throwable);
            }
            try {
                if ("findUser".equals(string) && arrclass.length == 1) {
                    return userServiceImpl.findUser(((Number)arrobject[0]).intValue());
                }
                if ("listUsers".equals(string) && arrclass.length == 0) {
                    return userServiceImpl.listUsers();
                }
                if ("findUserByName".equals(string) && arrclass.length == 1) {
                    return userServiceImpl.findUserByName((String)arrobject[0]);
                }
            }
    

    获取 Spring context

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

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

    $ ognl '#context=@com.alibaba.dubbo.config.spring.extension.SpringExtensionFactory@contexts.iterator.next, #context.getBean("userServiceImpl").findUser(1)'
    @User[
        id=@Integer[1],
        name=@String[Deanna Borer],
    ]
    
    • [email protected] 获取到SpringExtensionFactory里保存的 spring context 对象
    • #context.getBean("userServiceImpl").findUser(1) 获取到userServiceImpl再执行一次调用

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

    总结

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

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

    1 条回复    2018-12-07 10:37:58 +08:00
    huiyadanli
        1
    huiyadanli  
       2018-12-07 10:37:58 +08:00
    这文章很不错呐,刚好技术栈一样,最近也想试试 Arthas。
    关于   ·   帮助文档   ·   博客   ·   API   ·   FAQ   ·   我们的愿景   ·   实用小工具   ·   1214 人在线   最高记录 6543   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 28ms · UTC 23:14 · PVG 07:14 · LAX 16:14 · JFK 19:14
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.