Flight Recorder: เครื่องมือติดตามการทำงานของ Go แบบใหม่

ในปี 2024 เราได้แนะนำโลกให้รู้จักกับการติดตามการทำงานของ Go ที่มีประสิทธิภาพมากขึ้น ในบล็อกโพสต์นั้นเราได้เปิดเผยฟังก์ชันการทำงานใหม่บางอย่างที่เราสามารถปลดล็อกได้ด้วยตัวติดตามการทำงานใหม่ของเรา รวมถึง การบันทึกการบิน เรายินดีที่จะประกาศว่าการบันทึกการบินนี้พร้อมใช้งานแล้วใน Go 1.25 และเป็นเครื่องมือใหม่ที่ทรงพลังในชุดเครื่องมือวินิจฉัยของ Go

การติดตามการทำงาน

ก่อนอื่น มาทบทวนเกี่ยวกับการติดตามการทำงานของ Go กันสักเล็กน้อย

\ รันไทม์ของ Go สามารถถูกทำให้เขียนบันทึกเหตุการณ์ต่างๆ ที่เกิดขึ้นระหว่างการทำงานของแอปพลิเคชัน Go บันทึกนี้เรียกว่าการติดตามการทำงานของรันไทม์ การติดตามการทำงานของ Go มีข้อมูลมากมายเกี่ยวกับวิธีที่ goroutine มีปฏิสัมพันธ์กันและกับระบบพื้นฐาน ทำให้มันมีประโยชน์มากสำหรับการแก้ไขปัญหาความล่าช้า เนื่องจากมันบอกคุณทั้งเวลาที่ goroutine ของคุณกำลังทำงาน และที่สำคัญ เมื่อไหร่ที่พวกมันไม่ได้ทำงาน

\ แพ็คเกจ runtime/trace มี API สำหรับเก็บรวบรวมการติดตามการทำงานในช่วงเวลาที่กำหนดโดยการเรียก runtime/trace.Start และ runtime/trace.Stop วิธีนี้ใช้ได้ดีถ้าโค้ดที่คุณกำลังติดตามเป็นเพียงการทดสอบ การวัดประสิทธิภาพขนาดเล็ก หรือเครื่องมือคำสั่ง คุณสามารถเก็บการติดตามการทำงานทั้งหมดตั้งแต่ต้นจนจบ หรือเฉพาะส่วนที่คุณสนใจ

\ อย่างไรก็ตาม ในบริการเว็บที่ทำงานเป็นเวลานาน ซึ่งเป็นประเภทของแอปพลิเคชันที่ Go มีชื่อเสียง วิธีนี้ยังไม่ดีพอ เว็บเซิร์ฟเวอร์อาจทำงานเป็นวันหรือแม้กระทั่งเป็นสัปดาห์ และการเก็บการติดตามการทำงานทั้งหมดจะสร้างข้อมูลมากเกินไปที่จะต้องคัดกรอง บ่อยครั้งที่มีเพียงส่วนเดียวของการทำงานของโปรแกรมที่มีปัญหา เช่น คำขอที่หมดเวลาหรือการตรวจสอบสถานะที่ล้มเหลว เมื่อมันเกิดขึ้นแล้ว มันก็สายเกินไปที่จะเรียก Start!

\ วิธีหนึ่งในการแก้ปัญหานี้คือการสุ่มตัวอย่างการติดตามการทำงานจากทั่วทั้งระบบ แม้ว่าวิธีนี้จะมีประสิทธิภาพและสามารถช่วยค้นหาปัญหาก่อนที่จะกลายเป็นการหยุดทำงาน แต่มันต้องการโครงสร้างพื้นฐานจำนวนมากเพื่อให้เริ่มต้นได้ ข้อมูลการติดตามการทำงานจำนวนมากจะต้องถูกเก็บ คัดแยก และประมวลผล ซึ่งส่วนใหญ่จะไม่มีอะไรที่น่าสนใจเลย และเมื่อคุณพยายามหาสาเหตุของปัญหาเฉพาะ มันก็ไม่ใช่ทางออก

การบันทึกการบิน

นี่นำเรามาถึงตัวบันทึกการบิน

\ โปรแกรมมักจะรู้เมื่อมีบางอย่างผิดพลาด แต่สาเหตุที่แท้จริงอาจเกิดขึ้นนานมาแล้ว ตัวบันทึกการบินช่วยให้คุณเก็บการติดตามการทำงานในช่วงไม่กี่วินาทีสุดท้ายก่อนที่โปรแกรมจะตรวจพบว่ามีปัญหา

