Go 部落格

更強大的 Go 執行緒追蹤

Michael Knyszek
2024 年 3 月 14 日

runtime/trace 套件包含一個強大的工具,可了解和解決 Go 程式問題。透過此功能,可以在某一段時間內產生各個 goroutine 的執行追蹤。使用 go tool trace 命令(或極佳的開源 gotraceui 工具),便可以視覺化並探索這些追蹤中的資料。

追蹤的神奇在於,它可以輕鬆揭露程式中其他方式難以察覺的事情。舉例而言,在 CPU 設定檔中可能會很難看到大量 goroutine 阻塞在同一個通道上的並行化瓶頸,因為沒有執行可供抽樣。不過,在執行追蹤中,執行缺乏的狀況會非常清晰地顯示出來,而會被鎖住的 goroutine 的堆疊追蹤則會迅速指出罪魁禍首。

Go 開發人員甚至可以使用 任務區塊記錄 來建立自己的程式工具,用於將較高層級的疑慮與較低層級的執行細節相互關聯。

問題

很遺憾地,執行追蹤的資訊十分豐富,但常常難以取得。追蹤曾面臨四大問題,而這些問題一直存在。

  • 追蹤擁有很高的額外成本。
  • 追蹤難以擴充,並且可能過於龐大而無法分析。
  • 通常不清楚什麼時候開始追蹤,以擷取特定異常行為。
  • 只有最冒險的 gopher 能以程式方式分析追蹤,原因在於缺少用於剖析和解釋執行追蹤的公開套件。

如果你在過去幾年有使用追蹤,你可能曾經因為一個或多個這些問題而感到沮喪。但我們很興奮地分享在最近兩個 Go 版本中,我們在所有這四個領域都獲得了長足的進展。

低額外成本的追蹤

在 Go 1.21 之前,對於許多應用程式而言,追蹤的執行時間額外成本介於 10% 到 20% 的 CPU 之間,這使得追蹤只能在情境使用中使用,而不是像 CPU 剖析那樣持續使用。事實證明,追蹤的成本在很大程度上取決於追溯。執行時期產生的許多事件都附加了堆疊追蹤,這些追蹤對於實際確定在執行過程中的關鍵時刻 goroutine 在執行什麼非常有價值。

感謝 Felix Geisendörfer 和 Nick Ripley 在最佳化追溯效率方面所做的工作,許多應用程式執行追蹤的執行時間 CPU 額外成本已大幅降低,降至 1% 到 2%。你可以在此處閱讀有關這項工作的更多資訊 Felix 關於這個主題的精彩網誌貼文

可擴充的追蹤

追蹤格式及其事件的設計旨在實現相對有效的放射,但需要工具來剖析並保留整個追蹤的狀態。幾個 100 MiB 的追蹤可能需要數個 GiB 的記憶體才能分析!

很遺憾的是,這個問題對於追蹤如何生成而言是根本性的。為了將執行時間額外成本保持在低水位,所有事件都寫入等效於執行緒本機緩衝區。但這表示事件會以非真實順序出現,而負擔則落在追蹤工具上,找出實際發生了什麼事。

讓追蹤規模化且同時保持低額外成本的關鍵見解是,偶爾拆分正在生成的追蹤。每個拆分點的行為都有些類似於同時停用和重新啟用追蹤。到目前為止,所有追蹤資料都將表示一個完整且獨立的追蹤,而新的追蹤資料將從它停止的地方無縫接續。

正如你所想像的,修復此問題需要 重新思考並重寫執行時間追蹤實作的許多基礎。我們很樂意地告訴你,這份成果已經納入 Go 1.22 中,並且現在已廣泛提供。此次重寫也帶來大量實用性的改進,包括部分改進的 go tool trace 指令。如果你感興趣,詳細內容都記載於 設計文件中

(注意:`go tool trace` 仍會將完整的追蹤載入記憶體,但 移除這個限制 對於 Go 1.22+ 程式產生的追蹤來說已經可行。)

飛行記錄

假設你正在處理網路服務,而且一個 RPC 花了很多時間。你無法在你知道 RPC 已經執行一段時間的那個時間點開始追蹤,因為緩慢請求的根本原因已經發生,也沒有被記錄下來。

有一種技巧可以協助解決這個問題,稱為飛行記錄,你可能已經從其他程式設計環境中認識它。飛行記錄的原理是不間斷執行追蹤,並且隨時保留最近的追蹤資料,以備不時之需。然後,一旦發生某件有趣的事情,程式便可以寫出它所擁有的一切!

在追蹤可以被拆分之前,這幾乎是不可能開始執行的工作。但是,由於低開銷現在已經完全追蹤可行了,而且執行時間可以隨時拆分追蹤這項事實,因此證明實作飛行記錄很簡單。

因此,我們很高興宣布一個飛行記錄器實驗,它在 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))

如果你有任何正面的或負面的回饋,請將其分享至 建議事項問題

追蹤讀取器 API

隨著追蹤實作的重寫而來的工作還包含清理其他追蹤內部,例如 `go tool trace`。這激發了嘗試建立一個足夠完善到可以分享,且可以讓追蹤更容易存取的追蹤讀取器 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)

而就像飛行記錄一樣,有一個 建議事項問題 是留給回饋的好地方!

我們想要快速表揚 Dominik Honnef,他是早期嘗試、提供許多回饋,並為舊版追蹤貢獻 API 支援的人。

謝謝!

這項工作得以完成,大部分要歸功於那些正在參與 診斷工作小組 的人,它在一年多前開始,做為 Go 社群所有利害關係人的合作,對公眾開放。

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

討論、回饋,以及你們的努力,對於我們走到今天至關重要。謝謝!

下一篇:Go 開發人員調查 2024 上半年結果
前一篇:區塊的健壯通用函數
部落格索引