Flight Recorder: Un nou tracer de execuție Go

În 2024 am prezentat lumii urmăriri de execuție Go mai puternice. În acea postare de blog am oferit o privire asupra unor noi funcționalități pe care le puteam debloca cu noul nostru instrument de urmărire a execuției, inclusiv înregistrarea de zbor. Suntem bucuroși să anunțăm că înregistrarea de zbor este acum disponibilă în Go 1.25 și este un instrument nou puternic în setul de instrumente de diagnosticare Go.

Urmăriri de execuție

Mai întâi, o scurtă recapitulare a urmăririlor de execuție Go.

\ Runtime-ul Go poate fi configurat să scrie un jurnal care înregistrează multe dintre evenimentele care au loc în timpul execuției unei aplicații Go. Acest jurnal se numește urmărire de execuție runtime. Urmăririle de execuție Go conțin o multitudine de informații despre modul în care gorutinele interacționează între ele și cu sistemul subiacent. Acest lucru le face foarte utile pentru depanarea problemelor de latență, deoarece vă spun atât când gorutinele dvs. se execută, cât și, în mod crucial, când nu se execută.

\ Pachetul runtime/trace oferă un API pentru colectarea unei urmăriri de execuție într-o fereastră de timp dată prin apelarea runtime/trace.Start și runtime/trace.Stop. Acest lucru funcționează bine dacă codul pe care îl urmăriți este doar un test, un microbenchmark sau un instrument de linie de comandă. Puteți colecta o urmărire a execuției complete de la un capăt la altul sau doar a părților care vă interesează.

\ Cu toate acestea, în serviciile web cu execuție îndelungată, tipurile de aplicații pentru care Go este cunoscut, acest lucru nu este suficient. Serverele web pot funcționa zile sau chiar săptămâni, iar colectarea unei urmăriri a întregii execuții ar produce mult prea multe date pentru a le analiza. Adesea, doar o parte a execuției programului merge greșit, cum ar fi expirarea unei cereri sau un control de sănătate eșuat. În momentul în care se întâmplă, este deja prea târziu pentru a apela Start!

\ O modalitate de a aborda această problemă este de a eșantiona aleatoriu urmăriri de execuție din întreaga flotă. Deși această abordare este puternică și poate ajuta la găsirea problemelor înainte ca acestea să devină întreruperi, necesită multă infrastructură pentru a începe. Ar trebui stocate, triajate și procesate cantități mari de date de urmărire a execuției, dintre care multe nu vor conține nimic interesant. Iar când încercați să ajungeți la baza unei probleme specifice, este un non-starter.

Înregistrare de zbor

Aceasta ne aduce la înregistratorul de zbor.

\ Un program știe adesea când ceva a mers greșit, dar cauza principală s-ar fi putut întâmpla cu mult timp în urmă. Înregistratorul de zbor vă permite să colectați o urmărire a ultimelor câteva secunde de execuție care duc până în momentul în care un program detectează că a existat o problemă.

\ Înregistratorul de zbor colectează urmărirea execuției în mod normal, dar în loc să o scrie într-un socket sau un fișier, stochează în memorie ultimele câteva secunde ale urmăririi. În orice moment, programul poate solicita conținutul buffer-ului și poate face o captură exactă a ferestrei de timp problematice. Înregistratorul de zbor este ca un bisturiu care taie direct în zona problemei.

Exemplu

Să învățăm cum să folosim înregistratorul de zbor cu un exemplu. În mod specific, să-l folosim pentru a diagnostica o problemă de performanță cu un server HTTP care implementează un joc "ghicește numărul". Acesta expune un endpoint /guess-number care acceptă un număr întreg și răspunde apelantului informându-l dacă a ghicit numărul corect.

\ Există, de asemenea, o gorutină care, o dată pe minut, trimite un raport cu toate numerele ghicite către un alt serviciu printr-o cerere 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) } }

Iată codul complet pentru server: https://go.dev/play/p/rX1eyKtVglF, și pentru un client simplu: https://go.dev/play/p/2PjQ-1ORPiw. Pentru a evita un al treilea proces, "clientul" implementează și serverul de raportare, deși într-un sistem real acestea ar fi separate.

