解决的问题

在 piggygo 后台项目中处理一个请求可能会进行多次 pika 拉取数据或保存数据，同时可能存在同步或异步调用其他节点的情况。目前我们发现接口延时的主要依据是 prometheus 中的接口延时统计，存在的问题是 prometheus 统计的 30s 内各个请求的均值，并且根本无法知道高延时的请求时间花费在哪里。去年我尝试过给 piggygo 后台项目优化过几个高延时的接口，当时的依据是在开发测试环境针对 pika 和远程调用打印耗时，并收集和识别出问题，从而解决了排行榜无缓存从而拉取 pika 多次，以及没有使用 goroutine 进行异步发送远程调用的问题。

以下是当时排查输出的日志：

1
2
3
4
5
6
7
8
9

[2022-09-24 11:43:39.518 +0800] TRACE   5537    framework.go:417        main.handleRequest      --- start cost: [[["GAME_CMD_DICE_PLAY_RESULT_REQ"]]]   {}
[2022-09-24 11:43:39.519 +0800] TRACE   5537    data_util_multi.go:359  main.func1      mGetData [Board:100877 MiscInfoWeekExpire:100877] data cost:    [[[138]]]       {}
[2022-09-24 11:43:39.529 +0800] TRACE   5537    comm.go:57      main.func1      send msg sync cost:     [[["BOARD_CMD_BOARD_DICE_PLAY_REQ",9962]]]      {}
[2022-09-24 11:43:39.529 +0800] TRACE   5537    data_util_multi.go:359  main.func1      mGetData [TaskSysData:100877] data cost:        [[[114]]]       {}
[2022-09-24 11:43:39.529 +0800] TRACE   5537    data_util_multi.go:359  main.func1      mGetData [StageMission:100877] data cost:       [[[70]]]        {}
[2022-09-24 11:43:39.530 +0800] TRACE   5537    data_util_multi.go:359  main.func1      mGetData [BoardControl:100877] data cost:       [[[170]]]       {}
[2022-09-24 11:43:39.530 +0800] TRACE   5537    comm.go:119     main.func1      send msg async cost:    [[["INNER_GAME_CMD_ASYNC_EVENT_REQ",75]]]       {}
[2022-09-24 11:43:39.530 +0800] TRACE   5537    data_util_multi.go:445  main.func2      mSetBytes [StageMission:100877 UserPropertyData:100877] data cost:      [[[69]]]        {}
[2022-09-24 11:43:39.532 +0800] TRACE   5537    framework.go:421        main.func1      --- end cost:   [[["GAME_CMD_DICE_PLAY_RESULT_REQ",13256]]]     {}

但这种方式使用起来不方便，最大的问题是环境是收集和分析不容易，日志分布在各个进程自己的目录下，日志跟其他业务日志混合在一起，耗时日志无法反映各函数之间的调用关系，需要开发人员对代码足够熟悉才能把日志串起来进行分析。

为了更加方便的对线上的性能问题进行定位，对分布式链路追踪进行了调研、运用到 piggygo 后台项目。我们选择了 JAEGER 开源解决方案，这个项目目前已经是 CNCF 的 graduated 项目，被广泛运用于微服务领域。

Jaeger 是由 Uber Technologies 作为开源发布的分布式跟踪系统。 它用于监视和诊断基于微服务的分布式系统,包括:

  • 分布式上下文传播
  • 服务依赖性分析
  • 性能/延迟优化

Jaeger 介绍

Open Trace 数据模型

分布式链路追踪依赖 OpenTracing 数据模型，其起源是 Google Dapper 的论文。这些概念也是在接入 Jaeger 分布式链路追踪所必须了解的。下图包含了需要用到的所有的概念名词：

open trace

  • Trace：表示在分布式系统中传播的事务，这是一个隐式的概念，实际上在代码中不会出现此对象；
  • Span：表示分布式事务的一环，具有自己名字，并且可以通过调用 Finish 进行从生成到调用点的耗时统计，以及利用 Tag 装载其它有用信息。Span 之间是存在父子关系的，Root Span于 Trace 的概念一致，表示一次事务，Child Span 则表示为事务中的一环，一个事务内的 Span 构成一个有向无环图，从而知道整个事务的完整调用关系和耗时；

Span DAG

  • Span contxt：用于在分布式系统中传播的载体，其中包含 TraceId, SpanId 等信息，通过 Inject 函数注入到一个载体中，比如：bp 对象，以及使用 Extract 函数从载体中提取出来用于构建新的 Span 对象；

