Flight Recorder: Pelacak Eksekusi Go yang Baru

Pada tahun 2024 kami memperkenalkan dunia pada jejak eksekusi Go yang lebih kuat. Dalam posting blog tersebut kami memberikan sekilas tentang beberapa fungsi baru yang dapat kami buka dengan pelacak eksekusi baru kami, termasuk perekaman penerbangan. Kami senang mengumumkan bahwa perekaman penerbangan sekarang tersedia di Go 1.25, dan ini adalah alat baru yang kuat dalam kotak alat diagnostik Go.

Jejak eksekusi

Pertama, sekilas tentang jejak eksekusi Go.

\ Runtime Go dapat dibuat untuk menulis log yang merekam banyak peristiwa yang terjadi selama eksekusi aplikasi Go. Log tersebut disebut jejak eksekusi runtime. Jejak eksekusi Go berisi banyak informasi tentang bagaimana goroutine berinteraksi satu sama lain dan dengan sistem yang mendasarinya. Ini membuat mereka sangat berguna untuk men-debug masalah latensi, karena mereka memberi tahu Anda kapan goroutine Anda dieksekusi, dan yang penting, kapan mereka tidak.

\ Paket runtime/trace menyediakan API untuk mengumpulkan jejak eksekusi selama jendela waktu tertentu dengan memanggil runtime/trace.Start dan runtime/trace.Stop. Ini berfungsi dengan baik jika kode yang Anda lacak hanyalah tes, microbenchmark, atau alat command line. Anda dapat mengumpulkan jejak dari eksekusi end-to-end lengkap, atau hanya bagian yang Anda pedulikan.

\ Namun, dalam layanan web yang berjalan lama, jenis aplikasi yang dikenal Go, itu tidak cukup baik. Server web mungkin aktif selama berhari-hari atau bahkan berminggu-minggu, dan mengumpulkan jejak dari seluruh eksekusi akan menghasilkan terlalu banyak data untuk disaring. Seringkali hanya satu bagian dari eksekusi program yang salah, seperti permintaan yang habis waktu atau pemeriksaan kesehatan yang gagal. Pada saat itu terjadi, sudah terlambat untuk memanggil Start!

\ Salah satu cara untuk mendekati masalah ini adalah dengan mengambil sampel jejak eksekusi secara acak dari seluruh armada. Meskipun pendekatan ini kuat, dan dapat membantu menemukan masalah sebelum menjadi pemadaman, ini membutuhkan banyak infrastruktur untuk memulai. Sejumlah besar data jejak eksekusi perlu disimpan, dipilah, dan diproses, yang banyak di antaranya tidak akan berisi apa pun yang menarik sama sekali. Dan ketika Anda mencoba untuk menyelidiki masalah tertentu, ini bukan pilihan.

Perekaman penerbangan

Ini membawa kita ke perekam penerbangan.

\ Program sering tahu ketika sesuatu telah salah, tetapi akar penyebabnya mungkin telah terjadi lama sebelumnya. Perekam penerbangan memungkinkan Anda mengumpulkan jejak dari beberapa detik terakhir eksekusi yang mengarah ke saat program mendeteksi ada masalah.

\ Perekam penerbangan mengumpulkan jejak eksekusi seperti biasa, tetapi alih-alih menuliskannya ke soket atau file, ia menyangga beberapa detik terakhir dari jejak dalam memori. Pada titik mana pun, program dapat meminta isi buffer dan mengambil snapshot tepat pada jendela waktu yang bermasalah. Perekam penerbangan seperti pisau bedah yang memotong langsung ke area masalah.

Contoh

Mari kita pelajari cara menggunakan perekam penerbangan dengan contoh. Secara khusus, mari kita gunakan untuk mendiagnosis masalah kinerja dengan server HTTP yang mengimplementasikan permainan "tebak angka". Ini mengekspos endpoint /guess-number yang menerima bilangan bulat dan merespons pemanggil dengan memberi tahu mereka apakah mereka menebak angka yang benar.

\ Ada juga goroutine yang, sekali per menit, mengirimkan laporan semua angka yang ditebak ke layanan lain melalui permintaan 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) } }

Berikut adalah kode lengkap untuk server: https://go.dev/play/p/rX1eyKtVglF, dan untuk klien sederhana: https://go.dev/play/p/2PjQ-1ORPiw. Untuk menghindari proses ketiga, "klien" juga mengimplementasikan server laporan, meskipun dalam sistem nyata ini akan terpisah.

