Flight Recorder: Nowy tracer wykonania Go

W 2024 roku przedstawiliśmy światu potężniejsze śledzenie wykonania Go. W tamtym wpisie na blogu daliśmy przedsmak niektórych nowych funkcji, które mogliśmy odblokować dzięki naszemu nowemu narzędziu do śledzenia wykonania, w tym rejestracji lotu. Z przyjemnością ogłaszamy, że rejestracja lotu jest już dostępna w Go 1.25 i jest potężnym nowym narzędziem w zestawie narzędzi diagnostycznych Go.

Śledzenie wykonania

Najpierw krótkie przypomnienie o śladach wykonania Go.

\ Środowisko wykonawcze Go może zapisywać dziennik rejestrujący wiele zdarzeń, które występują podczas wykonywania aplikacji Go. Ten dziennik nazywany jest śladem wykonania środowiska wykonawczego. Ślady wykonania Go zawierają mnóstwo informacji o tym, jak gorutyny wchodzą w interakcje ze sobą i z podstawowym systemem. Sprawia to, że są bardzo przydatne do debugowania problemów z opóźnieniami, ponieważ informują zarówno o tym, kiedy gorutyny są wykonywane, jak i, co kluczowe, kiedy nie są.

\ Pakiet runtime/trace udostępnia API do zbierania śladu wykonania w określonym oknie czasowym poprzez wywołanie runtime/trace.Start i runtime/trace.Stop. Działa to dobrze, jeśli kod, który śledzisz, to tylko test, mikrobenchmark lub narzędzie wiersza poleceń. Możesz zebrać ślad całego wykonania od początku do końca lub tylko części, które Cię interesują.

\ Jednak w długo działających usługach internetowych, czyli rodzajach aplikacji, z których znany jest Go, to nie wystarczy. Serwery internetowe mogą działać przez dni, a nawet tygodnie, a zbieranie śladu całego wykonania wygenerowałoby zbyt dużo danych do przeszukania. Często tylko jedna część wykonania programu działa nieprawidłowo, na przykład upłynął limit czasu żądania lub nie powiodło się sprawdzenie stanu. Kiedy to się dzieje, jest już za późno, aby wywołać Start!

\ Jednym ze sposobów podejścia do tego problemu jest losowe próbkowanie śladów wykonania z całej floty. Chociaż to podejście jest potężne i może pomóc znaleźć problemy, zanim staną się awariami, wymaga dużej infrastruktury, aby ruszyć. Duże ilości danych śledzenia wykonania musiałyby być przechowywane, sortowane i przetwarzane, z czego wiele nie będzie zawierać nic interesującego. A kiedy próbujesz dotrzeć do sedna konkretnego problemu, to nie jest dobry punkt wyjścia.

Rejestracja lotu

To prowadzi nas do rejestratora lotu.

\ Program często wie, kiedy coś poszło nie tak, ale przyczyna mogła wystąpić dawno temu. Rejestrator lotu pozwala zebrać ślad ostatnich kilku sekund wykonania prowadzących do momentu, w którym program wykryje, że wystąpił problem.

\ Rejestrator lotu zbiera ślad wykonania jak zwykle, ale zamiast zapisywać go do gniazda lub pliku, buforuje ostatnie kilka sekund śladu w pamięci. W dowolnym momencie program może zażądać zawartości bufora i zrobić migawkę dokładnie problematycznego okna czasowego. Rejestrator lotu jest jak skalpel tnący bezpośrednio do obszaru problemu.

Przykład

Nauczmy się, jak korzystać z rejestratora lotu na przykładzie. W szczególności użyjmy go do zdiagnozowania problemu z wydajnością serwera HTTP, który implementuje grę "zgadnij liczbę". Udostępnia on punkt końcowy /guess-number, który przyjmuje liczbę całkowitą i odpowiada dzwoniącemu, informując go, czy zgadł właściwą liczbę.

\ Istnieje również gorutyna, która raz na minutę wysyła raport wszystkich zgadywanych liczb do innej usługi za pomocą żądania HTTP.

