當DUBBO遇上Arthas - 排查問題的實踐

橫雲斷嶺發表於2018-12-06

Apache Dubbo是Alibaba開源的高效能RPC框架，在國內有非常多的使用者。

Github: github.com/apache/incu…
文件：dubbo.incubator.apache.org/zh-cn/

Arthas是Alibaba開源的應用診斷利器，9月份開源以來，Github Star數三個月超過6000。

Github: github.com/alibaba/art…
文件：alibaba.github.io/arthas/
Arthas開源交流QQ群: 916328269
Arthas開源交流釘釘群: 21965291

當Dubbo遇上Arthas，會碰撞出什麼樣的火花呢？下面來分享Arthas排查Dubbo問題的一些經驗。

dubbo-arthas-demo

下面的排查分享基於這個dubbo-arthas-demo，非常簡單的一個應用，瀏覽器請求從Spring MVC到Dubbo Client，再傳送到Dubbo Server。

Demo裡有兩個spring boot應用，可以先啟動server-demo，再啟動client-demo。

github.com/hengyunabc/…

  /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快速開始

alibaba.github.io/arthas/inst…

$ 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線上服務丟擲異常，怎麼獲取呼叫引數？

alibaba.github.io/arthas/watc…

當線上服務丟擲異常時，最著急的是什麼引數導致了拋異常？

在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服務程式碼?

alibaba.github.io/arthas/rede…

在本地開發時，可能會用到熱部署工具，直接改程式碼，不需要重啟應用。但是線上上環境，有沒有辦法直接動態除錯程式碼？比如增加日誌。

在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。

怎樣減少測試小姐姐重複發請求的麻煩?

alibaba.github.io/arthas/tt.h…

在平時開發時，可能需要測試小姐姐發請求過來聯調，但是我們在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? 耗時是多少?

alibaba.github.io/arthas/trac…

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動態代理是怎樣實現的?

alibaba.github.io/arthas/jad.…
com.alibaba.dubbo.common.bytecode.Wrapper

通過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問題有幫助。

分享的PDF可以在 github.com/alibaba/art… 裡下載。

Arthas 實踐——生產環境排查 CPU 飈高問題
2020-11-30
Arthas實踐–快速排查SpringBoot應用404/401問題
2019-01-10
Spring Boot
Java線上問題排查神器Arthas實戰分析
2022-01-29
Java
線上問題排查神器入門——Arthas
2021-08-16
老遊戲遇上新問題：當動森遇上詐騙
2020-04-10
遊戲
線上FullGC問題排查實踐——手把手教你排查線上問題
2023-05-05
GC
Arthas實踐–使用redefine排查應用奇怪的日誌來源
2019-01-19
Arthas常用功能及一次線上問題排查
2022-05-16
Java 線上問題排查神器 Arthas 快速上手與原理淺談
2020-06-12
Java
Java線上問題排查神器Arthas快速上手與原理淺談
2020-08-25
Java
一次線上CPU高的問題排查實踐
2019-06-23
線上問題排查，一不小心踩到阿里的 arthas坑了
2020-10-27
阿里
詳說TCP重傳問題的排查思路與實踐
2020-01-04
TCP
windows系統相關命令及問題排查實踐
2019-01-05
Windows
深入Spring Boot--使用Arthas排查應用404/401問題
2019-01-07
Spring Boot
網易雲信 RTC 音訊問題排查的挑戰與實踐
2023-05-10
音訊
中原銀行 Arthas 實踐之路
2020-06-12
當Spark遇上TensorFlow分散式深度學習框架原理和實踐
2018-04-16
Spark分散式深度學習框架
當雲原生閘道器遇上圖資料庫，NebulaGraph 的 APISIX 最佳實踐
2022-12-28
資料庫API
應用系統瓶頸排查和分析的思考-Arthas 實戰
2020-09-03
深入SpringBoot：利用Arthas排查NoSuchMethodError
2018-09-27
Spring BootError
當 Rust 遇上 Fedora
2021-09-09
Rust
當UIColor遇上Swift
2018-01-03
UISwift
當 React 遇上 KendoUI
2014-09-29
ReactUI
當UIColor遇上 Swift
2016-03-02
UISwift
當transition遇上display
2016-01-13
java問題排查
2020-10-30
Java
JVM 問題排查
2016-05-31
JVM
[分散式][Dubbo]Dubbo常見問題
2019-03-20
分散式
記 Arthas 實現一次 CPU 排查與程式碼熱更新
2020-09-03
Proxyless Mesh 在 Dubbo 中的實踐
2023-01-03
當 Go 遇上了 Lua
2019-03-12
Go
當 Go struct 遇上 Mutex
2021-04-21
GoStructMutex
當 bind 遇上 apply
2017-09-26
APP
當GridSearch遇上XGBoost 一段程式碼解決調參問題
2018-08-17
React Native在Android當中實踐（五）——常見問題
2018-10-10
React NativeAndroid
SDK與問題排查
2021-11-24
使用 Arthas 排查 SpringBoot 詭異耗時的 Bug
2021-03-15
Spring Boot