\ Misalkan setelah menerapkan aplikasi di produksi, kami menerima keluhan dari pengguna bahwa beberapa panggilan /guess-number memakan waktu lebih lama dari yang diharapkan. Ketika kami melihat log kami, kami melihat bahwa terkadang waktu respons melebihi 100 milidetik, sementara mayoritas panggilan dalam urutan mikrodetik.

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

Sebelum kita lanjutkan, luangkan waktu sebentar dan lihat apakah Anda dapat menemukan apa yang salah!

\ Terlepas dari apakah Anda menemukan masalahnya atau tidak, mari kita menyelami lebih dalam dan melihat bagaimana kita dapat menemukan masalah dari prinsip pertama. Secara khusus, akan sangat bagus jika kita bisa melihat apa yang dilakukan aplikasi pada waktu menjelang respons lambat. Ini persis untuk apa perekam penerbangan dibuat! Kita akan menggunakannya untuk menangkap jejak eksekusi setelah kita melihat respons pertama yang melebihi 100 milidetik.

\ Pertama, di main, kita akan mengonfigurasi dan memulai perekam penerbangan:

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

MinAge mengonfigurasi durasi di mana data jejak dapat diandalkan dipertahankan, dan kami menyarankan untuk mengaturnya sekitar 2x jendela waktu peristiwa. Misalnya, jika Anda men-debug batas waktu 5 detik, atur ke 10 detik. MaxBytes mengonfigurasi ukuran jejak yang di-buffer sehingga Anda tidak meledakkan penggunaan memori Anda. Rata-rata, Anda dapat mengharapkan beberapa MB data jejak diproduksi per detik eksekusi, atau 10 MB/s untuk layanan yang sibuk.

\ Selanjutnya, kita akan menambahkan fungsi pembantu untuk menangkap snapshot dan menuliskannya ke file:

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

\ Dan akhirnya, tepat sebelum mencatat permintaan yang selesai, kita akan memicu snapshot jika permintaan memakan waktu lebih dari 100 milidetik:

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

\ Berikut adalah kode lengkap untuk server, sekarang diinstrumentasi dengan perekam penerbangan: https://go.dev/play/p/3V33gfIpmjG

\ Sekarang, kita menjalankan server lagi dan mengirim permintaan sampai kita mendapatkan permintaan lambat yang memicu snapshot.

\ Setelah kita mendapatkan jejak, kita akan membutuhkan alat yang akan membantu kita memeriksanya. Toolchain Go menyediakan alat analisis jejak eksekusi bawaan melalui perintah go tool trace. Jalankan go tool trace snapshot.trace untuk meluncurkan alat, yang memulai server web lokal, kemudian buka URL yang ditampilkan di browser Anda (jika alat tidak membuka browser Anda secara otomatis).

\ Alat ini memberi kita beberapa cara untuk melihat jejak, tetapi mari kita fokus pada visualisasi jejak untuk mendapatkan gambaran tentang apa yang terjadi. Klik "View trace by proc" untuk melakukannya.

\ Dalam tampilan ini, jejak disajikan sebagai garis waktu peristiwa. Di bagian atas halaman, di bagian "STATS", kita dapat melihat ringkasan keadaan aplikasi, termasuk jumlah thread, ukuran heap, dan jumlah goroutine.

\ Di bawah itu, di bagian "PROCS", kita dapat melihat bagaimana eksekusi goroutine dipetakan ke GOMAXPROCS (jumlah thread sistem operasi yang dibuat oleh aplikasi Go). Kita dapat melihat kapan dan bagaimana setiap goroutine mulai, berjalan, dan akhirnya berhenti dieksekusi.

\ Untuk saat ini, mari kita alihkan perhatian kita ke celah besar dalam eksekusi di sisi kanan penampil. Selama periode waktu, sekitar 100ms, tidak ada yang terjadi!

Dengan memilih alat zoom (atau menekan 3), kita dapat memeriksa bagian jejak tepat setelah celah dengan lebih detail.

\ Selain aktivitas masing-masing goroutine, kita dapat melihat bagaimana goroutine berinteraksi melalui "peristiwa aliran." Peristiwa aliran masuk menunjukkan apa yang terjadi untuk membuat goroutine mulai berjalan. Tepi aliran keluar menunjukkan efek apa yang dimiliki satu goroutine terhadap yang lain. Mengaktifkan visualisasi semua peristiwa aliran sering memberikan petunjuk yang mengarah pada sumber masalah.

