請求耗時採樣

Dubbo 3 請求耗時採樣

功能說明

效能採樣功能可以檢測 Dubbo 處理鏈路各個部分的耗時情況，當發生超時時，會通過日誌記錄 ( usageTime / timeout > profilerWarnPercent * 100 ) 的呼叫耗時。

該功能分為 simple profiler 和 detail profiler 兩種模式，其中 simple profiler 模式預設開啟，detail profiler 模式預設關閉。與 simple profiler 模式相比，detail profiler 會收集更多每個 filter 的處理耗時、具體協議的耗時等資訊。在 simple profiler 模式下，如果發現 Dubbo 框架內部存在耗時較長的情況，可以開啟 detail profiler 模式，以便更好地排查問題。

使用場景

需要收集和分析 Dubbo 請求精準耗時的場景，例如服務超時原因不明等。

使用方法

simple profiler 預設自動開啟，對於處理時間超過超時時間 3/4 的請求，會通過日誌列印出慢呼叫資訊。如果需要開啟 detail profiler 模式或者修改超時告警比例，可以參考效能採樣指令文件。

輸出範例

日誌說明

日誌中各個欄位的含義如下

[Dubbo-Consumer] execute service interface#method cost actual time-consuming, this invocation almost (maybe already) timeout. Timeout: timeout
invocation context:
request context
thread info:
Start time: start request time (nano time)
+-[ Offset: the start time of the current node; Usage: the total time spent on the current node, the time-consuming ratio of the current node ] Description of the current node
  +-[ Offset: the start time of the current node; Usage: the total time spent on the current node, the time-consuming ratio of the current node ] Description of the current node

針對請求耗時，這裡舉兩個例子

methodA() {
  do something (1)
  methodB (2)
  do something (3)
}

methodB() {
  do something (4)
  methodC (5)
  do something (6)
}

methodC() {
  do something (7)
}
 
+-[ Offset: 0 ms; Usage: (1) + (2) + (3) ms] execute methodA
  +-[ Offset: (1) ms; Usage: (4) + (5) + (6) = (2) ms ] execute methodB
    +-[ Offset: (1) + (4) ms; Usage: (7) = (5) ms ] execute methodC
    
(1) (2) (3) ... are all time placeholders

methodA() {
  do something (1)
  methodB (2)
  methodE (3)
  do something (4)
}

methodB() {
  do something (5)
  methodC (6)
  method D (7)
  do something (8)
}

methodC() {
  do something (9)
}

methodD() {
  do something (10)
}

methodE() {
  do something (11)
}
 
+-[ Offset: 0 ms; Usage: (1) + (2) + (3) + (4) ms] execute methodA
  +-[ Offset: (1) ms; Usage: (5) + (6) + (7) + (8) = (2) ms ] execute methodB
    +-[ Offset: (1) + (5) ms; Usage: (9) = (6) ms ] execute methodC
    +-[ Offset: (1) + (5) + (6) ms; Usage: (10) = (7) ms ] execute methodD
  +-[ Offset: (1) + (2) ms; Usage: (11) = (3) ms ] execute methodE
    
(1) (2) (3) ... are all time placeholders

simple profiler

消費者端

[19/07/22 07:08:35:035 CST] main WARN proxy.InvokerInvocationHandler: [DUBBO] [Dubbo-Consumer] execute service org.apache.dubbo.samples.api.GreetingsService#sayHi cost 1003.015746 ms, this invocation almost (maybe already) timeout. Timeout: 1000ms
invocation context:
path=org.apache.dubbo.samples.api.GreetingsService;
remote.application=first-dubbo-consumer;
interface=org.apache.dubbo.samples.api.GreetingsService;
version=0.0.0;
timeout=1000;
thread info:
Start time: 285821581299853
+-[ Offset: 0.000000ms; Usage: 1003.015746ms, 100% ] Receive request. Client invoke begin. ServiceKey: org.apache.dubbo.samples.api.GreetingsService MethodName:sayHi
  +-[ Offset: 7.987015ms; Usage: 994.207928ms, 99% ] Invoker invoke. Target Address: xx.xx.xx.xx:20880, dubbo version: 3.0.10-SNAPSHOT, current host: xx.xx.xx. xx

供應者端

[19/07/22 07:08:35:035 CST] DubboServerHandler-30.227.64.173:20880-thread-2 WARN filter.ProfilerServerFilter: [DUBBO] [Dubbo-Provider] execute service org.apache.dubbo.samples.api .GreetingsService:0.0.0#sayHi cost 808.494672 ms, this invocation almost (maybe already) timeout. Timeout: 1000ms
client: xx.xx.xx.xx:51604
invocation context:
input=281;
path=org.apache.dubbo.samples.api.GreetingsService;
remote.application=first-dubbo-consumer;
dubbo=2.0.2;
interface=org.apache.dubbo.samples.api.GreetingsService;
version=0.0.0;
timeout=1000;
thread info:
Start time: 285821754461125
+-[ Offset: 0.000000ms; Usage: 808.494672ms, 100% ] Receive request. Server invoke begin.
  +-[ Offset: 1.030912ms; Usage: 804.236342ms, 99% ] Receive request. Server biz impl invoke begin., dubbo version: 3.0.10-SNAPSHOT, current host: xx.xx.xx.xx

detail profiler