原创分享 像跟踪分布式服务调用那样跟踪 Go 函数调用链

bigwhite-github · 2020年12月12日 · 最后由 eudore 回复于 2020年12月18日 · 644 次阅读
本帖已被设为精华帖！

img{512x368}

这篇文章的初衷是想解答知乎上的一位知友提出的问题。没想到完成一种实现后，这个问题居然被删除了。那么既然实现了，就分享出来吧。问题的原文找不到了，问题大致是这样的：


一个程序中存在多个函数调用链都调用了函数D：

A1 -> B1 > C1 -> D

A2 -> B2 > C2 -> D

A3 -> B3 -> C3 -> D

... ...

那么，如果某次函数D被调用时出现了问题，那么怎么知道这个D是哪个函数调用链里的D呢？

有些 gopher 可能会说通过Delve 在线调试打印函数调用栈可以知晓 D 的调用链，还有些 gopher 可能会说通过各个函数中输出的业务日志可以查明出问题的 D 归属的函数调用链，这些都是可行的思路。

不过当遇到这个问题时，我大脑中的第一反应却是能否像跟踪分布式服务调用链那样跟踪函数调用链呢？于是就有了本文对这种思路的一个非生产级的实现以及其演化过程。

1. 利用 defer 实现函数出入口的跟踪

