Flight Recorder: Een Nieuwe Go Execution Tracer

In 2024 hebben we de wereld kennis laten maken met krachtigere Go execution traces. In dat blogbericht gaven we een voorproefje van enkele nieuwe functionaliteiten die we konden ontsluiten met onze nieuwe execution tracer, waaronder flight recording. We zijn blij om aan te kondigen dat flight recording nu beschikbaar is in Go 1.25, en het is een krachtig nieuw hulpmiddel in de Go diagnostische toolbox.

Execution traces

Eerst een korte samenvatting over Go execution traces.

\ De Go runtime kan worden ingesteld om een logboek te schrijven dat veel gebeurtenissen registreert die plaatsvinden tijdens de uitvoering van een Go-applicatie. Dat logboek wordt een runtime execution trace genoemd. Go execution traces bevatten een overvloed aan informatie over hoe goroutines met elkaar en met het onderliggende systeem interacteren. Dit maakt ze zeer handig voor het debuggen van latentieproblemen, omdat ze je zowel vertellen wanneer je goroutines worden uitgevoerd, als, cruciaal, wanneer ze dat niet worden.

\ Het runtime/trace pakket biedt een API voor het verzamelen van een execution trace over een bepaald tijdsvenster door het aanroepen van runtime/trace.Start en runtime/trace.Stop. Dit werkt goed als de code die je traceert slechts een test, microbenchmark of command line tool is. Je kunt een trace verzamelen van de volledige end-to-end uitvoering, of alleen van de delen waar je om geeft.

\ Echter, in langlopende webservices, het soort applicaties waar Go bekend om staat, is dat niet goed genoeg. Webservers kunnen dagen of zelfs weken actief zijn, en het verzamelen van een trace van de volledige uitvoering zou veel te veel gegevens produceren om door te spitten. Vaak gaat slechts één deel van de uitvoering van het programma fout, zoals een time-out van een verzoek of een mislukte gezondheidscontrole. Tegen de tijd dat het gebeurt, is het al te laat om Start aan te roepen!

\ Een manier om dit probleem aan te pakken is om willekeurig execution traces te samplen van de hele vloot. Hoewel deze aanpak krachtig is en kan helpen problemen te vinden voordat ze uitval veroorzaken, vereist het veel infrastructuur om op gang te komen. Grote hoeveelheden execution trace gegevens zouden moeten worden opgeslagen, getrieerd en verwerkt, waarvan veel helemaal niets interessants zal bevatten. En wanneer je probeert tot de kern van een specifiek probleem te komen, is het een non-starter.

Flight recording

Dit brengt ons bij de flight recorder.

\ Een programma weet vaak wanneer er iets mis is gegaan, maar de hoofdoorzaak kan lang geleden zijn gebeurd. De flight recorder stelt je in staat om een trace te verzamelen van de laatste paar seconden van uitvoering die leiden tot het moment waarop een programma detecteert dat er een probleem is geweest.

\ De flight recorder verzamelt de execution trace zoals normaal, maar in plaats van deze naar een socket of een bestand te schrijven, buffert het de laatste paar seconden van de trace in het geheugen. Op elk moment kan het programma de inhoud van de buffer opvragen en een snapshot maken van precies het problematische tijdsvenster. De flight recorder is als een scalpel dat direct naar het probleemgebied snijdt.

Voorbeeld

Laten we leren hoe we de flight recorder kunnen gebruiken met een voorbeeld. Specifiek, laten we het gebruiken om een prestatieprobleem te diagnosticeren met een HTTP-server die een "raad het getal" spel implementeert. Het stelt een /guess-number endpoint beschikbaar dat een geheel getal accepteert en reageert naar de beller om hen te informeren of ze het juiste getal hebben geraden.

\ Er is ook een goroutine die, eenmaal per minuut, een rapport van alle geraden getallen naar een andere service stuurt via een HTTP-verzoek.

// 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) } }

Hier is de volledige code voor de server: https://go.dev/play/p/rX1eyKtVglF, en voor een eenvoudige client: https://go.dev/play/p/2PjQ-1ORPiw. Om een derde proces te vermijden, implementeert de "client" ook de rapportserver, hoewel dit in een echt systeem gescheiden zou zijn.