\ ตัวบันทึกการบินเก็บการติดตามการทำงานตามปกติ แต่แทนที่จะเขียนออกไปยังซ็อกเก็ตหรือไฟล์ มันจะเก็บการติดตามในช่วงไม่กี่วินาทีสุดท้ายไว้ในหน่วยความจำ ทุกเมื่อ โปรแกรมสามารถขอเนื้อหาของบัฟเฟอร์และถ่ายภาพช่วงเวลาที่มีปัญหาได้พอดี ตัวบันทึกการบินเปรียบเสมือนมีดผ่าตัดที่ตัดตรงไปยังพื้นที่ที่มีปัญหา

ตัวอย่าง

มาเรียนรู้วิธีใช้ตัวบันทึกการบินด้วยตัวอย่างกัน โดยเฉพาะอย่างยิ่ง เราจะใช้มันเพื่อวินิจฉัยปัญหาประสิทธิภาพกับเซิร์ฟเวอร์ HTTP ที่ใช้เกม "ทายตัวเลข" มันเปิดเผยจุดสิ้นสุด /guess-number ที่รับจำนวนเต็มและตอบกลับผู้เรียกโดยแจ้งให้พวกเขาทราบว่าพวกเขาทายตัวเลขถูกหรือไม่

\ นอกจากนี้ยังมี goroutine ที่ส่งรายงานของตัวเลขที่ถูกทายทั้งหมดไปยังบริการอื่นผ่านคำขอ 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) } }

นี่คือโค้ดทั้งหมดสำหรับเซิร์ฟเวอร์: https://go.dev/play/p/rX1eyKtVglF และสำหรับไคลเอนต์อย่างง่าย: https://go.dev/play/p/2PjQ-1ORPiw เพื่อหลีกเลี่ยงกระบวนการที่สาม "ไคลเอนต์" ยังใช้เซิร์ฟเวอร์รายงานด้วย แม้ว่าในระบบจริงสิ่งนี้จะแยกกัน

\ สมมติว่าหลังจากนำแอปพลิเคชันไปใช้งานในการผลิต เราได้รับการร้องเรียนจากผู้ใช้ว่าการเรียก /guess-number บางครั้งใช้เวลานานกว่าที่คาดไว้ เมื่อเราดูที่บันทึกของเรา เราเห็นว่าบางครั้งเวลาตอบสนองเกิน 100 มิลลิวินาที ในขณะที่การเรียกส่วนใหญ่อยู่ในระดับไมโครวินาที

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

ก่อนที่เราจะดำเนินการต่อ ลองใช้เวลาสักครู่และดูว่าคุณสามารถพบสิ่งที่ผิดพลาดหรือไม่!

\ ไม่ว่าคุณจะพบปัญหาหรือไม่ก็ตาม มาดูลึกลงไปและดูว่าเราสามารถหาปัญหาจากหลักการพื้นฐานได้อย่างไร โดยเฉพาะอย่างยิ่ง จะดีมากถ้าเราสามารถเห็นว่าแอปพลิเคชันกำลังทำอะไรในช่วงเวลาก่อนที่จะมีการตอบสนองที่ช้า นี่คือสิ่งที่ตัวบันทึกการบินถูกสร้างขึ้นมาเพื่อ! เราจะใช้มันเพื่อจับการติดตามการทำงานเมื่อเราเห็นการตอบสนองแรกที่เกิน 100 มิลลิวินาที

\ ก่อนอื่น ใน main เราจะกำหนดค่าและเริ่มตัวบันทึกการบิน:

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

MinAge กำหนดระยะเวลาที่ข้อมูลการติดตามจะถูกเก็บรักษาอย่างน่าเชื่อถือ และเราแนะนำให้ตั้งค่าเป็นประมาณ 2 เท่าของช่วงเวลาของเหตุการณ์ ตัวอย่างเช่น ถ้าคุณกำลังแก้ไขข้อบกพร่องของการหมดเวลา 5 วินาที ให้ตั้งค่าเป็น 10 วินาที MaxBytes กำหนดขนาดของการติดตามที่ถูกบัฟเฟอร์เพื่อไม่ให้การใช้หน่วยความจำของคุณเพิ่มขึ้นมากเกินไป โดยเฉลี่ย คุณสามารถคาดหวังข้อมูลการติดตามประมาณสองสามเมกะไบต์ต่อวินาทีของการทำงาน หรือ 10 เมกะไบต์ต่อวินาทีสำหรับบริการที่มีการใช้งานมาก

\ ต่อไป เราจะเพิ่มฟังก์ชันตัวช่วยเพื่อจับภาพสแนปช็อตและเขียนลงในไฟล์:

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

\ และสุดท้าย ก่อนที่จะบันทึกคำขอที่เสร็จสมบูรณ์ เราจะทริกเกอร์สแนปช็อตถ้าคำขอใช้เวลามากกว่า 100 มิลลิวินาที:

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

