Request Timing Sampling

Dubbo Request Timing Sampling

The performance sampling feature can detect the time spent at various points in the Dubbo processing chain, logging the call duration when a timeout occurs ( usageTime / timeout > profilerWarnPercent * 100 ).

This feature has two modes: simple profiler and detail profiler, where the simple profiler mode is enabled by default and the detail profiler mode is disabled by default. The detail profiler collects more data, such as the processing time of each filter and specific protocol timing. If long processing times are detected in the Dubbo framework while in simple profiler mode, you can enable detail profiler mode to better troubleshoot issues.

Usage Scenarios

Scenarios that require precise timing analysis of Dubbo requests, such as unexplained service timeouts.

Usage

The simple profiler is automatically enabled by default, and for requests exceeding three-quarters of the timeout duration, slow call information will be logged. To enable detail profiler mode or modify the timeout alert ratio, refer to the performance sampling command documentation.

Log Description

The meanings of various fields in the log are as follows:

  1. [Dubbo-Consumer] execute service interface#method cost actual time spent, this invocation almost (maybe already) timeout. Timeout: timeout duration
  2. invocation context:
  3. request context
  4. thread info: 
  5. Start time: request start time (nano time)
  6. +-[ Offset: current node start time; Usage: total time spent at current node, current node time spent ratio ] current node description
  7.   +-[ Offset: current node start time; Usage: total time spent at current node, current node time spent ratio ] current node description

Here are two examples for request timing:

  1. methodA() {
  2.   do something (1)
  3.   methodB (2)
  4.   do something (3)
  5. }
  7. methodB() {
  8.   do something (4)
  9.   methodC (5)
  10.   do something (6)
  11. }
  13. methodC() {
  14.   do something (7)
  15. }
  17. +-[ Offset: 0 ms; Usage: (1) + (2) + (3) ms] execute methodA
  18.   +-[ Offset: (1) ms; Usage: (4) + (5) + (6) = (2) ms ] execute methodB
  19.     +-[ Offset: (1) + (4) ms; Usage: (7) = (5) ms ] execute methodC
  21. (1) (2) (3) ... are all time placeholders
  1. methodA() {
  2.   do something (1)
  3.   methodB (2)
  4.   methodE (3)
  5.   do something (4)
  6. }
  8. methodB() {
  9.   do something (5)
  10.   methodC (6)
  11.   methodD (7)
  12.   do something (8)
  13. }
  15. methodC() {
  16.   do something (9)
  17. }
  19. methodD() {
  20.   do something (10)
  21. }
  23. methodE() {
  24.   do something (11)
  25. }
  27. +-[ Offset: 0 ms; Usage: (1) + (2) + (3) + (4) ms] execute methodA
  28.   +-[ Offset: (1) ms; Usage: (5) + (6) + (7) + (8) = (2) ms ] execute methodB
  29.     +-[ Offset: (1) + (5) ms; Usage: (9) = (6) ms ] execute methodC
  30.     +-[ Offset: (1) + (5) + (6) ms; Usage: (10) = (7) ms ] execute methodD
  31.   +-[ Offset: (1) + (2) ms; Usage: (11) = (3) ms ] execute methodE
  33. (1) (2) (3) ... are all time placeholders

Simple Profiler

