Skywalking链路追踪自身耗时和总耗时算法分析

Skywalking链路追踪自身耗时和总耗时算法分析

一、前言

介绍Skywalking链路追踪中，【自身耗时】和【总耗时】的计算方式。

二、Trace、TraceSegment和Span之间的关系模型

一个span可能有零个、一个或多个children span。

三、【自身耗时】和【总耗时】的源码

四、Span的startTime和endTime生成

在字节码增强拦截器 {@link InstMethodsInter}中，拦截目标实例的方法定义如下：

其中：
beforeMethod()是方法调用前的核心api，在该方法中createSpan，生成startTime；
afterMethod()是方法调用后的核心api，在该方法中stopSpan，生成endTime；

五、Span创建的流程

为了让大家进一步了解Span的startTime和endTime是如何生成的，简要流程如下：

六、耗时公式的推导

1. 如果当前span没有任何children span时：

当前span自身耗时 = 当前span的endTime - 当前span的startTime;
当前span总耗时 = 当前span自身耗时;

2. 如果当前span有children span时：

当前span自身耗时 = (当前span的endTime-当前span的startTime) - (子1 span的endTime - 子1 span的startTime) - (子2 span的endTime - 子2 span的startTime) - ...;
当前span总耗时 = 当前span的endTime - 当前span的startTime;

七、耗时公式的证明

7.1 undertow-2.x-plugin插件创建entrySpan

在undertow-2.x-plugin插件中，创建createEntrySpan前开始记时，stopSpan后结束记时：

验证结果：对比UI显示耗时和代码锚点耗时检测的值，可知：

1、当span有children span的时候：
当前span自身耗时 = (当前span.endTime-当前span.startTime) - (子span.endTime-子span.startTime);
当前span总耗时 = 当前span.endTime - 当前span.startTime;

2、当span没有children span的时候：
当前span自身耗时 = 当前span总耗时 = 当前span.endTime - 当前span.startTime;

7.2 mvc-annotation-5.x-plugin插件创建EntrySpan

验证结果：假如当前span是父span

父span自身耗时 = (父span.endTime-父span.startTime) - (子span.endTime-子span.startTime);

对应到上图的两个测试，即：
1）父span自身耗时：1786-1784=2ms；子span自身耗时=子span总耗时：1784ms；
2）父span自身耗时：105-102=3ms；子span自身耗时=子span总耗时：102ms；

7.3 httpClient-4.x-plugin插件创建ExitSpan

HttpClient组件的exitspan有三个parent span：
1）parent1：HttpClient组件的exitSpan
1）parent2：SpringMVC组件的entryspan
2）parent3：Undertow组件的LocalSpan

验证结果：

当前span自身耗时 = 当前span.endTime-当前span.startTime;
parent1自身耗时 = (parent1.endTime-parent1.startTime) - (当前span.endTime-当前span.startTime);
parent2自身耗时 = (parent2.endTime-parent2.startTime) - (parent1.endTime-parent1.startTime);
parent3自身耗时 = (parent3.endTime-parent3.startTime) - (parent2.endTime-parent2.startTime);

7.4 netty-apsaras-4.x-plugin插件的entrySpan（G3 ApsarasClient调用）

注意：netty-apsaras-4.x-plugin组件的entryspan有五个parent span：
1）ApsarasClient组件的exitspan
2）SpringMVC组件的entrySpan
3）HttpClient组件的exitSpan
4）SpringMVC组件的entrySpan
5）Undertow组件的LocalSpan

（1）当前span的总耗时：


（2）当前span的parent1、parent2 span的总耗时：



（3）当前span的parent3、parent4、parent5 span的总耗时：




验证结果：

当前span自身耗时 = 当前span.endTime-当前span.startTime;
parent1自身耗时 = (parent1.endTime-parent1.startTime) - (当前span.endTime-当前span.startTime);
parent2自身耗时 = (parent2.endTime-parent2.startTime) - (parent1.endTime-parent1.startTime);
parent3自身耗时 = (parent3.endTime-parent3.startTime) - (parent2.endTime-parent2.startTime);
...
...
...

换句话也就是说,如果当前span不是最后一个span，则:
当前span自身耗时 = (当前span.endTime-当前span.startTime) - (子span.endTime-子span.startTime);

如果有多个children span，那么自身耗时=当前span总耗时-(遍历依次减去各个子span的总耗时);

八、最后的结论

1. 如果当前span没有任何children span时：

当前span自身耗时 = 当前stopSpan时的endTime - 当前createSpan时的startTime;
当前span总耗时 = 当前span自身耗时;

2. 如果当前span有children span时：

当前span自身耗时 = (当前span的endTime - 当前span的startTime) - (子1 span的endTime - 子1 span的startTime) - (子2 span的endTime - 子2 span的startTime)-...;
当前span总耗时 = 当前stopSpan时的endTime - 当前createSpan时的startTime;

3. 如果当前span有children span，并且当前span是异步span时：（这个结论可以不用记，了解就行）

~~当前span自身耗时=(当前span.endTime - 当前span.startTime)~~ 
~~当前span总耗时=当前span自身耗时+子span总耗时~~ 

九、自身耗时简单理解

9.1 链路完整的情况下

一个请求可能垮越多个进程或线程、操作多种中间件。服务间远程调用（垮进程）时各组件间存在一定的网络底层的消耗，比如tomcat转发请求的耗时、http协议的底层耗时、netty协议的底层耗时等等。所以，Skywalking自身耗时可以简单理解为一个微服务到另外一个微服务中间过程的网络延迟。

9.2 链路有断裂的情况下

当然还有一种特殊的情况，如下图所示，当前span有两个children span(mysql组件、redis组件)。

假设：
当前span.endTime-当前span.startTime = a
children1.endTime-children1.startTime = b
children2.endTime-children2.startTime = c

1. 那么，正常情况下：

当前span自身耗时 = a - b - c;

2. 但是，如果redis组件没有对应的Skywalking插件服务，也就是说redis查询操作在链路中看不到，那么：

当前span自身耗时 = a - b;// 而实际上应该是：当前span自身耗时 = a - b - c;

/**
 * 现在少了c，但是c操作却真实存在，仅仅是链路中没有统计到。
 * 所以此时：当前span自身耗时 > a-b，多出来的那部分自身耗时其实就是操作redis查询的总耗时。
 * 
 * 我们用数字代入一下试试看，假设 a=10ms, b=4ms, c=3ms
 * 当前span自身耗时 = 10 - 4 - 3； // 正常情况下，自身耗时是3ms
 * 当前span自身耗时 = 10 - 4； // c操作没统计到的情况下，自身耗时是6ms，相比正常情况多出来的3ms，就是redis操作的耗时。
 */

最后

PDF文档下载：Skywalking链路追踪自身耗时和总耗时算法分析