\ Laten we aannemen dat na het implementeren van de applicatie in productie, we klachten ontvingen van gebruikers dat sommige /guess-number aanroepen langer duurden dan verwacht. Wanneer we naar onze logs kijken, zien we dat soms responstijden meer dan 100 milliseconden bedragen, terwijl de meerderheid van de aanroepen in de orde van microseconden ligt.

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

Voordat we verdergaan, neem een minuut en kijk of je kunt zien wat er mis is!

\ Ongeacht of je het probleem hebt gevonden of niet, laten we dieper duiken en zien hoe we het probleem kunnen vinden vanuit eerste principes. In het bijzonder zou het geweldig zijn als we konden zien wat de applicatie deed in de tijd voorafgaand aan de trage respons. Dit is precies waarvoor de flight recorder is gebouwd! We zullen het gebruiken om een execution trace vast te leggen zodra we de eerste respons zien die 100 milliseconden overschrijdt.

\ Eerst, in main, zullen we de flight recorder configureren en starten:

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

MinAge configureert de duur waarvoor trace-gegevens betrouwbaar worden bewaard, en we raden aan om deze in te stellen op ongeveer 2x het tijdsvenster van de gebeurtenis. Als je bijvoorbeeld een time-out van 5 seconden debugt, stel het dan in op 10 seconden. MaxBytes configureert de grootte van de gebufferde trace zodat je je geheugengebruik niet opblaast. Gemiddeld kun je een paar MB aan trace-gegevens verwachten per seconde uitvoering, of 10 MB/s voor een drukke service.

\ Vervolgens voegen we een hulpfunctie toe om de snapshot vast te leggen en naar een bestand te schrijven:

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()) }) }

\ En tenslotte, net voordat we een voltooide aanvraag loggen, zullen we de snapshot triggeren als de aanvraag meer dan 100 milliseconden duurde:

// 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) }

\ Hier is de volledige code voor de server, nu geïnstrumenteerd met de flight recorder: https://go.dev/play/p/3V33gfIpmjG

\ Nu voeren we de server opnieuw uit en sturen we verzoeken totdat we een traag verzoek krijgen dat een snapshot triggert.

\ Zodra we een trace hebben, hebben we een tool nodig die ons helpt deze te onderzoeken. De Go toolchain biedt een ingebouwde execution trace analyse tool via het go tool trace commando. Voer go tool trace snapshot.trace uit om de tool te starten, die een lokale webserver start, en open vervolgens de weergegeven URL in je browser (als de tool je browser niet automatisch opent).

\ Deze tool geeft ons een paar manieren om naar de trace te kijken, maar laten we ons concentreren op het visualiseren van de trace om een idee te krijgen van wat er aan de hand is. Klik op "View trace by proc" om dit te doen.

\ In deze weergave wordt de trace gepresenteerd als een tijdlijn van gebeurtenissen. Bovenaan de pagina, in de sectie "STATS", kunnen we een samenvatting zien van de toestand van de applicatie, inclusief het aantal threads, de heap-grootte en het aantal goroutines.

\ Daaronder, in de sectie "PROCS", kunnen we zien hoe de uitvoering van goroutines wordt toegewezen aan GOMAXPROCS (het aantal besturingssysteem threads dat door de Go-applicatie wordt gemaakt). We kunnen zien wanneer en hoe elke goroutine start, draait en uiteindelijk stopt met uitvoeren.

\ Laten we nu onze aandacht richten op deze enorme kloof in de uitvoering aan de rechterkant van de viewer. Gedurende een periode van ongeveer 100ms gebeurt er niets!

Door het zoom gereedschap te selecteren (of door op 3 te drukken), kunnen we het gedeelte van de trace direct na de kloof met meer detail inspecteren.