Span Context

  • 信息携带：Tag 描述当前 span 的属性数据； Log 结构化日志数据，是一种键值对，用于描述 span 中发生的特定事件，包含时间戳，比如：出错信息；baggage 也是键值对，用于在整个事务中进行传播，会被 Child Span 继承，可以传播至远程节点；

完整的规格文档参考：https://github.com/opentracing/specification/blob/master/specification.md

Jaeger 架构

Jaeger Architecture

  • jaeger-client：为不同语言实现了符合 OpenTracing 标准的SDK，项目代码需要导入这个包来进行 span 数据上报；
  • jaeger-agent：它是一个监听在UDP端口上接收 span 数据的网络守护进程，它会将数据批量发送给 jaeger-collector。它被设计成一个基础组件，部署到业务进程所在宿主机上；
  • jaeger-collector：接收 jaeger-agent 发送来的数据，然后将数据写入后端存储。jaeger-collector 被设计成无状态的组件，因此您可以同时运行任意数量的 jaeger-collector；
  • DB：后端存储被设计成一个可插拔的组件，支持将数据写入cassandra、elastic search。
  • jaeger-query：接收查询请求，然后从后端存储系统中检索 Trace 并通过 UI 进行展示。jaeger-query是无状态的，您可以启动多个实例，把它们部署在Nginx负载均衡器后面；

在开发测试阶段，可通过 docker 快速部署一个 all-in-one 可执行文件：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17

docker run -d --name jaeger \
-e SPAN_STORAGE_TYPE=badger \
-e LOG_LEVEL=debug \
-e BADGER_DIRECTORY_VALUE=/badger/data \
-e BADGER_DIRECTORY_KEY=/badger/key \
-e COLLECTOR_ZIPKIN_HOST_PORT=:9411 \
-v /data/db/badger:/badger \
-p 5775:5775/udp \
-p 6831:6831/udp \
-p 6832:6832/udp \
-p 5778:5778 \
-p 16686:16686 \
-p 14268:14268 \
-p 14269:14269 \
-p 14250:14250 \
-p 9411:9411 \
jaegertracing/all-in-one:1.34

在 Jaeger中文文档 有一个比较好的入门教程来了解 jaeger 相关的知识。

实现过程

实现过程包含如下几个过程：

  • 前期调研快速进行 demo 实验，当时想使用 opentelemetry 这个官方推荐库作为依赖库，在尝试引入时发现 opentelmetry 依赖更高版本的 go 以及引入过多包，不便于放到 vendor 库中，遂改为使用 jaeger-client-go 作为依赖库，降低对外部的依赖；
  • demo 实现只能对最外层进行耗时统计，想要获得完整的调用链必须利用 go 语言中的 context 将 span 传递到任何想要生成 child span 的地方，以及跨节点调用的地方。这就必须对项目进行改进从而将 ctx 传递到需要的地方去，目前的做法是在 handleRequest 中生成一个 ctx 并作为函数的第一个参数传递到 pika 取数据，远程调用的地方去；
  • 在进入 handleRequest，pika 获取、保存数据以及远程调用时进行埋点，在跨节点的地方将 SpanContext数据注入到 ppb.PktOpt 中去，并在 handleRequst 函数解包后立即用于生成 child span；
  • 在任何需要的业务点调用 NewSpanChildOf 并在结束时调用 Finish 函数即可；

以下是实现时具体遇到的问题

ctx 问题

pgcontext 的问题

piggygo 中的 ctx 是自己实现的，其底层是一个 map，这样做的好处是 WithValue 是更轻量，且可以将数据从被调用者传递到调用者。但问题是 Open Tracing 利用了标准库中的 ctx 特性，这样被调用的函数不会影响到调用者。我们需要在 pgcontext 中模拟这个特性，所以提供了两个函数：

  • SetGoCtx 设置一个标准库中的 ctx 进去并生成一个新的 pgcontext 对象；
  • GetGoCtx 从 pgcontext 中取出一个标准库的 ctx 对象，如果没有的话则返回 nil ；

这样要求我们每次调用 SetGoCtx 后需要将新的 ctx 替换掉作为参数传递的 ctx：

1

ctx = pgcontext.SetGoCtx(ctx, goctx)

ctx 传递的问题