\ Să presupunem că după implementarea aplicației în producție, am primit plângeri de la utilizatori că unele apeluri /guess-number durau mai mult decât era de așteptat. Când ne uităm la jurnalele noastre, vedem că uneori timpii de răspuns depășesc 100 de milisecunde, în timp ce majoritatea apelurilor sunt de ordinul microsecundelor.

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

Înainte de a continua, luați un minut și vedeți dacă puteți observa ce este greșit!

\ Indiferent dacă ați găsit problema sau nu, să aprofundăm și să vedem cum putem găsi problema de la principii de bază. În special, ar fi grozav dacă am putea vedea ce făcea aplicația în timpul care a dus la răspunsul lent. Exact pentru asta a fost construit înregistratorul de zbor! Îl vom folosi pentru a captura o urmărire de execuție odată ce vedem primul răspuns care depășește 100 de milisecunde.

\ Mai întâi, în main, vom configura și porni înregistratorul de zbor:

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

MinAge configurează durata pentru care datele de urmărire sunt păstrate în mod fiabil, și sugerăm să o setați la aproximativ 2x fereastra de timp a evenimentului. De exemplu, dacă depanați un timeout de 5 secunde, setați-l la 10 secunde. MaxBytes configurează dimensiunea urmăririi stocate în buffer, astfel încât să nu vă epuizați memoria. În medie, vă puteți aștepta la câțiva MB de date de urmărire produse pe secundă de execuție, sau 10 MB/s pentru un serviciu ocupat.

\ În continuare, vom adăuga o funcție ajutătoare pentru a captura instantaneul și a-l scrie într-un fișier:

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 în final, chiar înainte de a înregistra o cerere completată, vom declanșa instantaneul dacă cererea a durat mai mult de 100 de milisecunde:

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

\ Iată codul complet pentru server, acum instrumentat cu înregistratorul de zbor: https://go.dev/play/p/3V33gfIpmjG

\ Acum, rulăm din nou serverul și trimitem cereri până când obținem o cerere lentă care declanșează un instantaneu.

\ Odată ce am obținut o urmărire, vom avea nevoie de un instrument care să ne ajute să o examinăm. Lanțul de instrumente Go oferă un instrument încorporat de analiză a urmăririi execuției prin comanda go tool trace. Rulați go tool trace snapshot.trace pentru a lansa instrumentul, care pornește un server web local, apoi deschideți URL-ul afișat în browser (dacă instrumentul nu vă deschide automat browserul).

\ Acest instrument ne oferă câteva modalități de a examina urmărirea, dar să ne concentrăm pe vizualizarea urmăririi pentru a înțelege ce se întâmplă. Faceți clic pe "View trace by proc" pentru a face acest lucru.

\ În această vizualizare, urmărirea este prezentată ca o cronologie a evenimentelor. În partea de sus a paginii, în secțiunea "STATS", putem vedea un rezumat al stării aplicației, inclusiv numărul de fire de execuție, dimensiunea heap-ului și numărul de gorutine.

\ Mai jos, în secțiunea "PROCS", putem vedea cum execuția gorutinelor este mapată pe GOMAXPROCS (numărul de fire de execuție ale sistemului de operare create de aplicația Go). Putem vedea când și cum fiecare gorutină începe, rulează și în final se oprește din execuție.

\ Pentru moment, să ne îndreptăm atenția către acest gol masiv în execuție din partea dreaptă a vizualizatorului. Pentru o perioadă de timp, în jur de 100ms, nu se întâmplă nimic!

Selectând instrumentul zoom (sau apăsând 3), putem inspecta secțiunea urmăririi imediat după gol cu mai multe detalii.

\ Pe lângă activitatea fiecărei gorutine individuale, putem vedea cum gorutinele interacționează prin "evenimente de flux". Un eveniment de flux de intrare indică ce s-a întâmplat pentru a face o gorutină să înceapă să ruleze. O margine de flux de ieșire indică ce efect a avut o gorutină asupra alteia. Activarea vizualizării tuturor evenimentelor de flux oferă adesea indicii care sugerează sursa unei probleme.