// bucket is a simple mutex-protected counter. type bucket struct { mu sync.Mutex guesses int } func main() { // Make one bucket for each valid number a client could guess. // The HTTP handler will look up the guessed number in buckets by // using the number as an index into the slice. buckets := make([]bucket, 100) // Every minute, we send a report of how many times each number was guessed. go func() { for range time.Tick(1 * time.Minute) { sendReport(buckets) } }() // Choose the number to be guessed. answer := rand.Intn(len(buckets)) http.HandleFunc("/guess-number", func(w http.ResponseWriter, r *http.Request) { start := time.Now() // Fetch the number from the URL query variable "guess" and convert it // to an integer. Then, validate it. guess, err := strconv.Atoi(r.URL.Query().Get("guess")) if err != nil || !(0 <= guess && guess < len(buckets)) { http.Error(w, "invalid 'guess' value", http.StatusBadRequest) return } // Select the appropriate bucket and safely increment its value. b := &buckets[guess] b.mu.Lock() b.guesses++ b.mu.Unlock() // Respond to the client with the guess and whether it was correct. fmt.Fprintf(w, "guess: %d, correct: %t", guess, guess == answer) log.Printf("HTTP request: endpoint=/guess-number guess=%d duration=%s", guess, time.Since(start)) }) log.Fatal(http.ListenAndServe(":8090", nil)) } // sendReport posts the current state of buckets to a remote service. func sendReport(buckets []bucket) { counts := make([]int, len(buckets)) for index := range buckets { b := &buckets[index] b.mu.Lock() defer b.mu.Unlock() counts[index] = b.guesses } // Marshal the report data into a JSON payload. b, err := json.Marshal(counts) if err != nil { log.Printf("failed to marshal report error=%s", err) return } url := "http://localhost:8091/guess-number-report" if _, err := http.Post(url, "application/json", bytes.NewReader(b)); err != nil { log.Printf("failed to send report: %s", err) } }

Oto pełny kod serwera: https://go.dev/play/p/rX1eyKtVglF, a dla prostego klienta: https://go.dev/play/p/2PjQ-1ORPiw. Aby uniknąć trzeciego procesu, "klient" implementuje również serwer raportów, choć w rzeczywistym systemie byłby on oddzielny.

\ Załóżmy, że po wdrożeniu aplikacji w produkcji otrzymaliśmy skargi od użytkowników, że niektóre wywołania /guess-number trwały dłużej niż oczekiwano. Gdy patrzymy na nasze logi, widzimy, że czasami czasy odpowiedzi przekraczają 100 milisekund, podczas gdy większość wywołań jest rzędu mikrosekund.

2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=69 duration=625ns 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=62 duration=458ns 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=42 duration=1.417µs 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=86 duration=115.186167ms 2025/09/19 16:52:02 HTTP request: endpoint=/guess-number guess=0 duration=127.993375ms

Zanim przejdziemy dalej, poświęć chwilę i sprawdź, czy możesz zauważyć, co jest nie tak!

\ Niezależnie od tego, czy znalazłeś problem, czy nie, zagłębmy się głębiej i zobaczmy, jak możemy znaleźć problem od podstaw. W szczególności byłoby świetnie, gdybyśmy mogli zobaczyć, co robiła aplikacja w czasie prowadzącym do wolnej odpowiedzi. To właśnie do tego został stworzony rejestrator lotu! Użyjemy go do przechwycenia śladu wykonania, gdy zobaczymy pierwszą odpowiedź przekraczającą 100 milisekund.

\ Najpierw w main skonfigurujemy i uruchomimy rejestrator lotu:

// Set up the flight recorder fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{ MinAge: 200 * time.Millisecond, MaxBytes: 1 << 20, // 1 MiB }) fr.Start()