piggygo 后端项目中原本仅仅将 context 用于给发奖函数等单次请求玩家相关的数据传递的，相对用的地方是比较少的。而分布式调用链追踪却要求加 context 传递到几乎整个项目所有的地方。改动起来倒也不难就是给每个调用 SetSliceData 和 GetSliceData 的地方都在最开始加一个 ctx pgcontext.Context 参数即可，难在于对整个项目进行全部修改。目前统计总共修改了 ~5202 处调用点和函数签名，整个过程 90% 以上是自动化修改，且可用于调用链增加其他参数。

为了做到自动化修改，利用了Go Tools 提供的静态程序分析工具，其中用到的核心包是 cmd/callgraph 对 go 程序中的调用图进行分析。

以下是程序分析的代码：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13

initial, err := packages.Load(cfg, args...)
prog, _ := ssautil.AllPackages(initial, 0)  
prog.Build()
mains, err := mainPackages(prog.AllPackages())
config := &pointer.Config{  
   Mains:          mains,  
   BuildCallGraph: true,  
}  
ptares, err := pointer.Analyze(config)
graph := ptares.CallGraph
callgraph.GraphVisitEdges(graph, func(edge *callgraph.Edge) error {
	// ... 具体构建下一步使用的图数据
})

核心算法是利用调用图生成调用点 CallLocation 、调用者 Caller 、被调用者 Callee 对象，并生成一个有向无环图。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34

type FuncInfo struct {  
   IDNum       int    `json:"IDNum,omitempty"`  
   ID          string `json:"ID,omitempty"`  
   PackagePath string `json:"PackagePath,omitempty"`  
   FileName    string `json:"FileName,omitempty"`  
   LineNo      int    `json:"LineNo,omitempty"`  
   FuncName    string `json:"FuncName,omitempty"`  
   RecvName    string `json:"RecvName,omitempty"`  
   CtxLocation int    `json:"CtxLocation,omitempty"`  
}  
  
type CallLocation struct {  
   FileName string `json:"FileName,omitempty"`  
   LineNo   int    `json:"LineNo,omitempty"`  
   Column   int    `json:"Column,omitempty"`  
   IDNum    int    `json:"IDNum,omitempty"`  
}  
  
type CallInfo struct {  
   Caller *FuncInfo     `json:"Caller"`  
   Callee *FuncInfo     `json:"Callee"`  
   Loc    *CallLocation `json:"Loc"`  
}  
  
type Edge struct {  
   In  int           `json:"In"`  
   Out int           `json:"Out"`  
   Loc *CallLocation `json:"Loc"`  
}  
  
type OutputObj struct {  
   Functions []*FuncInfo `json:"Functions"`  
   Graph     []*Edge     `json:"Graph"`  
}

随后从被调用的最底层往上回溯用 appendCallCtxParam 对没有 ctx 的调用点加上 ctx 参数，用 appendFuncDefCtxParam 对调用者函数签名没有 ctx 的加上 pgcontext.Context 参数声明。

利用 Go Tools 进行程序静态分析存在无法识别 interface 中参数的问题，所有 interface 中的参数都是手动加上的。另外存在对函数内部定义闭包无法利用自由变量，这一块也是手动改的。

另外一个我觉得比较好的地方是 Go Tools 静态分析不仅可用于正常程序还可用于单元测试，从而节省了不少修改单测的时间。

跨节点

通过给所有调用 GetSliceData 和 SetSliceData 加上 ctx 参数，且在处理客户端消息的入口函数 handleRequest 处生成一个 trace 即可形成单进程内调用图的有向无环图。对于一条信息可能会执行 SendTo 和 SendToAsync 需要一种方式串联起来。 Open Traceing 提供了 Inject 接口将 span 父子关系数据 baggage 序列化，并提供 Extract 反序列化出来，并且提供了 carrier 抽象，我实现了利用 Opt 作为载体的 carrier：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19

type OptTextMapCarrier struct {
	*ppb.PktOpt
}

func (opt *OptTextMapCarrier) Set(key string, val string) {
	if opt.SpanCarrier == nil {
		opt.SpanCarrier = map[string]string{}
	}
	opt.SpanCarrier[key] = val
}

func (opt *OptTextMapCarrier) ForeachKey(handler func(key, val string) error) error {
	for k, v := range opt.SpanCarrier {
		if err := handler(k, v); err != nil {
			return err
		}
	}
	return nil
}

在消息处理入口如果能够从 Opt 中继承父 span 则进行继承，如果不能的话则启动一个 root span：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17

