Flight Recorder : Un nouveau traceur d'exécution Go

En 2024, nous avons présenté au monde des traces d'exécution Go plus puissantes. Dans ce billet de blog, nous avons donné un aperçu de certaines des nouvelles fonctionnalités que nous pourrions débloquer avec notre nouveau traceur d'exécution, y compris l'enregistrement de vol. Nous sommes heureux d'annoncer que l'enregistrement de vol est maintenant disponible dans Go 1.25, et c'est un nouvel outil puissant dans la boîte à outils de diagnostic de Go.

Traces d'exécution

Tout d'abord, un bref rappel sur les traces d'exécution Go.

\ Le runtime Go peut être configuré pour écrire un journal enregistrant de nombreux événements qui se produisent pendant l'exécution d'une application Go. Ce journal est appelé trace d'exécution du runtime. Les traces d'exécution Go contiennent une pléthore d'informations sur la façon dont les goroutines interagissent entre elles et avec le système sous-jacent. Cela les rend très pratiques pour déboguer les problèmes de latence, car elles vous indiquent à la fois quand vos goroutines s'exécutent et, de manière cruciale, quand elles ne s'exécutent pas.

\ Le package runtime/trace fournit une API pour collecter une trace d'exécution sur une fenêtre de temps donnée en appelant runtime/trace.Start et runtime/trace.Stop. Cela fonctionne bien si le code que vous tracez n'est qu'un test, un micro-benchmark ou un outil en ligne de commande. Vous pouvez collecter une trace de l'exécution complète de bout en bout, ou simplement des parties qui vous intéressent.

\ Cependant, dans les services web à longue durée d'exécution, les types d'applications pour lesquels Go est connu, ce n'est pas suffisant. Les serveurs web peuvent fonctionner pendant des jours, voire des semaines, et la collecte d'une trace de l'ensemble de l'exécution produirait beaucoup trop de données à trier. Souvent, une seule partie de l'exécution du programme échoue, comme une requête qui expire ou un contrôle de santé qui échoue. Au moment où cela se produit, il est déjà trop tard pour appeler Start !

\ Une façon d'aborder ce problème est d'échantillonner aléatoirement des traces d'exécution dans l'ensemble de la flotte. Bien que cette approche soit puissante et puisse aider à trouver des problèmes avant qu'ils ne deviennent des pannes, elle nécessite beaucoup d'infrastructure pour démarrer. De grandes quantités de données de trace d'exécution devraient être stockées, triées et traitées, dont une grande partie ne contiendra rien d'intéressant du tout. Et lorsque vous essayez de comprendre un problème spécifique, c'est un non-démarrage.

Enregistrement de vol

Cela nous amène à l'enregistreur de vol.

\ Un programme sait souvent quand quelque chose a mal tourné, mais la cause première peut s'être produite il y a longtemps. L'enregistreur de vol vous permet de collecter une trace des dernières secondes d'exécution menant au moment où un programme détecte qu'il y a eu un problème.

\ L'enregistreur de vol collecte la trace d'exécution normalement, mais au lieu de l'écrire dans une socket ou un fichier, il met en mémoire tampon les dernières secondes de la trace. À tout moment, le programme peut demander le contenu du tampon et prendre un instantané exactement de la fenêtre de temps problématique. L'enregistreur de vol est comme un scalpel coupant directement vers la zone problématique.

Exemple

Apprenons à utiliser l'enregistreur de vol avec un exemple. Plus précisément, utilisons-le pour diagnostiquer un problème de performance avec un serveur HTTP qui implémente un jeu "devinez le nombre". Il expose un point de terminaison /guess-number qui accepte un entier et répond à l'appelant en l'informant s'il a deviné le bon nombre.

\ Il y a aussi une goroutine qui, une fois par minute, envoie un rapport de tous les nombres devinés à un autre service via une requête 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 data: 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) } }

