Go 官方部落格

更強大的 Go 執行跟蹤

Michael Knyszek
14 March 2024

runtime/trace 包包含一個強大的工具，用於理解和排查 Go 程式的問題。其中的功能可以用於生成每個 goroutine 在一段時間內的執行跟蹤。使用 go tool trace 命令（或優秀的開源 gotraceui 工具），可以視覺化和探索這些跟蹤資料。

跟蹤的神奇之處在於它可以輕鬆揭示程式中透過其他方式難以看到的問題。例如，許多 goroutine 在同一通道上阻塞造成的併發瓶頸在 CPU profile 中可能很難看到，因為沒有執行可以取樣。但在執行跟蹤中，執行的缺失會清晰地顯示出來，並且阻塞 goroutine 的堆疊跟蹤會迅速指向罪魁禍首。

Go 開發者甚至可以使用任務、區域和日誌來檢測自己的程式，他們可以用這些來關聯更高層面的關注點和底層執行細節。

問題

不幸的是，執行跟蹤中豐富的資訊往往難以獲取。跟蹤的四個主要問題歷來是阻礙。

跟蹤的開銷很高。
跟蹤的可伸縮性不好，資料可能變得太大而無法分析。
通常不清楚何時開始跟蹤才能捕獲特定的不良行為。
鑑於缺乏用於解析和解釋執行跟蹤的公共包，只有最勇於探索的 Go 開發者才能以程式設計方式分析跟蹤。

如果您在過去幾年使用過跟蹤，您可能曾因其中一個或多個問題而感到沮喪。但我們很高興地告訴您，在過去的兩個 Go 版本中，我們在這四個領域都取得了巨大進展。

低開銷跟蹤

在 Go 1.21 之前，對於許多應用程式來說，跟蹤的執行時開銷在 10-20% 的 CPU 之間，這將跟蹤限制在情境使用，而不是像 CPU profile 那樣持續使用。結果表明，跟蹤的大部分開銷歸結於回溯（tracebacks）。執行時生成的許多事件都附帶堆疊跟蹤，這對於實際識別 goroutine 在執行關鍵時刻正在做什麼非常有價值。

感謝 Felix Geisendörfer 和 Nick Ripley 在最佳化回溯效率方面所做的工作，執行跟蹤的執行時 CPU 開銷已大幅削減，對於許多應用程式來說降至 1-2%。您可以在 Felix 關於該主題的精彩博文中閱讀更多關於此處完成的工作的資訊。

可伸縮的跟蹤

跟蹤格式及其事件圍繞相對高效的發出而設計，但需要工具來解析並保留整個跟蹤的狀態。幾百 MiB 的跟蹤可能需要幾 GiB 的 RAM 才能分析！

不幸的是，這個問題是跟蹤如何生成的根本原因。為了保持執行時開銷低，所有事件都寫入相當於執行緒本地緩衝區的區域。但這表示事件出現時並非按真實順序排列，因此需要跟蹤工具來確定實際發生的情況。

在保持開銷低的同時使跟蹤具有可伸縮性的關鍵在於偶爾分割正在生成的跟蹤。每個分割點都像一次性停用和重新啟用跟蹤一樣。到目前為止的所有跟蹤資料將代表一個完整且自包含的跟蹤，而新的跟蹤資料將無縫地從上次停止的地方開始。

正如您可能想象的那樣，修復這個問題需要重新思考和重寫執行時跟蹤實現的基礎。我們很高興地告訴您，這項工作已在 Go 1.22 中實現並普遍可用。重寫帶來了許多不錯的改進，包括對 go tool trace 命令的一些改進。如果您好奇，所有詳細資訊都在設計文件中。

(注意：go tool trace 仍然將完整跟蹤載入到記憶體中，但取消此限制對於 Go 1.22+ 程式生成的跟蹤現在是可行的。)

飛行記錄

假設您正在開發一個 Web 服務，並且某個 RPC 花費了很長時間。您無法在知道 RPC 已經耗時很長時才開始跟蹤，因為慢請求的根本原因已經發生並且未被記錄下來。