\ นี่คือโค้ดทั้งหมดสำหรับเซิร์ฟเวอร์ ตอนนี้มีการติดตั้งตัวบันทึกการบินแล้ว: https://go.dev/play/p/3V33gfIpmjG

\ ตอนนี้ เรารันเซิร์ฟเวอร์อีกครั้งและส่งคำขอจนกว่าเราจะได้รับคำขอที่ช้าซึ่งทริกเกอร์สแนปช็อต

\ เมื่อเราได้รับการติดตามแล้ว เราจะต้องมีเครื่องมือที่จะช่วยเราตรวจสอบมัน Go toolchain มีเครื่องมือวิเคราะห์การติดตามการทำงานในตัวผ่านคำสั่ง go tool trace รัน go tool trace snapshot.trace เพื่อเปิดเครื่องมือ ซึ่งจะเริ่มเว็บเซิร์ฟเวอร์ท้องถิ่น จากนั้นเปิด URL ที่แสดงในเบราว์เซอร์ของคุณ (ถ้าเครื่องมือไม่เปิดเบราว์เซอร์ของคุณโดยอัตโนมัติ)

\ เครื่องมือนี้ให้วิธีการดูการติดตามหลายวิธี แต่เรามาเน้นที่การแสดงภาพการติดตามเพื่อให้เข้าใจว่ากำลังเกิดอะไรขึ้น คลิก "View trace by proc" เพื่อทำเช่นนั้น

\ ในมุมมองนี้ การติดตามถูกนำเสนอเป็นไทม์ไลน์ของเหตุการณ์ ที่ด้านบนของหน้า ในส่วน "STATS" เราสามารถเห็นสรุปของสถานะแอปพลิเคชัน รวมถึงจำนวนเธรด ขนาดฮีป และจำนวน goroutine

\ ด้านล่างนั้น ในส่วน "PROCS" เราสามารถเห็นว่าการทำงานของ goroutine ถูกแมปไปยัง GOMAXPROCS (จำนวนเธรดของระบบปฏิบัติการที่สร้างโดยแอปพลิเคชัน Go) อย่างไร เราสามารถเห็นเมื่อไหร่และอย่างไรที่แต่ละ goroutine เริ่ม ทำงาน และหยุดทำงานในที่สุด

\ ตอนนี้ เรามาให้ความสนใจกับช่องว่างขนาดใหญ่ในการทำงานทางด้านขวาของตัวดู เป็นระยะเวลาหนึ่ง ประมาณ 100 มิลลิวินาที ไม่มีอะไรเกิดขึ้น!

โดยการเลือกเครื่องมือ zoom (หรือกด 3) เราสามารถตรวจสอบส่วนของการติดตามหลังจากช่องว่างด้วยรายละเอียดมากขึ้น

\ นอกเหนือจากกิจกรรมของแต่ละ goroutine เราสามารถเห็นว่า goroutine มีปฏิสัมพันธ์กันอย่างไรผ่าน "เหตุการณ์การไหล" เหตุการณ์การไหลขาเข้าบ่งชี้ว่าเกิดอะไรขึ้นที่ทำให้ goroutine เริ่มทำงาน ขอบการไหลขาออกบ่งชี้ว่า goroutine หนึ่งมีผลต่ออีก goroutine หนึ่งอย่างไร การเปิดใช้งานการแสดงภาพของเหตุการณ์การไหลทั้งหมดมักจะให้เบาะแสที่บ่งบอกถึงแหล่งที่มาของปัญหา

ในกรณีนี้ เราสามารถเห็นว่า goroutine หลายตัวมีการเชื่อมต่อโดยตรงกับ goroutine เดียวหลังจากการหยุดชะงักในกิจกรรม

\ การคลิกที่ goroutine เดียวแสดงตารางเหตุการณ์ที่เต็มไปด้วยเหตุการณ์การไหลขาออก ซึ่งตรงกับสิ่งที่เราเห็นเมื่อมุมมองการไหลถูกเปิดใช้งาน

\ เกิดอะไรขึ้นเมื่อ goroutine นี้ทำงาน? ส่วนหนึ่งของข้อมูลที่เก็บไว้ในการติดตามคือมุมมองของการติดตามสแต็กในจุดเวลาที่แตกต่างกัน เมื่อเราดูที่ goroutine เราสามารถเห็นว่าการติดตามสแต็กเริ่มต้นแสดงว่ามันกำลังรอให้คำขอ HTTP เสร็จสมบูรณ์เมื่อ goroutine ถูกกำหนดให้ทำงาน และการติดตามสแต็กสุดท้ายแสดงว่าฟังก์ชัน sendReport ได้ส่งคืนค่าแล้วและมันกำลังรอตัวจับเวลาสำหรับเวลาที่กำหนดถัดไปเพื่อส่งรายงาน