Voici le code complet pour le serveur : https://go.dev/play/p/rX1eyKtVglF, et pour un client simple : https://go.dev/play/p/2PjQ-1ORPiw. Pour éviter un troisième processus, le "client" implémente également le serveur de rapport, bien que dans un système réel, ce serait séparé.

\ Supposons qu'après avoir déployé l'application en production, nous avons reçu des plaintes d'utilisateurs selon lesquelles certains appels /guess-number prenaient plus de temps que prévu. Lorsque nous examinons nos journaux, nous constatons que parfois les temps de réponse dépassent 100 millisecondes, alors que la majorité des appels sont de l'ordre de microsecondes.

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

Avant de continuer, prenez une minute et voyez si vous pouvez repérer ce qui ne va pas !

\ Que vous ayez trouvé le problème ou non, plongeons plus profondément et voyons comment nous pouvons trouver le problème à partir des premiers principes. En particulier, ce serait génial si nous pouvions voir ce que l'application faisait dans le temps menant à la réponse lente. C'est exactement pour cela que l'enregistreur de vol a été conçu ! Nous l'utiliserons pour capturer une trace d'exécution une fois que nous verrons la première réponse dépassant 100 millisecondes.

\ D'abord, dans main, nous allons configurer et démarrer l'enregistreur de vol :

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

MinAge configure la durée pendant laquelle les données de trace sont conservées de manière fiable, et nous suggérons de la définir à environ 2 fois la fenêtre de temps de l'événement. Par exemple, si vous déboguez un délai d'attente de 5 secondes, définissez-le à 10 secondes. MaxBytes configure la taille de la trace mise en mémoire tampon afin que vous ne fassiez pas exploser votre utilisation de mémoire. En moyenne, vous pouvez vous attendre à quelques Mo de données de trace produites par seconde d'exécution, ou 10 Mo/s pour un service occupé.

\ Ensuite, nous allons ajouter une fonction d'aide pour capturer l'instantané et l'écrire dans un fichier :

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

\ Et enfin, juste avant de journaliser une requête terminée, nous déclencherons l'instantané si la requête a pris plus de 100 millisecondes :

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

\ Voici le code complet pour le serveur, maintenant instrumenté avec l'enregistreur de vol : https://go.dev/play/p/3V33gfIpmjG

\ Maintenant, nous exécutons à nouveau le serveur et envoyons des requêtes jusqu'à ce que nous obtenions une requête lente qui déclenche un instantané.

\ Une fois que nous avons obtenu une trace, nous aurons besoin d'un outil qui nous aidera à l'examiner. La chaîne d'outils Go fournit un outil d'analyse de trace d'exécution intégré via la commande go tool trace. Exécutez go tool trace snapshot.trace pour lancer l'outil, qui démarre un serveur web local, puis ouvrez l'URL affichée dans votre navigateur (si l'outil n'ouvre pas automatiquement votre navigateur).

\ Cet outil nous donne quelques façons de regarder la trace, mais concentrons-nous sur la visualisation de la trace pour avoir une idée de ce qui se passe. Cliquez sur "View trace by proc" pour ce faire.

\ Dans cette vue, la trace est présentée comme une chronologie d'événements. En haut de la page, dans la section "STATS", nous pouvons voir un résumé de l'état de l'application, y compris le nombre de threads, la taille du tas et le nombre de goroutines.

\ En dessous, dans la section "PROCS", nous pouvons voir comment l'exécution des goroutines est mappée sur GOMAXPROCS (le nombre de threads du système d'exploitation créés par l'application Go). Nous pouvons voir quand et comment chaque goroutine démarre, s'exécute et finalement s'arrête.

\ Pour l'instant, tournons notre attention vers cet énorme écart dans l'exécution sur le côté droit de la visionneuse. Pendant une période de temps, environ 100ms, rien ne se passe !

En sélectionnant l'outil zoom (ou en appuyant sur 3), nous pouvons inspecter la section de la trace juste après l'écart avec plus de détails.