MinAge konfiguruje czas, przez który dane śledzenia są niezawodnie przechowywane, i sugerujemy ustawienie go na około 2x okno czasowe zdarzenia. Na przykład, jeśli debugujesz 5-sekundowy limit czasu, ustaw go na 10 sekund. MaxBytes konfiguruje rozmiar buforowanego śladu, aby nie zwiększać zużycia pamięci. Średnio można oczekiwać kilku MB danych śledzenia na sekundę wykonania lub 10 MB/s dla zajętej usługi.

\ Następnie dodamy funkcję pomocniczą do przechwytywania migawki i zapisywania jej do pliku:

var once sync.Once // captureSnapshot captures a flight recorder snapshot. func captureSnapshot(fr *trace.FlightRecorder) { // once.Do ensures that the provided function is executed only once. once.Do(func() { f, err := os.Create("snapshot.trace") if err != nil { log.Printf("opening snapshot file %s failed: %s", f.Name(), err) return } defer f.Close() // ignore error // WriteTo writes the flight recorder data to the provided io.Writer. _, err = fr.WriteTo(f) if err != nil { log.Printf("writing snapshot to file %s failed: %s", f.Name(), err) return } // Stop the flight recorder after the snapshot has been taken. fr.Stop() log.Printf("captured a flight recorder snapshot to %s", f.Name()) }) }

\ I wreszcie, tuż przed zalogowaniem zakończonego żądania, uruchomimy migawkę, jeśli żądanie trwało dłużej niż 100 milisekund:

// Capture a snapshot if the response takes more than 100ms. // Only the first call has any effect. if fr.Enabled() && time.Since(start) > 100*time.Millisecond { go captureSnapshot(fr) }

\ Oto pełny kod serwera, teraz wyposażony w rejestrator lotu: https://go.dev/play/p/3V33gfIpmjG

\ Teraz uruchamiamy serwer ponownie i wysyłamy żądania, aż otrzymamy wolne żądanie, które wyzwoli migawkę.

\ Po uzyskaniu śladu będziemy potrzebować narzędzia, które pomoże nam go zbadać. Łańcuch narzędzi Go zapewnia wbudowane narzędzie do analizy śladu wykonania za pomocą polecenia go tool trace. Uruchom go tool trace snapshot.trace, aby uruchomić narzędzie, które uruchamia lokalny serwer internetowy, a następnie otwórz wyświetlony adres URL w przeglądarce (jeśli narzędzie nie otworzy przeglądarki automatycznie).

\ To narzędzie daje nam kilka sposobów na spojrzenie na ślad, ale skupmy się na wizualizacji śladu, aby zrozumieć, co się dzieje. Kliknij "View trace by proc", aby to zrobić.

\ W tym widoku ślad jest przedstawiony jako oś czasu zdarzeń. Na górze strony, w sekcji "STATS", możemy zobaczyć podsumowanie stanu aplikacji, w tym liczbę wątków, rozmiar sterty i liczbę gorutyn.

\ Poniżej, w sekcji "PROCS", możemy zobaczyć, jak wykonanie gorutyn jest mapowane na GOMAXPROCS (liczbę wątków systemu operacyjnego utworzonych przez aplikację Go). Możemy zobaczyć, kiedy i jak każda gorutyna zaczyna, działa i ostatecznie przestaje działać.

\ Na razie skupmy naszą uwagę na tej ogromnej luce w wykonaniu po prawej stronie przeglądarki. Przez pewien czas, około 100 ms, nic się nie dzieje!

Wybierając narzędzie zoom (lub naciskając 3), możemy zbadać sekcję śladu tuż po luce z większą szczegółowością.

\ Oprócz aktywności każdej pojedynczej gorutyny możemy zobaczyć, jak gorutyny wchodzą w interakcje za pomocą "zdarzeń przepływu". Przychodzące zdarzenie przepływu wskazuje, co się stało, aby gorutyna zaczęła działać. Wychodzące zdarzenie przepływu wskazuje, jaki wpływ jedna gorutyna miała na drugą. Włączenie wizualizacji wszystkich zdarzeń przepływu często dostarcza wskazówek, które sugerują źródło problemu.

W tym przypadku możemy zobaczyć, że wiele gorutyn ma bezpośrednie połączenie z pojedynczą gorutyną tuż po przerwie w aktywności.