跟踪函数调用，我们首先想到的就是跟踪函数的出入口，而完成这一任务，当仁不让的就是利用defer。对于我这样的从 C 语言转到 Go 的 gopher 而言，defer 是我十分喜欢的 Go“语法糖”，因为它可以简化代码的实现，让代码逻辑更清晰，具有更好地可读性(关于 defer 让代码更清晰的系统描述，可参考我的Go 进阶技术专栏文章：https://www.imooc.com/read/87/article/2421)。

下面我们就来看看第一版函数跟踪实现的代码：

// github.com/bigwhite/experiments/blob/master/trace-function-call-chain/trace1/trace.go
func trace() func() {
    pc, _, _, ok := runtime.Caller(1)
    if !ok {
        panic("not found caller")
    }

    fn := runtime.FuncForPC(pc)
    name := fn.Name()

    fmt.Printf("enter: %s\n", name)
    return func() { fmt.Printf("exit: %s\n", name) } 
}

// github.com/bigwhite/experiments/blob/master/trace-function-call-chain/trace1/main.go
func A1() {
    defer trace()()
    B1()
}

func B1() {
    defer trace()()
    C1()
}

func C1() {
    defer trace()()
    D()
}

func D() {
    defer trace()()
}

func main() {
    A1()
}

我们看到：以 A1 实现为例，当执行流来带 defer 语句时，首先会对 defer 后面的表达式进行求值。trace 函数会执行，输出函数入口信息，并返回一个 “打印出口信息” 的匿名函数。该函数在此并不会执行，而是被注册到函数 A1 的 defer 函数栈中，待 A1 函数执行结束后才会被弹出执行。也就是在 A1 结束后，会有一条函数的出口信息被输出。

下面我们来真实运行一下上面的 trace1 示例 (Go 1.14, macOS 10.14.6)：

// github.com/bigwhite/experiments/trace-function-call-chain/trace1
$go build
$./functrace-demo
enter: main.A1
enter: main.B1
enter: main.C1
enter: main.D
exit: main.D
exit: main.C1
exit: main.B1
exit: main.A1

我们看到各个函数的出入口信息都被输出了，在单 Goroutine 的情况下，我们从执行顺序上能识别出 D 究竟是归属于哪个调用链的。

2. 添加 trace 开关

对函数调用链进行 Trace 是有一定性能损耗的，我们可能并不想在所有场合都开启 trace，那么我们来给 Trace 添加一个 “开关”，我们利用 go build tags 来实现这个功能特性：


// github.com/bigwhite/experiments/blob/master/trace-function-call-chain/trace2/trace.go

// +build trace

package main
... ...


// github.com/bigwhite/experiments/blob/master/trace-function-call-chain/trace2/trace_nop.go

// +build !trace

package main

func trace() func() {
    return func() {

    }
}

我们新增一个名为trace_nop.go的文件，里面包含了一个 trace 函数的空实现，即在 trace 函数与其返回的匿名函数中什么都不做。该源文件增加了一个 build 指示器 (directive)：

// +build !trace

即在关闭 trace 开关时，使用该文件中的 trace 函数。而原trace.go文件中也增加了一个 build 指示器：

// +build trace

即只有在打开 trace 开关的情况下，才会使用该源文件。

我们来对比一下在 trace 开关打开和关闭下的执行结果：

// github.com/bigwhite/experiments/trace-function-call-chain/trace2
// trace开关关闭
$go build
$./functrace-demo

vs.

// trace开关打开
$go build -tags trace
$./functrace-demo
enter: main.A1
enter: main.B1
enter: main.C1
enter: main.D
exit: main.D
exit: main.C1
exit: main.B1
exit: main.A1

不过这里的实现还是有一个问题的，那就是即便不开启 trace 开关，trace_nop.go中的 trace 函数也是会被编译到可执行程序中的。利用 go tool compile -S 查看汇编代码，trace_nop.go中的 trace 函数以及其返回的匿名函数都没有被 inline 掉。这会带来一定的运行时开销，这个问题我们先记下并留到后面解决。

3. 增加对多 goroutine 函数调用链的跟踪支持

前面的实现面对只有一个 goroutine 的时候还是可以支撑的，但当程序中并发运行多个 goroutine 的时候，多个函数调用链的出入口信息输出就会混杂在一起无法分辨。下面我们就来改造一下实现，增加对多 goroutine 函数调用链的跟踪支持。我们的方案就是在输出函数出入口信息时，带上一个在程序每次执行时能唯一区分 goroutine 的 goroutine id：

// github.com/bigwhite/experiments/blob/master/trace-function-call-chain/trace3/trace.go
func getGID() uint64 {
    b := make([]byte, 64)
    b = b[:runtime.Stack(b, false)]
    b = bytes.TrimPrefix(b, []byte("goroutine "))
    b = b[:bytes.IndexByte(b, ' ')]
    n, _ := strconv.ParseUint(string(b), 10, 64)
    return n
}

func trace() func() {
    pc, _, _, ok := runtime.Caller(1)
    if !ok {
        panic("not found caller")
    }

    fn := runtime.FuncForPC(pc)
    name := fn.Name()

    id := getGID()
    fmt.Printf("g[%02d]: enter %s\n", id, name)
    return func() { fmt.Printf("g[%02d]: exit %s\n", id, name) } 
}

main.go 也改成了启动多个 Goroutine：

// github.com/bigwhite/experiments/blob/master/trace-function-call-chain/trace3/main.go

func A1() {
    defer trace()()
    B1()
}

func B1() {
    defer trace()()
    C1()
}

func C1() {
    defer trace()()
    D()
}

func D() {
    defer trace()()
}

func A2() {
    defer trace()()
    B2()
}
func B2() {
    defer trace()()
    C2()
}
func C2() {
    defer trace()()
    D()
}

func main() {
    var wg sync.WaitGroup
    wg.Add(1)
    go func() {
        A2()
        wg.Done()
    }()

    time.Sleep(time.Millisecond * 50)
    A1()
    wg.Wait()
}

在 trace 功能开关打开的前提下，运行上面例子：

// github.com/bigwhite/experiments/trace-function-call-chain/trace3
$go build -tags trace
$./functrace-demo
g[18]: enter main.A2
g[18]: enter main.B2
g[18]: enter main.C2
g[18]: enter main.D
g[18]: exit main.D
g[18]: exit main.C2
g[18]: exit main.B2
g[18]: exit main.A2
g[01]: enter main.A1
g[01]: enter main.B1
g[01]: enter main.C1
g[01]: enter main.D
g[01]: exit main.D
g[01]: exit main.C1
g[01]: exit main.B1
g[01]: exit main.A1

4. 让输出更美观一些

了解分布式服务调用跟踪的童鞋都知道，通过带有层次感的输出，我们可以很容易识别出某个服务在哪个环节被调用。而上面我们的 Trace 输出太扁平，没有层次感，不容易识别，我们这里就来美化一下输出。我们将trace.go做如下改造：


// github.com/bigwhite/experiments/trace-function-call-chain/trace4/trace.go

var mu sync.Mutex
var m = make(map[uint64]int)

func printTrace(id uint64, name, typ string, indent int) {
    indents := ""
    for i := 0; i < indent; i++ {
        indents += "\t"
    }
    fmt.Printf("g[%02d]:%s%s%s\n", id, indents, typ, name)
}

func trace() func() {
    pc, _, _, ok := runtime.Caller(1)
    if !ok {
        panic("not found caller")
    }

    id := getGID()
    fn := runtime.FuncForPC(pc)
    name := fn.Name()

    mu.Lock()
    v := m[id]
    m[id] = v + 1
    mu.Unlock()
    printTrace(id, name, "->", v+1)
    return func() {
        mu.Lock()
        v := m[id]
        m[id] = v - 1
        mu.Unlock()
        printTrace(id, name, "<-", v)
    }
}

编译运行：

// github.com/bigwhite/experiments/trace-function-call-chain/trace4
$go build -tags trace
$./functrace-demo
g[18]:  ->main.A2
g[18]:      ->main.B2
g[18]:          ->main.C2
g[18]:              ->main.D
g[18]:              <-main.D
g[18]:          <-main.C2
g[18]:      <-main.B2
g[18]:  <-main.A2
g[01]:  ->main.A1
g[01]:      ->main.B1
g[01]:          ->main.C1
g[01]:              ->main.D
g[01]:              <-main.D
g[01]:          <-main.C1
g[01]:      <-main.B1
g[01]:  <-main.A1

这回显然好看多了，也更容易定位问题了！（当多个 goroutine 的函数跟踪输出混在一起时，我们还可以用 grep 工具将特定 id 的 goroutine 的函数跟踪输出过滤出来，比如：functrace-demo|grep "01"）。

5. 利用代码生成将 trace 代码注入到各个函数中

在前面我们提到过上面实现的一个问题，那就是一旦将 trace 写死到各个函数代码中，即便在 trace 开关未打开的情况下，依然是有性能损耗的。并且，上面的实现存在着对业务代码的较强的 “代码侵入性”。那么我们能否减少侵入，像分布式服务跟踪那样将 “跟踪” 的设施注入 (instrumenting) 到需要跟踪的函数中呢？下面我们就来尝试一下。

1) 将 trace 单独打包为一个 module