\ ระหว่างการเริ่มต้นและการสิ้นสุดของ goroutine นี้ที่ทำงาน เราเห็น "การไหลขาออก" จำนวนมาก ซึ่งมันมีปฏิสัมพันธ์กับ goroutine อื่นๆ การคลิกที่รายการ Outgoing flow รายการหนึ่งนำเราไปสู่มุมมองของการปฏิสัมพันธ์

\ การไหลนี้เกี่ยวข้องกับ Unlock ใน sendReport:

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

\ ใน sendReport เราตั้งใจที่จะได้รับล็อคในแต่ละถังและปล่อยล็อคหลังจากคัดลอกค่า

\ แต่นี่คือปัญหา: เราไม่ได้ปล่อยล็อคทันทีหลังจากคัดลอกค่าที่อยู่ใน bucket.guesses เนื่องจากเราใช้คำสั่ง defer เพื่อปล่อยล็อค การปล่อยนั้นจะไม่เกิดขึ้นจนกว่าฟังก์ชันจะส่งคืนค่า เราถือล็อคไม่เพียงแค่หลังจากจบลูป แต่จนกว่าคำขอ HTTP จะเสร็จสมบูรณ์ นั่นเป็นข้อผิดพลาดที่ละเอียดอ่อนซึ่งอาจยากที่จะติดตามในระบบการผลิตขนาดใหญ่

\ โชคดีที่การติดตามการทำงานช่วยให้เราระบุปัญหาได้อย่างแม่นยำ อย่างไรก็ตาม ถ้าเราพยายามใช้ตัวติดตามการทำงานในเซิร์ฟเวอร์ที่ทำงานเป็นเวลานานโดยไม่มีโหมดการบันทึกการบินใหม่ มันอาจจะสะสมข้อมูลการติดตามการทำงานจำนวนมาก ซึ่งผู้ดำเนินการจะต้องเก็บ ส่ง และคัดกรอง ตัวบันทึกการบินให้พลังแห่งการมองย้อนหลัง มันช่วยให้เราจับเฉพาะสิ่งที่ผิดพลาด หลังจากที่มันเกิดขึ้นแล้ว และรวมจุดสนใจไปที่สาเหตุอย่างรวดเร็ว

\ ตัวบันทึกการบินเป็นเพียงส่วนเพิ่มเติมล่าสุดในชุดเครื่องมือของนักพัฒนา Go สำหรับการวินิจฉัยการทำงานภายในของแอปพลิเคชันที่กำลังทำงาน เราได้ปรับปรุงการติดตามอย่างต่อเนื่องในช่วงสองสามรุ่นที่ผ่านมา Go 1.21 ลดโอเวอร์เฮดของการติดตามในขณะทำงานอย่างมาก รูปแบบการติดตามกลายเป็นที่แข็งแกร่งขึ้นและแบ่งแยกได้ในรุ่น Go 1.22 นำไปสู่คุณสมบัติเช่นตัวบันทึกการบิน เครื่องมือโอเพนซอร์สเช่น gotraceui และความสามารถในการแยกวิเคราะห์การติดตามการทำงานโดยโปรแกรมที่กำลังจะมาถึงเป็นวิธีเพิ่มเติมในการใช้ประโยชน์จากพลังของการติดตามการทำงาน หน้าการวินิจฉัยแสดงเครื่องมือเพิ่มเติมมากมายที่คุณสามารถใช้ได้ เราหวังว่าคุณจะใช้ประโยชน์จากพวกมันเมื่อคุณเขียนและปรับปรุงแอปพลิเคชัน Go ของคุณ

ขอบคุณ

เราขอใช้เวลาสักครู่เพื่อขอบคุณสมาชิกชุมชนเหล่านั้นที่มีส่วนร่วมในการประชุมวินิจฉัย มีส่วนร่วมในการออกแบบ และให้ข้อเสนอแนะตลอดหลายปีที่ผ่านมา: Felix Geisendörfer (@felixge.de), Nick Ripley (@nsrip-dd), Rhys Hiltner (@rhysh), Dominik Honnef (@dominikh), Bryan Boreham (@bboreham), และ PJ Malloy (@thepudds)

\ การสนทนา ข้อเสนอแนะ และงานที่พวกคุณทุกคนได้ทุ่มเทมีส่วนสำคัญในการผลักดันเราไปสู่อนาคตของการวินิจฉัยที่ดีขึ้น ขอบคุณ!

---

Carlos Amedee และ Michael Knyszek

\ บทความนี้มีอยู่ใน The Go Blog ภายใต้ใบอนุญาต CC BY 4.0 DEED

\ ภาพถ่ายโดย Lukas Souza บน Unsplash

\