请求耗时采样

Dubbo 请求耗时采样

功能说明

性能采样功能可以对 Dubbo 处理链路上的各处耗时进行检测，在出现超时的时候 ( usageTime / timeout > profilerWarnPercent * 100 ) 通过日志记录调用的耗时。

此功能分为 simple profiler 和 detail profiler 两个模式，其中 simple profiler 模式默认开启，detail profiler 模式默认关闭。 detail profiler 相较 simple profiler 模式多采集了每个 filter 的处理耗时、协议上的具体耗时等。在 simple profiler 模式下如果发现 Dubbo 框架内部存在耗时长的情况，可以开启 detail profiler 模式，以便更好地排查问题。

使用场景

需要对 Dubbo 请求的精确耗时进行采集分析的场景，如服务不明原因的超时等

使用方式

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

日志说明

日志中各字段的含义如下：

[Dubbo-Consumer] execute service 接口#方法 cost 实际耗时, this invocation almost (maybe already) timeout. Timeout: 超时时间
invocation context:
请求上下文
thread info: 
Start time: 开始请求时间（nano 时间）
+-[ Offset: 当前节点开始时间; Usage: 当前节点使用总耗时, 当前节点耗时比例 ] 当前节点描述
  +-[ Offset: 当前节点开始时间; Usage: 当前节点使用总耗时, 当前节点耗时比例 ] 当前节点描述

对于请求耗时这里以两个例子进行介绍：

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) ... 均为时间占位符

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

methodB() {
  do something (5)
  methodC (6)
  methodD (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) ... 均为时间占位符

simple profiler

Consumer 侧：

[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

Provider 侧：

[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