我们首先要做的就是将 trace 相关的代码单独提取打包为一个 module。这里我将上面的 trace.go 和 trace_nop.go 放入了一个路径为github.com/bigwhite/functrace的 module 中：

$tree -F -L 2 functrace 
functrace
├── LICENSE
... ...
├── README.md
├── example_test.go
├── go.mod
├── go.sum
├── trace.go
└── trace_nop.go

有了这个 module，你可以以 “侵入式” 的方式为你的代码添加函数链调用跟踪，就像上面 repo 中example_test.go中的那样：

// https://github.com/bigwhite/functrace/blob/main/example_test.go
import (
    "github.com/bigwhite/functrace"
)

func a() {
    defer functrace.Trace()()
    b()
}

func b() {
    defer functrace.Trace()()
    c()
}

func c() {
    defer functrace.Trace()()
    d()
}

func d() {
    defer functrace.Trace()()
}

func ExampleTrace() {
    a()
    // Output:
    // g[01]:   ->github.com/bigwhite/functrace_test.a
    // g[01]:       ->github.com/bigwhite/functrace_test.b
    // g[01]:           ->github.com/bigwhite/functrace_test.c
    // g[01]:               ->github.com/bigwhite/functrace_test.d
    // g[01]:               <-github.com/bigwhite/functrace_test.d
    // g[01]:           <-github.com/bigwhite/functrace_test.c
    // g[01]:       <-github.com/bigwhite/functrace_test.b
    // g[01]:   <-github.com/bigwhite/functrace_test.a
}

2) 增加代码注入功能

我们在github.com/bigwhite/functrace仓库中增加了一个名为gen的工具。利用该工具我们可以将 functrace 中的 trace 基础设施代码自动注入 (instrumenting) 到目标源文件的各个函数定义中。这个工具调用的核心算法在 github.com/bigwhite/functrace/pkg/generator 中：

// github.com/bigwhite/functrace/blob/main/pkg/generator/rewrite.go
func Rewrite(filename string) ([]byte, error) {
        fset := token.NewFileSet()
        oldAST, err := parser.ParseFile(fset, filename, nil, 0)
        if err != nil {
                return nil, fmt.Errorf("error parsing %s: %w", filename, err)
        }

        if !hasFuncDecl(oldAST) {
                return nil, nil
        }

        // add import declaration
        astutil.AddImport(fset, oldAST, "github.com/bigwhite/functrace")

        // inject code into each function declaration
        addDeferTraceIntoFuncDecls(oldAST)

        buf := &bytes.Buffer{}
        err = format.Node(buf, fset, oldAST)
        if err != nil {
                return nil, fmt.Errorf("error formatting new code: %w", err)
        }
        return buf.Bytes(), nil
}