\ Kliknięcie na pojedynczą gorutynę pokazuje tabelę zdarzeń wypełnioną wychodzącymi zdarzeniami przepływu, co odpowiada temu, co widzieliśmy, gdy widok przepływu był włączony.

\ Co się stało, gdy ta gorutyna działała? Część informacji przechowywanych w śladzie to widok śladu stosu w różnych punktach w czasie. Gdy patrzymy na gorutynę, możemy zobaczyć, że początkowy ślad stosu pokazuje, że czekała na zakończenie żądania HTTP, gdy gorutyna została zaplanowana do uruchomienia. A końcowy ślad stosu pokazuje, że funkcja sendReport już wróciła i czekała na ticker na następny zaplanowany czas wysłania raportu.

\ Między początkiem a końcem działania tej gorutyny widzimy ogromną liczbę "wychodzących przepływów", gdzie wchodzi ona w interakcje z innymi gorutynami. Kliknięcie na jednym z wpisów Outgoing flow przenosi nas do widoku interakcji.

\ Ten przepływ wskazuje na Unlock w sendReport:

for index := range buckets { b := &buckets[index] b.mu.Lock() defer b.mu.Unlock() counts[index] = b.guesses }

\ W sendReport zamierzaliśmy uzyskać blokadę na każdym wiaderku i zwolnić blokadę po skopiowaniu wartości.

\ Ale oto problem: nie zwalniamy blokady natychmiast po skopiowaniu wartości zawartej w bucket.guesses. Ponieważ użyliśmy instrukcji defer do zwolnienia blokady, to zwolnienie nie następuje, dopóki funkcja nie wróci. Utrzymujemy blokadę nie tylko poza końcem pętli, ale aż do zakończenia żądania HTTP. To subtelny błąd, który może być trudny do śledzenia w dużym systemie produkcyjnym.

\ Na szczęście śledzenie wykonania pomogło nam zlokalizować problem. Jednak gdybyśmy próbowali użyć narzędzia do śledzenia wykonania w długo działającym serwerze bez nowego trybu rejestracji lotu, prawdopodobnie zgromadziłoby ono ogromną ilość danych śledzenia wykonania, które operator musiałby przechowywać, przesyłać i przeszukiwać. Rejestrator lotu daje nam moc retrospekcji. Pozwala nam uchwycić tylko to, co poszło nie tak, po tym, jak już się stało, i szybko skupić się na przyczynie.

\ Rejestrator lotu to tylko najnowszy dodatek do zestawu narzędzi programisty Go do diagnozowania wewnętrznego działania działających aplikacji. Stale ulepszaliśmy śledzenie w ciągu ostatnich kilku wydań. Go 1.21 znacznie zmniejszyło narzut czasu wykonania śledzenia. Format śladu stał się bardziej solidny i również podzielny w wydaniu Go 1.22, prowadząc do funkcji takich jak rejestrator lotu. Narzędzia open-source, takie jak gotraceui, i nadchodząca możliwość programowego analizowania śladów wykonania to kolejne sposoby wykorzystania mocy śladów wykonania. Strona Diagnostyka wymienia wiele dodatkowych narzędzi do dyspozycji. Mamy nadzieję, że skorzystasz z nich podczas pisania i udoskonalania swoich aplikacji Go.

Podziękowania

Chcielibyśmy poświęcić chwilę, aby podziękować tym członkom społeczności, którzy byli aktywni w spotkaniach diagnostycznych, przyczynili się do projektów i przekazali opinie przez lata: Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham) i PJ Malloy (@thepudds).

\ Dyskusje, opinie i praca, którą wszyscy włożyliście, były instrumentalne w popychaniu nas do lepszej przyszłości diagnostycznej. Dziękujemy!

---

Carlos Amedee i Michael Knyszek

\ Ten artykuł jest dostępny na The Go Blog na licencji CC BY 4.0 DEED.

\ Zdjęcie autorstwa Lukasa Souzy na Unsplash

\