\ En plus de l'activité de chaque goroutine individuelle, nous pouvons voir comment les goroutines interagissent via des "événements de flux". Un événement de flux entrant indique ce qui s'est passé pour faire démarrer une goroutine. Un bord de flux sortant indique quel effet une goroutine a eu sur une autre. L'activation de la visualisation de tous les événements de flux fournit souvent des indices qui suggèrent la source d'un problème.

Dans ce cas, nous pouvons voir que de nombreuses goroutines ont une connexion directe à une seule goroutine juste après la pause dans l'activité.

\ En cliquant sur la goroutine unique, on affiche un tableau d'événements rempli d'événements de flux sortants, ce qui correspond à ce que nous avons vu lorsque la vue de flux était activée.

\ Que s'est-il passé lorsque cette goroutine s'est exécutée ? Une partie des informations stockées dans la trace est une vue de la trace de pile à différents moments. Lorsque nous regardons la goroutine, nous pouvons voir que la trace de pile de départ montre qu'elle attendait que la requête HTTP soit terminée lorsque la goroutine a été programmée pour s'exécuter. Et la trace de pile de fin montre que la fonction sendReport était déjà retournée et qu'elle attendait le ticker pour le prochain moment prévu pour envoyer le rapport.

\ Entre le début et la fin de l'exécution de cette goroutine, nous voyons un grand nombre de "flux sortants", où elle interagit avec d'autres goroutines. Cliquer sur l'une des entrées Outgoing flow nous amène à une vue de l'interaction.

\ Ce flux implique le Unlock dans sendReport :

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

\ Dans sendReport, nous avions l'intention d'acquérir un verrou sur chaque bucket et de libérer le verrou après avoir copié la valeur.

\ Mais voici le problème : nous ne libérons pas réellement le verrou immédiatement après avoir copié la valeur contenue dans bucket.guesses. Parce que nous avons utilisé une instruction defer pour libérer le verrou, cette libération ne se produit pas avant que la fonction ne retourne. Nous conservons le verrou non seulement au-delà de la fin de la boucle, mais jusqu'après la fin de la requête HTTP. C'est une erreur subtile qui peut être difficile à traquer dans un grand système de production.

\ Heureusement, le traçage d'exécution nous a aidés à identifier le problème. Cependant, si nous essayions d'utiliser le traceur d'exécution dans un serveur à longue durée d'exécution sans le nouveau mode d'enregistrement de vol, il accumulerait probablement une énorme quantité de données de trace d'exécution, qu'un opérateur devrait stocker, transmettre et trier. L'enregistreur de vol nous donne le pouvoir du recul. Il nous permet de capturer exactement ce qui a mal tourné, après que cela se soit déjà produit, et de cibler rapidement la cause.

\ L'enregistreur de vol est juste la dernière addition à la boîte à outils du développeur Go pour diagnostiquer le fonctionnement interne des applications en cours d'exécution. Nous avons constamment amélioré le traçage au cours des dernières versions. Go 1.21 a considérablement réduit la surcharge d'exécution du traçage. Le format de trace est devenu plus robuste et également divisible dans la version Go 1.22, conduisant à des fonctionnalités comme l'enregistreur de vol. Des outils open-source comme gotraceui, et la capacité à venir d'analyser programmatiquement les traces d'exécution sont d'autres moyens de tirer parti de la puissance des traces d'exécution. La page Diagnostics liste de nombreux outils supplémentaires à votre disposition. Nous espérons que vous les utiliserez lorsque vous écrirez et affinerez vos applications Go.

Remerciements

Nous aimerions prendre un moment pour remercier les membres de la communauté qui ont été actifs dans les réunions de diagnostic, ont contribué aux conceptions et ont fourni des commentaires au fil des ans : Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham), et PJ Malloy (@thepudds).

\ Les discussions, les commentaires et le travail que vous avez tous fournis ont été déterminants pour nous pousser vers un meilleur avenir en matière de diagnostic. Merci !

Carlos Amedee et Michael Knyszek

\ Cet article est disponible sur The Go Blog sous une licence CC BY 4.0 DEED.

\ Photo par Lukas Souza sur Unsplash

\