\ Naast de activiteit van elke individuele goroutine kunnen we zien hoe goroutines interacteren via "flow events." Een inkomend flow event geeft aan wat er gebeurde om een goroutine te laten starten. Een uitgaande flow edge geeft aan welk effect de ene goroutine had op een andere. Het inschakelen van de visualisatie van alle flow events geeft vaak aanwijzingen die wijzen op de bron van een probleem.

In dit geval kunnen we zien dat veel van de goroutines een directe verbinding hebben met een enkele goroutine direct na de pauze in activiteit.

\ Door op de enkele goroutine te klikken, wordt een gebeurtenistabel getoond gevuld met uitgaande flow events, wat overeenkomt met wat we zagen toen de flow-weergave was ingeschakeld.

\ Wat gebeurde er toen deze goroutine werd uitgevoerd? Een deel van de informatie die in de trace is opgeslagen, is een weergave van de stack trace op verschillende tijdstippen. Wanneer we naar de goroutine kijken, kunnen we zien dat de start stack trace laat zien dat deze wachtte op de voltooiing van het HTTP-verzoek toen de goroutine werd gepland om uit te voeren. En de eind stack trace laat zien dat de functie sendReport al was teruggekeerd en dat deze wachtte op de ticker voor de volgende geplande tijd om het rapport te verzenden.

\ Tussen het begin en het einde van deze goroutine die wordt uitgevoerd, zien we een enorm aantal "outgoing flows", waar het interactie heeft met andere goroutines. Door op een van de Outgoing flow items te klikken, komen we bij een weergave van de interactie.

\ Deze flow impliceert de Unlock in sendReport:

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

\ In sendReport wilden we een lock verkrijgen op elke bucket en de lock vrijgeven na het kopiëren van de waarde.

\ Maar hier is het probleem: we geven de lock niet onmiddellijk vrij na het kopiëren van de waarde in bucket.guesses. Omdat we een defer statement gebruikten om de lock vrij te geven, gebeurt die vrijgave pas wanneer de functie terugkeert. We houden de lock niet alleen vast tot na het einde van de lus, maar tot na de voltooiing van het HTTP-verzoek. Dat is een subtiele fout die moeilijk op te sporen kan zijn in een groot productiesysteem.

\ Gelukkig hielp execution tracing ons het probleem precies te lokaliseren. Als we echter de execution tracer in een langlopende server zouden proberen te gebruiken zonder de nieuwe flight-recording modus, zou het waarschijnlijk een enorme hoeveelheid execution trace gegevens verzamelen, die een operator zou moeten opslaan, verzenden en doorzoeken. De flight recorder geeft ons de kracht van terugblik. Het stelt ons in staat om precies vast te leggen wat er mis ging, nadat het al is gebeurd, en snel in te zoomen op de oorzaak.

\ De flight recorder is slechts de nieuwste toevoeging aan de toolbox van de Go-ontwikkelaar voor het diagnosticeren van de interne werking van draaiende applicaties. We hebben de tracing gestaag verbeterd over de afgelopen paar releases. Go 1.21 verminderde de runtime overhead van tracing aanzienlijk. Het trace-formaat werd robuuster en ook splitsbaar in de Go 1.22 release, wat leidde tot functies zoals de flight recorder. Open-source tools zoals gotraceui, en de aankomende mogelijkheid om execution traces programmatisch te parseren zijn meer manieren om de kracht van execution traces te benutten. De Diagnostics-pagina vermeldt vele aanvullende tools tot je beschikking. We hopen dat je er gebruik van maakt terwijl je je Go-applicaties schrijft en verfijnt.

Dankwoord

We willen even de tijd nemen om die gemeenschapsleden te bedanken die actief zijn geweest in de diagnostische vergaderingen, hebben bijgedragen aan de ontwerpen en feedback hebben gegeven door de jaren heen: Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham), en PJ Malloy (@thepudds).

\ De discussies, feedback en het werk dat jullie allemaal hebben geleverd, zijn van instrumenteel belang geweest bij het streven naar een betere diagnostische toekomst. Bedankt!

Carlos Amedee en Michael Knyszek

\ Dit artikel is beschikbaar op The Go Blog onder een CC BY 4.0 DEED licentie.

\ Foto door Lukas Souza op Unsplash

\