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

简介: Apache Dubbo是Alibaba开源的高性能RPC框架,在国内有非常多的用户。 * Github: https://github.com/apache/incubator-dubbo * 文档:http://dubbo.incubator.apache.org/zh-cn/ Arthas是Alibaba开源的应用诊断利器,9月份开源以来,Github Star数三个月超过
+关注继续查看

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问题有帮助。

相关文章
|
16天前
|
Dubbo JavaScript 应用服务中间件
浏览器可直接访问 Dubbo、gRPC 后端微服务,Dubbo-js 首个alpha 版本来了!
浏览器可直接访问 Dubbo、gRPC 后端微服务,Dubbo-js 首个alpha 版本来了!
|
16天前
|
Dubbo JavaScript 应用服务中间件
浏览器可直接访问 Dubbo、gRPC 后端微服务,Dubbo-js 首个 alpha 版本来了!
Dubbo-js 已于 9 月份发布支持 Dubbo3 协议的首个 alpha 版本,它的发布将有机会彻底改变微服务前后端的架构与通信模式,让你能直接在浏览器页面或 web 服务器中访问后端 Dubbo、gRPC 服务。
|
21天前
|
Dubbo Java 应用服务中间件
掌握微服务:Spring Cloud 对比 Dubbo
Spring Cloud 框架为开发人员提供了快速构建健壮云应用程序的工具。我们还可以构建基于微服务的应用程序,例如配置管理、服务发现、断路器、智能路由、集群状态、微代理、控制总线、一次性令牌等。
|
SQL Dubbo 安全
从应用层到网络层排查 Dubbo 接口超时全记录
从应用层到网络层排查 Dubbo 接口超时全记录
|
XML 缓存 监控
一次漫长的dubbo网关内存泄露排查经历
在微服务架构中,不同的微服务有不同的网络地址,而客户端则是通过统一的地址进行调用,在客户端与服务端之间需要有一个通信的桥梁,这就产生了微服务网关。微服务网关可以连接客户端与微服务,提供统一的认证方式,管理接口的生命周期,做更好的负载均衡、熔断限流,提供方便的监控,提供统一的风控入口。
317 0
一次漫长的dubbo网关内存泄露排查经历
|
Dubbo IDE Java
排查dubbo接口重复注销问题,我发现了一个巧妙的设计
我在公司内负责自研的dubbo注册中心相关工作,群里经常接到业务方反馈dubbo接口注销报错。经排查,确定是同一个接口调用了两次注销接口导致,由于我们的注册中心注销接口不能重复调用,调用第二次会因为实例已经注销而报实例找不到的错误。 虽然这个报错仅会打印一条错误日志,不影响业务,但本着 follow through的精神,我决定还是一探究竟,更何况重复注销也增加了应用的结束时间,影响了发布回滚速度。
198 0
排查dubbo接口重复注销问题,我发现了一个巧妙的设计
|
消息中间件 存储 监控
Kafka 异步消息也会阻塞?记一次 Dubbo 频繁超时排查过程
线上某服务 A 调用服务 B 接口完成一次交易,一次晚上的生产变更之后,系统监控发现服务 B 接口频繁超时,后续甚至返回线程池耗尽错误 Thread pool is EXHAUSTED。因为服务 B 依赖外部接口,刚开始误以为外部接口延时导致,所以临时增加服务 B dubbo 线程池线程数量。配置变更之后,重启服务,服务恢复正常。一段时间之后,服务 B 再次返回线程池耗尽错误。这次深入排查问题之后,才发现 Kafka 异步发送消息阻塞了 dubbo 线程,从而导致调用超时。
Kafka 异步消息也会阻塞?记一次 Dubbo 频繁超时排查过程
|
Arthas 负载均衡 Dubbo
Arthas 定位 Dubbo 手动注册 Eureka 异常
很久没有写技术分享博客,因为发现一个好的工具确实有点忍不住分享一下,毕竟独乐乐不如众乐乐。这里需要说的主角就是 Artahs。Arthas 使用文档很详细,我这里主要记录一下使用 Arthas 的一点总结。
Arthas 定位 Dubbo 手动注册 Eureka 异常
|
Arthas Dubbo Cloud Native
Arthas | 定位线上 Dubbo 线程池满异常
Dubbo 线程池满异常应该是大多数 Dubbo 用户都遇到过的一个问题,本文以 Arthas 3.1.7 版本为例,介绍如何针对该异常进行诊断,主要使用到 dashboard / thread 两个指令。
Arthas | 定位线上 Dubbo 线程池满异常
|
Arthas Dubbo IDE
Arthas | 定位线上 Dubbo 线程池满异常
Dubbo 线程池满异常应该是大多数 Dubbo 用户都遇到过的一个问题,本文以 Arthas 3.1.7 版本为例,介绍如何针对该异常进行诊断,主要使用到 `dashboard` / `thread` 两个指令。
Arthas | 定位线上 Dubbo 线程池满异常
相关产品
云迁移中心
推荐文章
更多