请求耗时采样

Dubbo 3 请求耗时采样

功能描述

性能采样功能可以检测 Dubbo 处理链路各个环节的耗时，当发生超时时，( usageTime / timeout > profilerWarnPercent * 100 ) 会通过日志记录调用耗时。

该功能分为简单采样和详细采样两种模式，其中简单采样模式默认开启，详细采样模式默认关闭。相比简单采样模式，详细采样模式会收集更多每个过滤器处理的耗时、具体协议耗时等信息。在简单采样模式下，如果发现 Dubbo 框架内部存在长时间耗时情况，可以开启详细采样模式，以便更好地排查问题。

使用场景

需要收集和分析 Dubbo 请求精确耗时的场景，例如服务超时原因不明等。

使用方法

简单采样默认自动开启，对于处理时间超过超时时间 3/4 的请求，会通过日志打印慢调用信息。如果需要开启详细采样模式或修改超时报警比例，可以参考性能采样命令文档。

输出示例

日志描述

日志中每个字段的含义如下

[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

简单采样

消费者端

[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

详细采样