Skip to content

分享及其资料:当DUBBO遇上Arthas - 排查问题的实践 #327

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
hengyunabc opened this issue Dec 1, 2018 · 11 comments
Closed

Comments

@hengyunabc
Copy link
Collaborator

hengyunabc commented Dec 1, 2018

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/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包里加载的:

$ 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],
]
  • SpringExtensionFactory@contexts.iterator.next 获取到SpringExtensionFactory里保存的spring context对象
  • #context.getBean("userServiceImpl").findUser(1) 获取到userServiceImpl再执行一次调用

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

总结

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

@oldratlee oldratlee changed the title 当DUBBO遇上Arthas-排查问题的实践 分享及其资料:当DUBBO遇上Arthas - 排查问题的实践 Dec 4, 2018
@lixyou
Copy link

lixyou commented Dec 7, 2018

why can't I download the pdf?

@hengyunabc
Copy link
Collaborator Author

why can't I download the pdf?

更新了,在文章的最后面

@tolyzty
Copy link

tolyzty commented Jan 17, 2019

非常棒啊

@lonelystone545
Copy link

感觉对于排查线上异常的作用不是那么大,一般都是可以通过日志进行定位的,不知道我的理解对不对额?

@shaozhengmao
Copy link

加群人数已经到上限了

@hengyunabc
Copy link
Collaborator Author

加群人数已经到上限了

钉钉群在申请扩容,估计这周四可以扩好

@liugddx
Copy link

liugddx commented Sep 6, 2019

ognl基本是java.lang.ClassNotFoundException
image

@liugddx
Copy link

liugddx commented Sep 6, 2019

ognl基本是java.lang.ClassNotFoundException
image

使用的就是demo-arthas-spring-boot-0.0.1-SNAPSHOT.jar

@kayleyang
Copy link

请问如何获取dubbo protocol、provider、consumer的配置信息呢?

@tain198127
Copy link

arthas 在trace dubbo的泛化调用( i n v o k e ) ,这个该怎么办啊?
IT is not work when debug dubbo general i n v o k e w i t h a r t h a s , i t s h o w a e r r o r m e s s a g e f o r s p e c i a l c h a r . How deal with it?

@hengyunabc
Copy link
Collaborator Author

arthas 在trace dubbo的泛化调用( i n v o k e ) ,这个该怎么办啊?
IT is not work when debug dubbo general i n v o k e w i t h a r t h a s , i t s h o w a e r r o r m e s s a g e f o r s p e c i a l c h a r . How deal with it?

'包起来。

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants