Đọc panic trace và runtime.Stack trong Go: mổ xẻ từng dòng để chẩn đoán crash

Khi một chương trình Go crash, nó nôn ra một khối chữ đỏ dài mà nhiều người chỉ liếc dòng đầu rồi cuộn qua. Đó là lãng phí: panic trace là bản đồ đầy đủ dẫn thẳng tới bug — nó nói lỗi gì, xảy ra ở dòng nào, goroutine nào, và cả chuỗi gọi dẫn tới đó. Bài trước ta dùng pprof goroutine để phát hiện rò rỉ; bài này đọc chính cái định dạng mà pprof, panic, và runtime.Stack cùng in ra — để khi thấy nó lúc 3 giờ sáng, bạn đọc được ngay thay vì đoán mò.

Ta sẽ mổ xẻ ba loại trace thật, hiểu từng thành phần, và dùng runtime.Stack để chủ động chụp trạng thái mọi goroutine.

Ba thành phần của một panic trace

func chia(a, b int) int {
	return a / b // b==0 -> panic "integer divide by zero"
}
func tang(x int) int { return chia(x, x-3) }
func main() { fmt.Println(tang(3)) } // 3-3=0

Chạy thật cho ra:

panic: runtime error: integer divide by zero

goroutine 1 [running]:
main.chia(...)
	/work/t130/panic.go:10
main.tang(...)
	/work/t130/panic.go:6
main.main()
	/work/t130/panic.go:15 +0x5c

Ba phần cần đọc: (1) dòng panic: cho biết lỗi gì — ở đây là chia cho 0. (2) goroutine 1 [running]: cho biết goroutine nào và trạng thái của nó (đang chạy). (3) ngăn xếp gọi, đọc từ trên xuống: đỉnh (main.chia) là nơi panic thật sự xảy ra, đáy (main.main) là điểm vào. Mỗi khung có file:dòng và một offset như +0x5c (vị trí lệnh máy trong hàm). (...) nghĩa là tham số bị lược bỏ vì hàm đã được inline.

Hình 1: Ba loại trace và cách đọc một khung: số hiệu goroutine + trạng thái + hàm + file:dòng +offset + dòng created by. runtime.Stack(buf, true) chụp mọi goroutine — cùng định dạng mà pprof và SIGQUIT dùng.

runtime.Stack: chụp trạng thái mọi goroutine

panic chỉ in goroutine gây ra nó. Nhưng nhiều bug (deadlock, rò rỉ, treo) cần nhìn tất cả goroutine cùng lúc. runtime.Stack(buf, true) làm đúng việc đó — tham số true nghĩa là "mọi goroutine", false là "chỉ goroutine hiện tại":

buf := make([]byte, 1<<16)
n := runtime.Stack(buf, true) // true = tất cả goroutine
fmt.Printf("%s", buf[:n])

Ta chạy thật với bốn goroutine cố tình đưa vào bốn trạng thái khác nhau (một chờ channel, một chờ mutex, một sleep, một đang chạy):

goroutine 1 [running]:            main.main()          đang chạy
goroutine 6 [chan receive]:       main.main.func1()    chặn ở <-ch
goroutine 7 [sync.Mutex.Lock]:    main.main.func2()    chờ mu.Lock()
  sync.runtime_SemacquireMutex ... sync.(*Mutex).lockSlow ...
goroutine 8 [sleep]:              main.main.func3()    time.Sleep

Điểm quý nhất là trạng thái trong ngoặc vuông: nó cho biết vì sao goroutine không tiến triển. [chan receive] = đang chặn ở nhận channel, [sync.Mutex.Lock] = đang chờ khóa, [sleep] = đang ngủ. Với deadlock, bạn nhìn ngay ra hai goroutine chờ chéo nhau. Với treo, bạn thấy goroutine kẹt ở đâu. Mỗi goroutine còn kèm dòng created by main.main in goroutine 1 — cho biết ai đã sinh ra nó, cực hữu ích khi truy nguồn goroutine lạ.

Hình 2: Đo thật — panic chia cho 0 (ngăn xếp đọc từ đỉnh chia xuống đáy main); runtime.Stack chụp 4 goroutine mỗi cái một trạng thái; và nil deref kèm [signal SIGSEGV ...] cùng tham số hex 0x68?.

Nil pointer deref: SIGSEGV và tham số hex

Loại trace hay gặp thứ ba là truy cập con trỏ nil. Ta tắt inline (//go:noinline) để thấy rõ tham số:

//go:noinline
func doc(c *Cau) string { return c.ten } // c == nil

Chạy thật:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x77430]

goroutine 1 [running]:
main.doc(0x68?)
	/work/t130/panic2.go:7
main.xuly(0x85660?)
	/work/t130/panic2.go:12 +0x1c

Hai chi tiết mới. [signal SIGSEGV: ... addr=0x0 ...]: nil deref là lỗi phần cứng (truy cập địa chỉ 0x0), runtime bắt tín hiệu SIGSEGV rồi biến thành panic — addr=0x0 xác nhận đang đọc con trỏ nil. Tham số hex 0x68?: đây là giá trị tham số hàm; dấu ? phía sau nghĩa là runtime lấy giá trị từ thanh ghi và không đảm bảo chính xác (giá trị có thể đã bị ghi đè). Đừng tin tuyệt đối vào số hex có dấu ?; hãy dùng nó như gợi ý, còn file:dòng mới là điểm neo chắc chắn.

