trpc.group/trpc-go/trpc-go@v1.0.3/rpcz/README.zh_CN.md (about) 1 [English](README.md) | 中文 2 3 # RPCZ 4 5 RPCZ 是一个监控 RPC 的工具，记录了一次 rpc 中发生的各种事件，如序列化/反序列，压缩解压缩和执行拦截器。 6 RPCZ 可以帮助用户调试服务，它允许用户自行配置需要被记录的事件，用户可以通过 admin 工具可以查看记录的事件，能帮助用户快速准确的定位问题。 7 除此之外，由于 RPCZ 记录了 RPC 中各种事件的持续时间和收发数据包的大小，因此可以帮助用户分析超时事件，优化服务的性能。 8 9 ## 术语解释 10 11 ### 事件（Event） 12 13 事件（Event）[1, 2, 3] 用来描述某一特定时刻（`Event.Time`）发生了某件事情（`Event.Name`）。 14 15 ```go 16 type Event struct { 17 Name string 18 Time time.Time 19 } 20 ``` 21 在一个普通 RPC 调用中会发生一系列的事件，例如发送请求的 Client 端按照时间先后顺序，一般会发生如下一系列事件： 22 23 1. 开始运行前置拦截器 24 2. 结束运行前置拦截器 25 3. 开始序列化 26 4. 结束序列化 27 5. 开始压缩 28 6. 结束压缩 29 7. 开始编码协议头部字段 30 8. 结束编码协议头部字段 31 9. 开始发送二进制文件到网络 32 10. 结束发送二进制文件到网络 33 11. 开始从网络中接收二进制文件 34 12. 结束从网络中接收二进制文件 35 13. 开始解码协议头部字段 36 14. 结束解码协议头部字段 37 15. 开始解压缩 38 16. 结束解压缩 39 17. 开始反序列化 40 18. 结束反序列化 41 19. 开始运行后置拦截器 42 20. 结束运行后置拦截器 43 44 而处理请求的 server 端，按照时间先后顺序，一般会发生如下一系列事件： 45 46 1. 开始解码协议头部字段 47 2. 结束解码协议头部字段 48 3. 开始解压缩 49 4. 结束解压缩 50 5. 开始反序列化 51 6. 结束反序列化 52 7. 开始运行前置拦截器 53 8. 结束运行前置拦截器 54 9. 开始运行用户自定义处理函数 55 10. 结束运行用户自定义处理函数 56 11. 开始运行后置拦截器 57 12. 结束运行后置拦截器 58 13. 开始序列化 59 14. 结束序列化 60 15. 开始压缩 61 16. 结束压缩 62 17. 开始编码协议头部字段 63 18. 结束解码协议头部字段 64 19. 开始发送二进制文件到网络 65 20. 结束发送二进制文件到网络 66 67 ### Span 68 69 Span[4, 5] 用来描述某段时间间隔（具有开始时间和结束时间）的单个操作，例如客户端发送远程请求，服务端处理请求或函数调用。 70 根据划分的时间间隔大小不同，一个大的 Span 可以包含多个小的 Span，就像一个函数中可能调用多个其他函数一样，会形成树结构的层次关系。 71 因此一个 Span 除了包含名字、内部标识 span-id[6]，开始时间、结束时间和这段时间内发生的一系列事件（Event）外，还可能包含许多子 Span。 72 73 rpcz 中存在两种类型的 Span。 74 1. client-Span：描述 client 从开始发送请求到接收到回复这段时间间隔内的操作（涵盖上一节 Event 中描述的 client 端发生一系列事件）。 75 76 2. server-Span：描述 server 从开始接收请求到发送完回复这段时间间隔内的操作（涵盖上一节 Event 中描述的 server 端发生一系列事件）。 77 server-Span 运行用户自定义处理函数的时候，可能会创建 client 调用下游服务，此时 server-Span 会包含多个子 client-Span。 78 79 ``` 80 server-Span 81 client-Span-1 82 client-Span-2 83 ...... 84 client-Span-n 85 ``` 86 87 Span 被存储在 context 中，rpcz 会自动调用 ContextWithSpan 往 context 中存 Span，在函数调用过程中需要保证 context 中的 Span 不会丢失。 88 89 ## Span 的生命周期 90 91 考察 Span 对象的生命周期，rpcz 中对 Span 的绝大多数操作，都需要考虑并发安全。 92 除此之外采用了 sync.Pool 和 预先分配的循环数组来降低 Span 的内存分配时对性能的影响。 93 94 ### Span 的构造 95 96 rpcz 在启动时会初始化一个全局 GlobalRPCZ，用于生成和存储 Span。 97 在框架内部 Span 只可能在两个位置被构造， 98 第一个位置是在 server 端的 transport 层的 handle 函数刚开始处理接收到的请求时； 99 第二个位置是在 client 端的桩代码中调用 Invoke 函数开始发起 rpc 请求时。 100 虽然两个位置创建的 Span 类型是不同，但是代码逻辑是相似的，都会调用 rpczNewSpanContext，该函数实际上执行了三个操作 101 1. 调用 SpanFromContext 函数，从 context 中获取 span。 102 2. 调用 span.NewChild 方法，创建新的 child span。 103 3. 调用 ContextWithSpan 函数，将新创建的 child span 设置到 context 中。 104 105 ### Span 在 context 中传递 106 107 被创建 Span 在提交前，会一直在存放在 context 中，沿着 rpc 调用的链路传递。 108 在调用链路上使用 `rpcz.AddEvent` 往当前 context 中的 Span 中添加新的事件。 109 110 ### Span 的提交 111 112 在 server 端的 transport 层的 handle 函数处理完请求后，会调用 `ender.End()` 把 Span 提交到 GlobalRPCZ 当中。 113 此后虽然 context 中仍然存放着 Span，但是从语义上来说，已经调用过的 End 函数的 Span 不允许再被继续操作，其行为是未定义的。 114 115 ### 在 admin 中访问 Span 116 117 admin 模块调用 `rpcz.Query` 和 `rpcz.BatchQuery` 从 GlobalRPCZ 中读取 Span。 118 有一点需要注意的是，admin 获取的 Span 是只读类型的 Span（ReadOnlySpan），只读类型的 Span 是由可写入的 Span 导出得到的，这样做的原因是保证并发访问安全。 119 120 ### 删除多余的 Span 121 122 当哈希表中存储的 Span 过多时就需要按照某种淘汰规则，删除多余的 Span。 123 目前的实现是当 GlobalRPCZ 中的 Span 个数超过最大容量上限时会删除最老的 Span。 124 125 ## RPCZ 名字的由来 126 127 关于 "RPCZ" 的这个名字的由来，后缀 -z 有在英文中一般有两种含义 [7]: 一是用于名词，实现单数变复数，如 Boy**z** are always trouble；二是用于动词实现动词形态的变化 He love**z** me。 128 总的来说，在单词后面加 -z 的效果类似于加 -s。 129 所以 "RPCZ" 就是指各种类型的 RPC，从一个分布式全局的调用链路视角来看的确是成立的，各种 RPC 调用存在树状的父子关系，组合成了 "RPCZ"。 130 131 "RPCZ" 这一术语最早来源于 google 内部的 RPC 框架 Stubby，在此基础上 google 在开源的 grpc 实现了类似功能的 channelz[8]，channelz 中除了包括各种 channel 的信息，也涵盖 trace 信息。 132 之后，百度开源的 brpc 在 google 发表的分布式追踪系统 Dapper 论文 [9] 的基础上，实现了一个非分布式的 trace 工具，模仿 channelz 取名为 brpc-rpcz[10]。 133 接着就是用户在使用 tRPC 中需要类似于 brpc-rpcz 的工具来进行调试和优化，所以 tRPC-Cpp 首先支持类似功能，仍然保留了 RPCZ 这个名字。 134 135 最后就是在 tRPC-Go 支持类似 "RPCZ" 的功能，在实现过程中发现随着分布式追踪系统的发展，社区中出现了 opentracing[11] 和 opentelemetry[12] 的开源系统。 136 tRPC-Go-RPCZ 在 span 和 event 设计上部分借鉴了 opentelemetry-trace 的 go 语言实现，可以认为是 tRPC-Go 框架内部的 trace 系统。 137 严格来说，tRPC-Go-RPCZ 是非分布式，因为不同服务之间没有在协议层面实现通信。 138 现在看来，brpc, tRPC-Cpp 和 tRPC-Go 实现的 rpcz，取名叫 spanz 或许更符合后缀 "-z" 本来的含义。 139 140 ## 如何配置 rpcz 141 142 rpcz 的配置包括基本配置，进阶配置和代码配置，更多配置例子见 `config_test.go`。 143 144 ### 不同 tRPC-GO 版本的支持情况 145 146 - v0.15.0：支持 tRPC 流式和 tnet。 147 - v0.14.0：支持 http 协议。 148 - v0.11.0：支持 tRPC 一元调用。 149 - v0.11.0 之前的版本：不支持。 150 151 ### 基本配置 152 153 在 server 端配置 admin，同时在 admin 里面配置 rpcz : 154 155 ```yaml 156 server: 157 admin: 158 ip: 127.0.0.1 159 port: 9028 160 rpcz: 161 fraction: 1.0 162 capacity: 10000 163 ``` 164 165 - `fraction` : 采样率，其取值范围为`[0.0, 1.0]`，默认值为 0.0 代表不采样，需要手动配置。 166 - `capacity`: rpcz 的存储容量，默认值为 10000，表示最多能存储的 span 数量。 167 168 ### 进阶配置 169 170 进阶配置允许你自行过滤感兴趣的 span，在使用进阶配置之前需要先了解 rpcz 的采样机制。 171 172 #### 采样机制 173 174 rpcz 使用采样机制来控制性能开销和过滤你不感兴趣的 Span。 175 采样可能发生在 Span 的生命周期的不同阶段，最早的采样发生在 Span 创建之前，最晚的采样发生在 Span 提交之前。 176 177 ##### 采样结果表 178 179 只有创建和提交之前都被采样到的 Span 才会最终被收集到 GlobalRPCZ 中，供你通过 admin 接口查询。 180 181 | 在 Span 创建之前采样？ | 在 Span 提交之前采样？ | Span 最终是否会被收集？ | 182 |:-----------------|:--------------:|:--------------:| 183 | true | true | true | 184 | true | false | false | 185 | false | true | false | 186 | false | false | false | 187 188 ##### 在 Span 创建之前采样 189 190 只有当 Span 被采样到才会去创建 Span，否则就不需要创建 Span，也就避免了后续对 Span 的一系列操作，从而可以较大程度上减少性能开销。 191 采用固定采样率 [13] 的采样策略，该策略只有一个可配置浮点参数 `rpcz.fraction`, 例如`rpcz.fraction` 为 0.0001，则表示每 10000（1/0.0001）个请求会采样一条请求。 192 当 `rpcz.fraction` 小于 0 时，会向上取 0；当 `rpcz.fraction` 大于 1 时，会向下取 1。 193 194 ##### 在 Span 提交之前采样 195 196 已经创建好的 Span 会记录 rpc 中的各种信息，但是你可能只关心包含某些特定信息的 Span，例如出现 rpc 错误的 Span，高耗时的 Span 以及包含特定属性信息的 Span。 197 这时，就需要在 Span 最终提交前只对你需要的 Span 进行采样。 198 rpcz 提供了一个灵活的对外接口，允许你在服务在启动之前，通过配置文件设置 `rpcz.record_when` 字段来自定义 Span 提交之前采样逻辑。 199 record_when 提供3种常见的布尔操作：`AND`， `OR` 和 `NOT`，7种返回值为布尔值的基本操作，`__min_request_size`, `__min_response_size`, `__error_code`, `__error_message`, `__rpc_name`, `__min_duration` 和 `__has_attribute`。 200 **需要注意的是 record_when 本身是一个 `AND` 操作**。 201 你可以通过对这些操作进行任意组合，灵活地过滤出感兴趣的 Span。 202 203 ```yaml 204 server: # server configuration. 205 admin: 206 ip: 127.0.0.1 # ip. 207 port: 9528 # default: 9028. 208 rpcz: # tool that monitors the running state of RPC, recording various things that happen in a rpc. 209 fraction: 0.0 # sample rate, 0.0 <= fraction <= 1.0. 210 record_when: # record_when is actually an AND operation 211 - AND: 212 - __min_request_size: 30 # record span whose request_size is greater than__min_request_size in bytes. 213 - __min_response_size: 40 # record span whose response_size is greater than __min_response_size in bytes. 214 - OR: 215 - __error_code: 1 # record span whose error codes is 1. 216 - __error_code: 2 # record span whose error codes is 2. 217 - __error_message: "unknown" # record span whose error messages contain "unknown". 218 - __error_message: "not found" # record span whose error messages contain "not found". 219 - NOT: {__rpc_name: "/trpc.app.server.service/method1"} # record span whose RPCName doesn't contain __rpc_name. 220 - NOT: # record span whose RPCName doesn't contain "/trpc.app.server.service/method2, or "/trpc.app.server.service/method3". 221 OR: 222 - __rpc_name: "/trpc.app.server.service/method2" 223 - __rpc_name: "/trpc.app.server.service/method3" 224 - __min_duration: 1000ms # record span whose duration is greater than __min_duration. 225 # record span that has the attribute: name1, and name1's value contains "value1" 226 # valid attribute form: (key, value) only one space character after comma character, and key can't contain comma(',') character. 227 - __has_attribute: (name1, value1) 228 # record span that has the attribute: name2, and name2's value contains "value2". 229 - __has_attribute: (name2, value2) 230 ``` 231 232 #### 配置举例 233 234 ##### 对包含错误码为 1(RetServerDecodeFail)，且错误信息中包含 “unknown” 字符串，且持续时间大于 1s 的 span 进行提交 235 236 ```yaml 237 server: 238 admin: 239 ip: 127.0.0.1 240 port: 9028 241 rpcz: 242 fraction: 1.0 243 capacity: 10000 244 record_when: 245 - __error_code: 1 246 - __min_duration: 1000ms 247 - __sampling_fraction: 1 248 ``` 249 250 注意: record_when 本身是一个 AND 节点，还可以有以下写法：写法1， 写法2 251 252 写法1: 253 254 ```yaml 255 server: 256 admin: 257 ip: 127.0.0.1 258 port: 9028 259 rpcz: 260 fraction: 1.0 261 capacity: 10000 262 record_when: 263 - AND: 264 - __error_code: 1 265 - __min_duration: 1000ms 266 - __sampling_fraction: 1 267 ``` 268 269 写法2: 270 271 ```yaml 272 server: 273 admin: 274 ip: 127.0.0.1 275 port: 9028 276 rpcz: 277 fraction: 1.0 278 capacity: 10000 279 record_when: 280 - AND: 281 - __error_code: 1 282 - AND: 283 - __min_duration: 1000ms 284 - __sampling_fraction: 1 285 ``` 286 287 写法3: 288 289 ```yaml 290 server: 291 admin: 292 ip: 127.0.0.1 293 port: 9028 294 rpcz: 295 fraction: 1.0 296 capacity: 10000 297 record_when: 298 - AND: 299 - __error_code: 1 300 - AND: 301 - __min_duration: 1000ms 302 - AND: 303 - __sampling_fraction: 1 304 ``` 305 306 还有其他写法，你可以自行尝试。 307 308 ##### 对包含错误码为 1(RetServerDecodeFail) 或 21(RetServerTimeout) 的或持续时间大于 2s 的 span 以 1/2 的概率进行提交 309 310 ```yaml 311 server: 312 admin: 313 ip: 127.0.0.1 314 port: 9028 315 rpcz: 316 fraction: 1.0 317 capacity: 10000 318 record_when: 319 - OR: 320 - error_code: 1 321 - error_code: 21 322 - min_duration: 2s 323 - __sampling_fraction: 0.5 324 ``` 325 326 ##### 对持续时间大于 10s, 且 rpc name 包含 "TDXA/Transfer" 字样，且 error message 里不能包含 "pseudo" 字样的 span 进行提交 327 328 ```yaml 329 server: 330 admin: 331 ip: 127.0.0.1 332 port: 9028 333 rpcz: 334 fraction: 1.0 335 capacity: 10000 336 record_when: 337 - min_duration: 2s 338 - __rpc_name: "TDXA/Transfer" 339 - NOT: 340 __error_message: "pseudo" 341 - __sampling_fraction: 1 342 ``` 343 344 ### 代码配置 345 346 在读取配置文件之后且在服务启动前，可以通过 `rpcz.GlobalRPCZ` 来配置 rpcz，此时的提交采样逻辑需要实现 `ShouldRecord` 函数。 347 348 ```go 349 // ShouldRecord determines if the Span should be recorded. 350 type ShouldRecord = func(Span) bool 351 ``` 352 353 ##### 只对包含 "SpecialAttribute" 属性的 Span 进行提交 354 355 ```go 356 const attributeName = "SpecialAttribute" 357 rpcz.GlobalRPCZ = rpcz.NewRPCZ(&rpcz.Config{ 358 Fraction: 1.0, 359 Capacity: 1000, 360 ShouldRecord: func(s rpcz.Span) bool { 361 _, ok = s.Attribute(attributeName) 362 return ok 363 }, 364 }) 365 ``` 366 367 ### 查询最近提交的多条 span 的概要信息 368 369 查询最近 num 个 span 的概要信息，可以访问如下的 url: 370 371 ```html 372 http://ip:port/cmds/rpcz/spans?num=xxx 373 ``` 374 375 例如执行 `curl http://ip:port/cmds/rpcz/spans?num=2` ，则会返回如下 2 个 span 的概要信息： 376 377 ```html 378 1: 379 span: (client, 65744150616107367) 380 time: (Dec 1 20:57:43.946627, Dec 1 20:57:43.946947) 381 duration: (0, 319.792µs, 0) 382 attributes: (RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, <nil>) 383 2: 384 span: (server, 1844470940819923952) 385 time: (Dec 1 20:57:43.946677, Dec 1 20:57:43.946912) 386 duration: (0, 235.5µs, 0) 387 attributes: (RequestSize, 125),(ResponseSize, 18),(RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, success) 388 ``` 389 390 每个 span 的概要信息和如下的模版匹配： 391 392 ```html 393 span: (name, id) 394 time: (startTime, endTime) 395 duration: (preDur, middleDur, postDur) 396 attributes: (name1, value1) (name2, value2) 397 ``` 398 399 其中每个字段的含义解释如下： 400 401 - name：span 的名字 402 - id：span 唯一标识，可通过它查询具体的某个 span 详细信息 403 - startTime：span 的创建时间 404 - endTime：span 的提交时间，当 span 未被提交成功时，该字段值为 "unknown" 405 - duration：包含个时间段来描述 currentSpan 和 parentSpan 的耗时 406 - preDur: currentSpan.startTime - parentSpan.startTime 407 - middleDur：currentSpan.endTime - currentSpan.startTime，当 currentSpan.endTime 为 "unknown" 时，middleDur 的值也为 "unknown" 408 - postDur：parentSpan.endTime - currentSpan.endTime，当 parentSpan.endTime 或 currentSpan.endTime 为 "unknown" 时，postDur 的值也为 "unknown" 409 - attributes：span 的属性值，每一个属性由（属性名，属性值）组成，通常会显示下面三个属性 410 - RequestSize：请求包大小（byte） 411 - ResponseSize：响应包大小（byte） 412 - RPCName：对端的服务名 + 接口名 (/trpc.app.server.service/method) 413 - Error：错误信息，根据框架返回码判断请求是否成功，success 或 nil 表示成功 414 415 如果不指定查询的个数，则下列查询将会默认返回最近提交成功的 [^1] 10 个 span 的概要信息： 416 417 ```html 418 http://ip:port/cmds/rpcz/spans 419 ``` 420 421 [^1]: **最近提交的 span 并不是严格按照时间来排序的，可能存在多个 goroutine 同时提交 span，是按照最近提交成功的 span 来排序。** 422 423 ### 查询某个 span 的详细信息 424 425 查询包含 id 的 span 的详细信息，可以访问如下的 url： 426 427 ```html 428 http://ip:port/cmds/rpcz/spans/{id} 429 ``` 430 431 例如执行 `curl http://ip:port/cmds/rpcz/spans/6673650005084645130` 可查询 span id 为 6673650005084645130 的 span 的详细信息： 432 433 ``` 434 span: (server, 6673650005084645130) 435 time: (Dec 2 10:43:55.295935, Dec 2 10:43:55.399262) 436 duration: (0, 103.326ms, 0) 437 attributes: (RequestSize, 125),(ResponseSize, 18),(RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, success) 438 span: (DecodeProtocolHead, 6673650005084645130) 439 time: (Dec 2 10:43:55.295940, Dec 2 10:43:55.295952) 440 duration: (4.375µs, 12.375µs, 103.30925ms) 441 span: (Decompress, 6673650005084645130) 442 time: (Dec 2 10:43:55.295981, Dec 2 10:43:55.295982) 443 duration: (45.875µs, 791ns, 103.279334ms) 444 span: (Unmarshal, 6673650005084645130) 445 time: (Dec 2 10:43:55.295982, Dec 2 10:43:55.295983) 446 duration: (47.041µs, 334ns, 103.278625ms) 447 span: (filter1, 6673650005084645130) 448 time: (Dec 2 10:43:55.296161, Dec 2 10:43:55.399249) 449 duration: (225.708µs, 103.088ms, 12.292µs) 450 event: (your annotation at pre-filter, Dec 2 10:43:55.296163) 451 span: (filter2, 6673650005084645130) 452 time: (Dec 2 10:43:55.296164, Dec 2 10:43:55.399249) 453 duration: (2.75µs, 103.085ms, 250ns) 454 event: (your annotation at pre-filter, Dec 2 10:43:55.296165) 455 span: (server.WithFilter, 6673650005084645130) 456 time: (Dec 2 10:43:55.296165, Dec 2 10:43:55.399249) 457 duration: (1.208µs, 103.083625ms, 167ns) 458 event: (your annotation at pre-filter, Dec 2 10:43:55.296165) 459 span: (, 6673650005084645130) 460 time: (Dec 2 10:43:55.296166, Dec 2 10:43:55.399249) 461 duration: (792ns, 103.082583ms, 250ns) 462 span: (HandleFunc, 6673650005084645130) 463 time: (Dec 2 10:43:55.296177, Dec 2 10:43:55.399249) 464 duration: (11.583µs, 103.070917ms, 83ns) 465 event: (handling EmptyCallF, Dec 2 10:43:55.296179) 466 span: (client, 6673650005084645130) 467 time: (Dec 2 10:43:55.296187, Dec 2 10:43:55.297871) 468 duration: (9.125µs, 1.684625ms, 101.377167ms) 469 attributes: (RPCName, /trpc.testing.end2end.TestTRPC/UnaryCall),(Error, <nil>) 470 span: (filter1, 6673650005084645130) 471 time: (Dec 2 10:43:55.296192, Dec 2 10:43:55.297870) 472 duration: (5.292µs, 1.678542ms, 791ns) 473 span: (client.WithFilter, 6673650005084645130) 474 time: (Dec 2 10:43:55.296192, Dec 2 10:43:55.297870) 475 duration: (542ns, 1.677875ms, 125ns) 476 span: (selector, 6673650005084645130) 477 time: (Dec 2 10:43:55.296193, Dec 2 10:43:55.297870) 478 duration: (541ns, 1.677209ms, 125ns) 479 span: (CallFunc, 6673650005084645130) 480 time: (Dec 2 10:43:55.296200, Dec 2 10:43:55.297869) 481 duration: (7.459µs, 1.668541ms, 1.209µs) 482 attributes: (RequestSize, 405),(ResponseSize, 338) 483 span: (Marshal, 6673650005084645130) 484 time: (Dec 2 10:43:55.296202, Dec 2 10:43:55.296341) 485 duration: (1.375µs, 138.875µs, 1.528291ms) 486 span: (Compress, 6673650005084645130) 487 time: (Dec 2 10:43:55.296341, Dec 2 10:43:55.296341) 488 duration: (140.708µs, 333ns, 1.5275ms) 489 span: (EncodeProtocolHead, 6673650005084645130) 490 time: (Dec 2 10:43:55.296342, Dec 2 10:43:55.296345) 491 duration: (141.458µs, 3.333µs, 1.52375ms) 492 span: (SendMessage, 6673650005084645130) 493 time: (Dec 2 10:43:55.297540, Dec 2 10:43:55.297555) 494 duration: (1.339375ms, 15.708µs, 313.458µs) 495 span: (ReceiveMessage, 6673650005084645130) 496 time: (Dec 2 10:43:55.297556, Dec 2 10:43:55.297860) 497 duration: (1.355666ms, 303.75µs, 9.125µs) 498 span: (DecodeProtocolHead, 6673650005084645130) 499 time: (Dec 2 10:43:55.297862, Dec 2 10:43:55.297865) 500 duration: (1.661916ms, 2.5µs, 4.125µs) 501 span: (Decompress, 6673650005084645130) 502 time: (Dec 2 10:43:55.297866, Dec 2 10:43:55.297866) 503 duration: (1.665583ms, 167ns, 2.791µs) 504 span: (Unmarshal, 6673650005084645130) 505 time: (Dec 2 10:43:55.297866, Dec 2 10:43:55.297868) 506 duration: (1.666041ms, 1.709µs, 791ns) 507 span: (sleep, 6673650005084645130) 508 time: (Dec 2 10:43:55.297876, unknown) 509 duration: (1.698709ms, unknown, unknown) 510 event: (awake, Dec 2 10:43:55.398954) 511 span: (client, 6673650005084645130) 512 time: (Dec 2 10:43:55.398979, Dec 2 10:43:55.399244) 513 duration: (102.80125ms, 265.417µs, 4.25µs) 514 attributes: (RPCName, /trpc.testing.end2end.TestTRPC/UnaryCall),(Error, <nil>) 515 span: (filter2, 6673650005084645130) 516 time: (Dec 2 10:43:55.398986, Dec 2 10:43:55.399244) 517 duration: (6.834µs, 258.25µs, 333ns) 518 span: (client.WithFilter, 6673650005084645130) 519 time: (Dec 2 10:43:55.398987, Dec 2 10:43:55.399244) 520 duration: (1.708µs, 256.458µs, 84ns) 521 span: (selector, 6673650005084645130) 522 time: (Dec 2 10:43:55.398988, Dec 2 10:43:55.399244) 523 duration: (417ns, 255.916µs, 125ns) 524 span: (CallFunc, 6673650005084645130) 525 time: (Dec 2 10:43:55.399005, Dec 2 10:43:55.399243) 526 duration: (16.833µs, 238.375µs, 708ns) 527 attributes: (RequestSize, 405),(ResponseSize, 338) 528 span: (Marshal, 6673650005084645130) 529 time: (Dec 2 10:43:55.399006, Dec 2 10:43:55.399017) 530 duration: (1.792µs, 10.458µs, 226.125µs) 531 span: (Compress, 6673650005084645130) 532 time: (Dec 2 10:43:55.399017, Dec 2 10:43:55.399017) 533 duration: (12.583µs, 167ns, 225.625µs) 534 span: (EncodeProtocolHead, 6673650005084645130) 535 time: (Dec 2 10:43:55.399018, Dec 2 10:43:55.399023) 536 duration: (12.958µs, 4.917µs, 220.5µs) 537 span: (SendMessage, 6673650005084645130) 538 time: (Dec 2 10:43:55.399041, Dec 2 10:43:55.399070) 539 duration: (36.375µs, 29.083µs, 172.917µs) 540 span: (ReceiveMessage, 6673650005084645130) 541 time: (Dec 2 10:43:55.399070, Dec 2 10:43:55.399239) 542 duration: (65.75µs, 168.25µs, 4.375µs) 543 span: (DecodeProtocolHead, 6673650005084645130) 544 time: (Dec 2 10:43:55.399240, Dec 2 10:43:55.399241) 545 duration: (235.417µs, 1.375µs, 1.583µs) 546 span: (Decompress, 6673650005084645130) 547 time: (Dec 2 10:43:55.399242, Dec 2 10:43:55.399242) 548 duration: (237µs, 125ns, 1.25µs) 549 span: (Unmarshal, 6673650005084645130) 550 time: (Dec 2 10:43:55.399242, Dec 2 10:43:55.399243) 551 duration: (237.292µs, 750ns, 333ns) 552 event: (your annotation at post-filter, Dec 2 10:43:55.399249) 553 event: (your annotation at post-filter, Dec 2 10:43:55.399249) 554 event: (your annotation at post-filter, Dec 2 10:43:55.399249) 555 span: (Marshal, 6673650005084645130) 556 time: (Dec 2 10:43:55.399250, Dec 2 10:43:55.399251) 557 duration: (103.314625ms, 1.208µs, 10.167µs) 558 span: (Compress, 6673650005084645130) 559 time: (Dec 2 10:43:55.399252, Dec 2 10:43:55.399252) 560 duration: (103.315958ms, 125ns, 9.917µs) 561 span: (EncodeProtocolHead, 6673650005084645130) 562 time: (Dec 2 10:43:55.399252, Dec 2 10:43:55.399253) 563 duration: (103.316208ms, 750ns, 9.042µs) 564 span: (SendMessage, 6673650005084645130) 565 time: (Dec 2 10:43:55.399253, Dec 2 10:43:55.399261) 566 duration: (103.317333ms, 8.333µs, 334ns) 567 ``` 568 569 在 span 的详细信息中新增了 `event` 字段，以及内嵌的子 span。 570 571 - event: 描述了在某一时刻发生的事情，类似于日志。 572 可以由你自行插入的事件，如上面例子中的 `Nov 4 14:39:23.594147: your annotation at pre-filter`。 573 - span：在 server 处理你自定义函数时，可能会创建新的 client 调用下游服务，此时会创建子 span 574 可以看到，所有的 子 span 都是在 `HandleFunc` 内发生的。 575 576 需要注意的是，endTime、duration 中的 middleDur 和 postDur 的值可能为 "unknown"，例如上面的 span 中包含如下的子 span： 577 578 ``` 579 span: (sleep, 6673650005084645130) 580 time: (Dec 2 10:43:55.297876, unknown) 581 duration: (1.698709ms, unknown, unknown) 582 event: (awake, Dec 2 10:43:55.398954) 583 ``` 584 585 ## Span 接口 586 587 你可以先调用 `rpcz.SpanFromContext`[^2] 获取当前 `context` 中的 `Span`，然后使用下面的接口来操作 Span。 588 589 ```go 590 type Span interface { 591 // AddEvent adds a event. 592 AddEvent(name string) 593 594 // SetAttribute sets Attribute with (name, value). 595 SetAttribute(name string, value interface{}) 596 597 // ID returns SpanID. 598 ID() SpanID 599 600 // NewChild creates a child span from current span. 601 // Ender ends this span if related operation is completed. 602 NewChild(name string) (Span, Ender) 603 } 604 ``` 605 606 [^2]: 当 `context` 中不含有任何 `span` 的时候会返回一个 `noopSpan`，对 `noopSpan` 的任何操作都是空操作，不会生效。 607 608 ### 使用 AddEvent 来添加事件 609 610 ```go 611 // If no Span is currently set in ctx an implementation of a Span that performs no operations is returned. 612 span := SpanFromContext(ctx context.Context) 613 614 span.AddEvent("Acquiring lock") 615 mutex.Lock() 616 617 span.AddEvent("Got lock, doing work...") 618 // do some stuff ... 619 620 span.AddEvent("Unlocking") 621 mutex.Unlock() 622 ``` 623 624 ### 使用 SetAttribute 来设置属性 625 626 ```go 627 ctx, msg := codec.EnsureMessage(ctx) 628 span := SpanFromContext(ctx context.Context) 629 span.SetAttribute("RPCName", msg.ClientRPCName()) 630 span.SetAttribute("Error", msg.ClientRspErr()) 631 ``` 632 633 ### 创建新的子 Span 634 635 **特别需要注意的是：创建的子 Span 应该由调用者只调用一次 end.End() 函数来结束子 Span 的生命周期，未调用 End 和 多次调用 End 的行为是未定义的** 636 637 ```go 638 span := SpanFromContext(ctx context.Context) 639 cs, end := span.NewChild("Decompress") 640 reqBodyBuf, err := codec.Decompress(compressType, reqBodyBuf) 641 end.End() 642 ``` 643 644 ## 参考 645 646 - [1] https://en.wikipedia.org/wiki/Event_(UML) 647 - [2] https://en.wikipedia.org/wiki/Event_(computing) 648 - [3] https://opentelemetry.io/docs/instrumentation/go/manual/#events 649 - [4] https://opentelemetry.io/docs/instrumentation/go/api/tracing/#starting-and-ending-a-span 650 - [5] https://opentelemetry.io/docs/concepts/observability-primer/#spans 651 - [6] span-id 用 8 字节的数组表示，满足 w3c trace-context specification. https://www.w3.org/TR/trace-context/#parent-id 652 - [7] https://en.wiktionary.org/wiki/-z#English 653 - [8] https://github.com/grpc/proposal/blob/master/A14-channelz.md 654 - [9] Dapper, a Large-Scale Distributed Systems Tracing Infrastructure: http://static.googleusercontent.com/media/research.google.com/en//pubs/archive/36356.pdf 655 - [10] brpc-rpcz: https://github.com/apache/incubator-brpc/blob/master/docs/cn/rpcz.md 656 - [11] opentracing: https://opentracing.io/ 657 - [12] opentelemetry: https://opentelemetry.io/ 658 - [13] open-telemetry-sdk-go-traceIDRatioSampler: https://github.com/open-telemetry/opentelemetry-go/blob/main/sdk/trace/sampling.go