Dalam kasus ini, kita dapat melihat bahwa banyak goroutine memiliki koneksi langsung ke satu goroutine tepat setelah jeda dalam aktivitas.

\ Mengklik goroutine tunggal menunjukkan tabel peristiwa yang dipenuhi dengan peristiwa aliran keluar, yang cocok dengan apa yang kita lihat ketika tampilan aliran diaktifkan.

\ Apa yang terjadi ketika goroutine ini berjalan? Bagian dari informasi yang disimpan dalam jejak adalah tampilan jejak tumpukan pada titik waktu yang berbeda. Ketika kita melihat goroutine, kita dapat melihat bahwa jejak tumpukan awal menunjukkan bahwa itu sedang menunggu permintaan HTTP selesai ketika goroutine dijadwalkan untuk berjalan. Dan jejak tumpukan akhir menunjukkan bahwa fungsi sendReport telah kembali dan itu sedang menunggu ticker untuk waktu terjadwal berikutnya untuk mengirim laporan.

\ Antara awal dan akhir goroutine ini berjalan, kita melihat sejumlah besar "aliran keluar," di mana ia berinteraksi dengan goroutine lain. Mengklik salah satu entri Outgoing flow membawa kita ke tampilan interaksi.

\ Aliran ini melibatkan Unlock di sendReport:

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

\ Di sendReport, kami bermaksud untuk memperoleh kunci pada setiap bucket dan melepaskan kunci setelah menyalin nilai.

\ Tapi inilah masalahnya: kita tidak benar-benar melepaskan kunci segera setelah menyalin nilai yang terkandung dalam bucket.guesses. Karena kita menggunakan pernyataan defer untuk melepaskan kunci, pelepasan itu tidak terjadi sampai fungsi kembali. Kita memegang kunci tidak hanya melewati akhir loop, tetapi sampai setelah permintaan HTTP selesai. Itu adalah kesalahan halus yang mungkin sulit dilacak dalam sistem produksi besar.

\ Untungnya, pelacakan eksekusi membantu kita menentukan masalah. Namun, jika kita mencoba menggunakan pelacak eksekusi dalam server yang berjalan lama tanpa mode perekaman penerbangan baru, kemungkinan akan mengumpulkan sejumlah besar data jejak eksekusi, yang harus disimpan, ditransmisikan, dan disaring oleh operator. Perekam penerbangan memberi kita kekuatan pandangan ke belakang. Ini memungkinkan kita menangkap apa yang salah, setelah itu terjadi, dan dengan cepat menentukan penyebabnya.

\ Perekam penerbangan hanyalah tambahan terbaru untuk kotak alat pengembang Go untuk mendiagnosis cara kerja internal aplikasi yang berjalan. Kami telah terus meningkatkan pelacakan selama beberapa rilis terakhir. Go 1.21 sangat mengurangi overhead runtime pelacakan. Format jejak menjadi lebih kuat dan juga dapat dibagi dalam rilis Go 1.22, yang mengarah ke fitur seperti perekam penerbangan. Alat open-source seperti gotraceui, dan kemampuan yang akan datang untuk mengurai jejak eksekusi secara terprogram adalah cara lain untuk memanfaatkan kekuatan jejak eksekusi. Halaman Diagnostik mencantumkan banyak alat tambahan yang tersedia untuk Anda. Kami harap Anda memanfaatkannya saat Anda menulis dan menyempurnakan aplikasi Go Anda.

Terima kasih

Kami ingin mengambil waktu sejenak untuk berterima kasih kepada anggota komunitas yang telah aktif dalam pertemuan diagnostik, berkontribusi pada desain, dan memberikan umpan balik selama bertahun-tahun: Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham), dan PJ Malloy (@thepudds).

\ Diskusi, umpan balik, dan kerja yang telah Anda semua lakukan sangat membantu dalam mendorong kami menuju masa depan diagnostik yang lebih baik. Terima kasih!

Carlos Amedee and Michael Knyszek

\ Artikel ini tersedia di The Go Blog di bawah lisensi CC BY 4.0 DEED.

\ Foto oleh Lukas Souza di Unsplash

\