Đánh đổi cần cân nhắc

Đọc trace từ trên xuống, nhưng cẩn thận với inline và runtime. Đỉnh ngăn xếp là nơi lỗi xảy ra — đó là nơi bạn muốn nhìn trước. Nhưng chú ý: các khung trên cùng đôi khi là mã runtime (như sync.runtime_SemacquireMutex khi chờ mutex) chứ không phải mã của bạn; hãy lướt xuống tới khung main.* đầu tiên để tìm dòng code của mình. Và (...) do inline che mất tham số — nếu cần thấy tham số, tắt inline khi debug hoặc dựng lại với -gcflags="-l".

GOTRACEBACK điều khiển lượng chi tiết in ra khi crash. Mặc định (GOTRACEBACK=single) chỉ in goroutine gây panic. Đặt GOTRACEBACK=all in mọi goroutine của bạn, GOTRACEBACK=system in cả goroutine runtime, và GOTRACEBACK=crash sinh core dump (bài sau). Trên production, GOTRACEBACK=all giúp một panic để lại đủ ngữ cảnh về các goroutine khác. Gửi tín hiệu SIGQUIT (Ctrl+\ ở terminal) cũng ép in stack mọi goroutine mà không cần crash — cách nhanh để soi một tiến trình đang treo.

runtime.Stack có phí và dừng thế giới. runtime.Stack(buf, true) phải tạm dừng lịch (stop-the-world) để chụp nhất quán mọi goroutine — với hàng chục nghìn goroutine, nó không rẻ và làm khựng chương trình. Đừng gọi nó trong vòng nóng; dùng cho chẩn đoán (một endpoint debug, một handler tín hiệu). Buffer phải đủ lớn: nếu n == len(buf) thì trace đã bị cắt cụt — tăng buffer rồi gọi lại. Với nhu cầu thật, net/http/pprof (/debug/pprof/goroutine?debug=2) in đúng định dạng này mà đã lo sẵn buffer.

Ba ý mang về

1. Panic trace có ba phần đọc được: dòng panic: (lỗi gì), goroutine N [trạng thái] (goroutine nào, đang kẹt ở đâu), và ngăn xếp đọc từ trên xuống (đỉnh = nơi lỗi, đáy = điểm vào) kèm file:dòng +offset — đo thật với chia-cho-0, nil deref (SIGSEGV addr=0x0) và tham số hex có dấu ? (không đảm bảo chính xác).
2. runtime.Stack(buf, true) chụp mọi goroutine với trạng thái [chan receive]/[sync.Mutex.Lock]/[sleep]... và dòng created by — đo thật 4 goroutine mỗi cái một trạng thái; đây là chìa khóa gỡ deadlock, treo và rò rỉ, cùng định dạng mà pprof và SIGQUIT dùng.
3. Điều khiển và cân nhắc phí: GOTRACEBACK=all cho crash chi tiết hơn, SIGQUIT/Ctrl+\ ép in stack tiến trình treo; nhưng runtime.Stack dừng-thế-giới nên đừng gọi trong vòng nóng, và kiểm n==len(buf) để biết trace có bị cắt không.

Bài tập làm thử

Bài 1 (đọc hiểu). Cho panic trace thật sau:

panic: runtime error: integer divide by zero

goroutine 1 [running]:
main.chia(...)
	/work/t130/panic.go:10
main.tang(...)
	/work/t130/panic.go:6
main.main()
	/work/t130/panic.go:15 +0x5c

Nêu ba phần cần đọc trong trace này, và giải thích tại sao phải đọc ngăn xếp từ trên xuống.

Bài 2 (đọc hiểu code Go). Giải thích chính xác runtime.Stack làm gì trong đoạn code sau, ý nghĩa của tham số true, và vì sao không nên gọi nó trong vòng lặp nóng (hot loop):

buf := make([]byte, 1<<16)
n := runtime.Stack(buf, true)
fmt.Printf("%s", buf[:n])

Bài 3 (đọc hiểu / bẫy). Cho trace nil pointer:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x77430]

goroutine 1 [running]:
main.doc(0x68?)
	/work/t130/panic2.go:7

Giải thích ý nghĩa của addr=0x0 và của dấu ? sau 0x68. Có nên tin tuyệt đối vào giá trị 0x68 này không?

Bài 4 (vận dụng thực tế). runtime.Stack chụp được 4 goroutine với các trạng thái: [running], [chan receive], [sync.Mutex.Lock], [sleep]. Nếu bạn đang điều tra một nghi ngờ deadlock (hai goroutine chờ chéo nhau), bạn sẽ nhìn vào thông tin nào trong trace để xác nhận?

Bài 5 (đánh đổi / vận dụng thực tế). Một dịch vụ production đang treo (không crash, không log gì thêm) và bạn cần biết mọi goroutine đang kẹt ở đâu ngay lập tức mà không muốn sửa code để thêm gọi runtime.Stack. Nêu hai cách làm được đề cập trong bài, và phân biệt chúng.

Phần sau là bài capstone: gộp mọi thứ trong sê-ri vào một dịch vụ REST API thật — cấu trúc, đo hiệu năng, và áp các bài học runtime/hồ sơ/chẩn đoán đã học vào một hệ thống hoàn chỉnh.