有一種技術可以幫助解決這個問題，稱為飛行記錄 (flight recording)，您可能在其他程式設計環境中已經熟悉它。飛行記錄的關鍵思想是持續開啟跟蹤，並始終保留最新的跟蹤資料，以防萬一。然後，一旦發生有趣的事情，程式就可以立即將擁有的資料寫出！

在跟蹤可以分割之前，這幾乎是不可能的。但由於低開銷使得持續跟蹤現在可行，並且執行時現在可以在需要時分割跟蹤，實現飛行記錄就變得很簡單了。

因此，我們很高興宣佈飛行記錄器實驗功能，該功能可在 golang.org/x/exp/trace 包中使用。

請嘗試一下！下面是一個設定飛行記錄以捕獲長時間 HTTP 請求的示例，供您入門。

    // Set up the flight recorder.
    fr := trace.NewFlightRecorder()
    fr.Start()

    // Set up and run an HTTP server.
    var once sync.Once
    http.HandleFunc("/my-endpoint", func(w http.ResponseWriter, r *http.Request) {
        start := time.Now()

        // Do the work...
        doWork(w, r)

        // We saw a long request. Take a snapshot!
        if time.Since(start) > 300*time.Millisecond {
            // Do it only once for simplicity, but you can take more than one.
            once.Do(func() {
                // Grab the snapshot.
                var b bytes.Buffer
                _, err = fr.WriteTo(&b)
                if err != nil {
                    log.Print(err)
                    return
                }
                // Write it to a file.
                if err := os.WriteFile("trace.out", b.Bytes(), 0o755); err != nil {
                    log.Print(err)
                    return
                }
            })
        }
    })
    log.Fatal(http.ListenAndServe(":8080", nil))

如果您有任何反饋，無論是積極的還是消極的，請在提案 issue 中分享！

跟蹤讀取器 API

隨著跟蹤實現的重寫，還進行了一項清理其他跟蹤內部的工作，例如 go tool trace。這催生了建立跟蹤讀取器 API 的嘗試，該 API 足夠好以供共享，並可以使跟蹤更容易訪問。

就像飛行記錄器一樣，我們很高興宣佈我們也有一個實驗性的跟蹤讀取器 API 希望與您分享。它與飛行記錄器在同一個包 golang.org/x/exp/trace 中可用。

我們認為它已經足夠好，可以開始在其之上構建東西了，所以請嘗試一下！下面是一個測量因等待網路而阻塞的 goroutine 阻塞事件比例的示例。

    // Start reading from STDIN.
    r, err := trace.NewReader(os.Stdin)
    if err != nil {
        log.Fatal(err)
    }

    var blocked int
    var blockedOnNetwork int
    for {
        // Read the event.
        ev, err := r.ReadEvent()
        if err == io.EOF {
            break
        } else if err != nil {
            log.Fatal(err)
        }

        // Process it.
        if ev.Kind() == trace.EventStateTransition {
            st := ev.StateTransition()
            if st.Resource.Kind == trace.ResourceGoroutine {
                from, to := st.Goroutine()

                // Look for goroutines blocking, and count them.
                if from.Executing() && to == trace.GoWaiting {
                    blocked++
                    if strings.Contains(st.Reason, "network") {
                        blockedOnNetwork++
                    }
                }
            }
        }
    }
    // Print what we found.
    p := 100 * float64(blockedOnNetwork) / float64(blocked)
    fmt.Printf("%2.3f%% instances of goroutines blocking were to block on the network\n", p)

就像飛行記錄器一樣，有一個提案 issue 是留下反饋的好地方！

我們想特別感謝 Dominik Honnef，他是早期嘗試者之一，提供了寶貴的反饋，併為 API 貢獻了對舊跟蹤版本的支援。

謝謝！

這項工作得以完成，很大程度上得益於診斷工作組成員的幫助。該工作組於一年前啟動，是 Go 社群各利益相關者之間的合作，並向公眾開放。

我們想花點時間感謝在過去一年中定期參加診斷會議的社群成員：Felix Geisendörfer、Nick Ripley、Rhys Hiltner、Dominik Honnef、Bryan Boreham、thepudds。

你們所有人的討論、反饋和投入的工作對於我們今天取得的成就至關重要。謝謝！

下一篇文章：Go 開發者調查 2024 年上半年結果
上一篇文章：切片上的健壯泛型函式
部落格索引