我们看到这个包的 Rewrite 函数使用了 Go 项目提供的go/ast包以及 Go 扩展项目提供的 ast(抽象语法树) 操作工具包golang.org/x/tools/go/ast/astutil对目标源文件进行解析、修改并重建的。go/ast包的内容较多，其本身就具备单独写几篇文章了，这里不赘述。有兴趣的童鞋可以移步本文后面的参考资料，或查看 go 官方文档了解。

为了帮助大家了解如何使用 gen 生成带有 trace 的代码，我还在 functrace 这个 repo 中建立了一个demo：examples/gen-demo：

$tree examples/gen-demo 
examples/gen-demo
├── Makefile
├── go.mod
├── go.sum
└── main.go

在该 demo 中，我们利用 go generate 生成带有跟踪代码的目标代码：

// https://github.com/bigwhite/functrace/blob/main/examples/gen-demo/main.go
package main

//go:generate ../../gen -w main.go

... ...

构建该 demo 并运行 (为了方便构建，我建立了 Makefile)：


// Makefile
all:
    go generate
    go build -tags trace

$make
go generate
[../../gen -w main.go]
add trace for main.go ok
go build -tags trace

$./functrace-demo 
g[01]:  ->main.main
g[01]:      ->main.A2
g[01]:          ->main.B2
g[01]:              ->main.C2
g[01]:                  ->main.D
g[01]:                  <-main.D
g[01]:              <-main.C2
g[01]:          <-main.B2
g[01]:      <-main.A2
g[18]:  ->main.A1
g[18]:      ->main.B1
g[18]:          ->main.C1
g[18]:              ->main.D
g[18]:              <-main.D
g[18]:          <-main.C1
g[18]:      <-main.B1
g[18]:  <-main.A1
g[01]:  <-main.main

我们看到，我们通过 ast 将跟踪代码注入到目标代码并运行的思路成功实现了！

6. 小结

functrace module 中 Trace 函数的实现比较简单，目前仅是输出日志，但实际上我们可以在 Trace 函数中以及 Trace 函数返回的匿名函数中通过各种方式输出我们想要的数据，比如，像分布式服务跟踪那样，将数据发送到一个集中的后端做统一存储、分析和展示。但鉴于篇幅和需求不同，这里仅给出满足演示的实现，大家可以自行 fork 该 repo 以实现满足你们自己需求的实现。

7. 参考资料

本文中涉及到的示例源码可以到这里下载 https://github.com/bigwhite/experiments/tree/master/trace-function-call-chain。

“Gopher 部落” 知识星球开球了！高品质首发 Go 技术文章，“三天” 首发阅读权，每年两期 Go 语言发展现状分析，每天提前 1 小时阅读到新鲜的 Gopher 日报，网课、技术专栏、图书内容前瞻，六小时内必答保证等满足你关于 Go 语言生态的所有需求！星球首开，福利自然是少不了的！2020 年年底之前，8.8 折 (很吉利吧^_^) 加入星球，下方图片扫起来吧！

我的 Go 技术专栏：“改善 Go 语⾔编程质量的 50 个有效实践” 主要满足广大 gopher 关于 Go 语言进阶的需求，围绕如何写出地道且高质量 Go 代码给出 50 条有效实践建议，上线后收到一致好评！ 欢迎大家订阅！

img{512x368}

我的网课 “Kubernetes 实战：高可用集群搭建、配置、运维与应用” 在慕课网热卖中，欢迎小伙伴们订阅学习！

Gopher Daily(Gopher 每日新闻) 归档仓库 - https://github.com/bigwhite/gopherdaily

我的联系方式：

更多原创文章干货分享，请关注公众号
  • 加微信实战群请加微信(注明:实战群)：gocnio
2 个赞
kevin 将本帖设为了精华贴 12月13日 08:55
kevin 在 GoCN 每日新闻 (2020-12-13) 中提及了此贴 12月13日 09:08
sotex #3 · 2020年12月14日

学习了。👍

MrTrans #4 · 2020年12月17日

有点意思

eudore #5 · 2020年12月18日

思路清奇😀

需要 登录 后方可回复, 如果你还没有账号请点击这里 注册。
共收到 3 条回复
打赏支持
有新回复！点击这里立即载入