Consumer Side:

  1. [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
  2. invocation context:
  3. path=org.apache.dubbo.samples.api.GreetingsService;
  4. remote.application=first-dubbo-consumer;
  5. interface=org.apache.dubbo.samples.api.GreetingsService;
  6. version=0.0.0;
  7. timeout=1000;
  8. thread info: 
  9. Start time: 285821581299853
  10. +-[ Offset: 0.000000ms; Usage: 1003.015746ms, 100% ] Receive request. Client invoke begin. ServiceKey: org.apache.dubbo.samples.api.GreetingsService MethodName:sayHi
  11.   +-[ 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 Side:

  1. [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
  2. client: xx.xx.xx.xx:51604
  3. invocation context:
  4. input=281;
  5. path=org.apache.dubbo.samples.api.GreetingsService;
  6. remote.application=first-dubbo-consumer;
  7. dubbo=2.0.2;
  8. interface=org.apache.dubbo.samples.api.GreetingsService;
  9. version=0.0.0;
  10. timeout=1000;
  11. thread info: 
  12. Start time: 285821754461125
  13. +-[ Offset: 0.000000ms; Usage: 808.494672ms, 100% ] Receive request. Server invoke begin.
  14.   +-[ 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

Consumer Side:

  1. [19/07/22 07:10:59:059 CST] main  WARN proxy.InvokerInvocationHandler:  [DUBBO] [Dubbo-Consumer] execute service org.apache.dubbo.samples.api.GreetingsService#sayHi cost 990.828336 ms, this invocation almost (maybe already) timeout. Timeout: 1000ms
  2. invocation context:
  3. path=org.apache.dubbo.samples.api.GreetingsService;
  4. remote.application=first-dubbo-consumer;
  5. interface=org.apache.dubbo.samples.api.GreetingsService;
  6. version=0.0.0;
  7. timeout=1000;
  8. thread info: 
  9. Start time: 285965458479241
  10. +-[ Offset: 0.000000ms; Usage: 990.828336ms, 100% ] Receive request. Client invoke begin. ServiceKey: org.apache.dubbo.samples.api.GreetingsService MethodName:sayHi
  11.   +-[ Offset: 0.852044ms; Usage: 989.899439ms, 99% ] Filter org.apache.dubbo.rpc.cluster.filter.support.ConsumerContextFilter invoke.
  12.      +-[ Offset: 1.814858ms; Usage: 988.924876ms, 99% ] Filter org.apache.dubbo.rpc.protocol.dubbo.filter.FutureFilter invoke.
  13.         +-[ Offset: 1.853211ms; Usage: 988.877928ms, 99% ] Filter org.apache.dubbo.monitor.support.MonitorClusterFilter invoke.
  14.            +-[ Offset: 1.873243ms; Usage: 988.661708ms, 99% ] Filter org.apache.dubbo.rpc.cluster.router.RouterSnapshotFilter invoke.
  15.               +-[ Offset: 2.159140ms; Usage: 0.504939ms, 0% ] Router route.
  16.               +-[ Offset: 8.125823ms; Usage: 981.748366ms, 99% ] Cluster org.apache.dubbo.rpc.cluster.support.FailoverClusterInvoker invoke.
  17.                  +-[ Offset: 8.258359ms; Usage: 981.612033ms, 99% ] Invoker invoke. Target Address: xx.xx.xx.xx:20880, dubbo version: 3.0.10-SNAPSHOT, current host: xx.xx.xx.xx

Provider Side:

  1. [19/07/22 07:10:59:059 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 811.017347 ms, this invocation almost (maybe already) timeout. Timeout: 1000ms
  2. client: xx.xx.xx.xx:52019
  3. invocation context:
  4. input=281;
  5. path=org.apache.dubbo.samples.api.GreetingsService;
  6. remote.application=first-dubbo-consumer;
  7. dubbo=2.0.2;
  8. interface=org.apache.dubbo.samples.api.GreetingsService;
  9. version=0.0.0;
  10. timeout=1000;
  11. thread info: 
  12. Start time: 285965612316294
  13. +-[ Offset: 0.000000ms; Usage: 811.017347ms, 100% ] Receive request. Server invoke begin.
  14.   +-[ Offset: 1.096880ms; Usage: 809.916668ms, 99% ] Filter org.apache.dubbo.rpc.filter.EchoFilter invoke.
  15.      +-[ Offset: 1.133478ms; Usage: 809.866204ms, 99% ] Filter org.apache.dubbo.rpc.filter.ClassLoaderFilter invoke.
  16.         +-[ Offset: 1.157563ms; Usage: 809.838572ms, 99% ] Filter org.apache.dubbo.rpc.filter.GenericFilter invoke.
  17.            +-[ Offset: 1.202075ms; Usage: 809.736843ms, 99% ] Filter org.apache.dubbo.rpc.filter.ContextFilter invoke.
  18.               +-[ Offset: 1.433193ms; Usage: 809.504401ms, 99% ] Filter org.apache.dubbo.auth.filter.ProviderAuthFilter invoke.
  19.                  +-[ Offset: 1.470760ms; Usage: 809.464291ms, 99% ] Filter org.apache.dubbo.rpc.filter.ExceptionFilter invoke.
  20.                     +-[ Offset: 1.489103ms; Usage: 809.440183ms, 99% ] Filter org.apache.dubbo.monitor.support.MonitorFilter invoke.
  21.                        +-[ Offset: 1.515757ms; Usage: 809.381893ms, 99% ] Filter org.apache.dubbo.rpc.filter.TimeoutFilter invoke.
  22.                           +-[ Offset: 1.526632ms; Usage: 809.366553ms, 99% ] Filter org.apache.dubbo.rpc.protocol.dubbo.filter.TraceFilter invoke.
  23.                              +-[ Offset: 1.536964ms; Usage: 809.335907ms, 99% ] Filter org.apache.dubbo.rpc.filter.ClassLoaderCallbackFilter invoke.
  24.                                 +-[ Offset: 1.558545ms; Usage: 804.276436ms, 99% ] Receive request. Server biz impl invoke begin., dubbo version: 3.0.10-SNAPSHOT, current host: xx.xx.xx.xx

Note

For empty logs caused by log framework mismatches, refer to Log Framework Adaptation and Runtime Management for dynamically modifying the log output framework.

Feedback

Was this page helpful?

Yes No

Last modified September 30, 2024: Update & Translate Overview Docs (#3040) (d37ebceaea7)