În acest caz, putem vedea că multe dintre gorutine au o conexiune directă cu o singură gorutină imediat după pauza în activitate.

\ Făcând clic pe gorutina unică se afișează un tabel de evenimente plin de evenimente de flux de ieșire, care corespunde cu ceea ce am văzut când vizualizarea fluxului a fost activată.

\ Ce s-a întâmplat când această gorutină a rulat? O parte din informațiile stocate în urmărire este o vizualizare a urmei stivei în diferite momente în timp. Când ne uităm la gorutină, putem vedea că urmărirea stivei de început arată că aștepta finalizarea cererii HTTP când gorutina a fost programată să ruleze. Iar urmărirea stivei de final arată că funcția sendReport se întorsese deja și aștepta cronometrul pentru următorul moment programat pentru a trimite raportul.

\ Între începutul și sfârșitul rulării acestei gorutine, vedem un număr uriaș de "fluxuri de ieșire", unde interacționează cu alte gorutine. Făcând clic pe una dintre intrările Outgoing flow ne duce la o vizualizare a interacțiunii.

\ Acest flux implică Unlock în sendReport:

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

\ În sendReport, am intenționat să achiziționăm un blocaj pentru fiecare bucket și să eliberăm blocajul după copierea valorii.

\ Dar iată problema: nu eliberăm de fapt blocajul imediat după copierea valorii conținute în bucket.guesses. Deoarece am folosit o instrucțiune defer pentru a elibera blocajul, acea eliberare nu are loc până când funcția nu se întoarce. Menținem blocajul nu doar după sfârșitul buclei, ci până după finalizarea cererii HTTP. Aceasta este o eroare subtilă care poate fi dificil de urmărit într-un sistem de producție mare.

\ Din fericire, urmărirea execuției ne-a ajutat să identificăm problema. Cu toate acestea, dacă am încerca să folosim instrumentul de urmărire a execuției într-un server cu execuție îndelungată fără noul mod de înregistrare de zbor, ar acumula probabil o cantitate uriașă de date de urmărire a execuției, pe care un operator ar trebui să le stocheze, să le transmită și să le analizeze. Înregistratorul de zbor ne oferă puterea retrospectivei. Ne permite să capturăm exact ce a mers greșit, după ce s-a întâmplat deja, și să identificăm rapid cauza.

\ Înregistratorul de zbor este doar cea mai recentă adăugare la setul de instrumente al dezvoltatorului Go pentru diagnosticarea funcționării interne a aplicațiilor în execuție. Am îmbunătățit constant urmărirea în ultimele câteva versiuni. Go 1.21 a redus considerabil overhead-ul de rulare al urmăririi. Formatul de urmărire a devenit mai robust și, de asemenea, divizibil în versiunea Go 1.22, ducând la caracteristici precum înregistratorul de zbor. Instrumente open-source precum gotraceui și viitoarea capacitate de a analiza programatic urmăririle de execuție sunt mai multe modalități de a valorifica puterea urmăririlor de execuție. Pagina de Diagnosticare enumeră multe instrumente suplimentare la dispoziția dvs. Sperăm că le veți folosi în timp ce scrieți și rafinați aplicațiile dvs. Go.

Mulțumiri

Am dori să luăm un moment pentru a mulțumi acelor membri ai comunității care au fost activi în întâlnirile de diagnosticare, au contribuit la design-uri și au oferit feedback de-a lungul anilor: Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham) și PJ Malloy (@thepudds).

\ Discuțiile, feedback-ul și munca pe care le-ați depus cu toții au fost instrumentale în a ne împinge către un viitor mai bun al diagnosticării. Vă mulțumim!

---

Carlos Amedee și Michael Knyszek

\ Acest articol este disponibil pe The Go Blog sub o licență CC BY 4.0 DEED.

\ Fotografie de Lukas Souza pe Unsplash

\