像跟蹤分散式服務呼叫那樣跟蹤 Go 函式呼叫鏈

bigwhite-github發表於2020-12-12

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 折 (很吉利吧^_^) 加入星球，下方圖片掃起來吧！