func Inherit(ctx pgcontext.Context, opt *ppb.PktOpt, service string, spanName string) (opentracing.Span, pgcontext.Context) {
	tracer := getTracer(service)
	carrier := &OptTextMapCarrier{opt}
	spanCtx, err := tracer.Extract(opentracing.TextMap, carrier)
	if err == nil {
		goctx := context.Background()
		var span opentracing.Span
		if carrier.IsAsync() {
			span = tracer.StartSpan(spanName, opentracing.FollowsFrom(spanCtx))
		} else {
			span = tracer.StartSpan(spanName, opentracing.ChildOf(spanCtx))
		}
		goctx = opentracing.ContextWithSpan(goctx, span)
		return span, pgcontext.SetGoCtx(ctx, goctx)
	}
	return NewSpan(ctx, service, spanName, true)
}

进行内部调用时将 span 关系数据注入到 Opt 中，这里区分了异步和同步调用：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16

func Inject(ctx pgcontext.Context, opt *ppb.PktOpt, isAsync bool) error {
	goctx, ok := pgcontext.GetGoCtx(ctx)
	if !ok {
		return nil
	}
	sp := opentracing.SpanFromContext(goctx)
	if sp == nil {
		return nil
	}
	carrier := &OptTextMapCarrier{opt}
	err := sp.Tracer().Inject(sp.Context(), opentracing.TextMap, carrier)
	if isAsync {
		carrier.SetAsync()
	}
	return err
}

至此项目中的所有进程就都串联起来了。

如何埋点

上面实现的是一个基本框架，可以对单次请求中的 pika 访问和节点之间的调用进行分析。使用时也可以在任何想要进行分析的函数中加上 NewSpanChildOf 调用：

1
2
3
4

sp, ctx = pgtrace.NewSpanChildOf(ctx, configmgr.SrvName, "{operation_name}")
if sp != nil {
	defer sp.Finish()
}

如果这是一条进行了分析的请求，sp 必不为 nil，调用 ps.Finish() 进行耗时上报。注意这里返回的 ctx 需要替换掉作为参数传递进来的 ctx，这样才能形成有效的父子关系。

当需要加入其他信息到分析中去的时候，调用 SetTag LogFields LogError：

1
2
3
4

pgtrace.SetTag(ctx, "UID", newP.GetOpt().UID)
pgtrace.SetTag(ctx, "reqID", newP.GetOpt().RequestID)
pgtrace.LogFields(ctx, log.String("event", "timeout"), log.Int("elapse", 100))
pgtrace.LogError(ctx, err, log.String("cmd", cmdName))

效果

登录接口

以下是一个数据库为 redis 的开发机上游客登录的调用链图形，可以看出登录过程中分别进入了 loginsrv, statsrv, game, boardsrv 节点，并进行了多次pika 拉取和保存数据。

jaeger-login

从这里可以看出登录接口本身消耗了 3.89 ms 进行登录处理，并对 game 节点进行了一次异步调用 ASYNC_EVENT_TYPE_LOGIN_SERVER 这个异步事件中 9 次 pika get 操作，还执行了一次异步添加 mail 的操作以及 statsrv 的在线上报。如果是 fb 登录或者数据库为 pika 的话数据耗时上还会有所不一样。

即便是从这个图形中依然可以看出 ASYNC_EVENT_TYPE_LOGIN_SERVER 执行了过多的 pika get 操作，是否可以合并成一个，或者其中一些消除掉。

投骰子接口

以下图形为一次没有阶梯的投骰子过程，耗时4.63 ms，其中1.06 ms 消耗在 boardsrv 实际处理投骰子算法过程中，后面还有多次异步调用分别是修改 CK, 修改数据, 投骰子低速率异步触发事件。

jaeger-dice-play

从上图可以看出在远程调用过程中不是没有网络时间损耗的，实际boardsrv处理消耗1.06ms，调用花费了 1.82ms, 其中 0.76ms 划分在网络中。而且这里 3.0ms后到4.63ms的时间去缺失的，这里具体时间消耗在做什么需要进一步埋点去看问题。

后续

以上的实践基本搭建好了分布式链路追踪的架子，但依然有不完善的地方，比如：目前上报的信息只上报了 UID、命令字、数据key等少量信息，没有对请求中的 error 进行区分上报，对于 HTTP 请求没有进行上报。后面都需要在使用过程中继续完善以发挥作用。