Profiling Go với pprof: tìm điểm nghẽn CPU, bộ nhớ và goroutine

1. Tổng quan

Khi một service Go chạy chậm hoặc ngốn RAM, đoán mò thường tốn thời gian và hay sai chỗ. Go có sẵn công cụ pprof trong thư viện chuẩn. Công cụ này cho bạn biết chính xác hàm nào ăn CPU, chỗ nào cấp phát bộ nhớ và goroutine nào đang bị kẹt.

Đọc xong bài này, bạn sẽ biết cách bật pprof cho HTTP service, thu profile từ benchmark và chương trình CLI, đọc kết quả bằng go tool pprof, và so sánh hai profile để kiểm chứng một lần tối ưu.

2. pprof là gì và có những loại profile nào

pprof gồm hai phần:

  • Phía thu thập: package runtime/pprof và net/http/pprof trong thư viện chuẩn. Chúng ghi profile theo định dạng protobuf.
  • Phía phân tích: lệnh go tool pprof. Lệnh này đọc file profile hoặc URL rồi hiển thị kết quả dạng bảng, mã nguồn hoặc giao diện web.

Các loại profile thường dùng:

Profile Đo cái gì Bật mặc định?
profile (CPU) Thời gian CPU theo hàm, lấy mẫu 100 lần/giây Có, khi được yêu cầu
heap Bộ nhớ đang sống và tổng đã cấp phát Có
allocs Giống heap, nhưng mặc định xem tổng cấp phát Có
goroutine Stack trace của mọi goroutine hiện có Có
block Thời gian chờ trên channel, select, sync.Cond Không
mutex Tranh chấp trên sync.Mutex/RWMutex Không
trace Trace sự kiện chi tiết (dùng go tool trace) Có, khi được yêu cầu

3. Bật pprof cho HTTP service

Cách nhanh nhất là import net/http/pprof để lấy side effect. Package này đăng ký các handler /debug/pprof/* vào http.DefaultServeMux.

package main

import (
	"log"
	"net/http"
	_ "net/http/pprof" // đăng ký /debug/pprof/* vào DefaultServeMux
)

func main() {
	// Server pprof riêng, chỉ lắng nghe trên localhost
	go func() {
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()

	// Server ứng dụng dùng mux riêng, không lộ pprof
	appMux := http.NewServeMux()
	appMux.HandleFunc("GET /invoice", invoiceHandler)
	log.Fatal(http.ListenAndServe(":8080", appMux))
}

Vài điểm cần chú ý:

  • Dòng _ "net/http/pprof" chỉ đăng ký handler, bạn không gọi hàm nào trong package này.
  • Server pprof truyền nil làm handler, tức là dùng DefaultServeMux, nơi chứa các route pprof.
  • Ứng dụng chính dùng appMux riêng, nên cổng 8080 không có /debug/pprof.

Kiểm tra nhanh:

curl -s http://localhost:6060/debug/pprof/ | head -n 20

Lưu ý: Đừng bao giờ mở /debug/pprof ra Internet. Endpoint này để lộ stack trace và cấu trúc mã. Kẻ xấu còn có thể dùng nó để làm service quá tải (CPU profile 30 giây có tốn tài nguyên). Hãy bind vào localhost, hoặc đặt sau mạng nội bộ và lớp xác thực.

4. Thu và đọc CPU profile

Giả sử service có hàm tạo hóa đơn như sau:

type Item struct {
	SKU   string
	Price float64
	Qty   int
}

type Order struct {
	ID    int
	Items []Item
}

func BuildInvoice(o Order) string {
	s := ""
	for _, it := range o.Items {
		s += fmt.Sprintf("%s x%d = %.2f\n", it.SKU, it.Qty, it.Price*float64(it.Qty))
	}
	return s
}

Ở mỗi vòng lặp, s += ... tạo một chuỗi mới và copy toàn bộ nội dung cũ sang. Với đơn hàng nhiều dòng, chi phí tăng theo O(n²).

Trong lúc service đang nhận tải (ví dụ bạn dùng hey hoặc wrk bắn request vào /invoice), hãy thu CPU profile trong 30 giây:

go tool pprof "http://localhost:6060/debug/pprof/profile?seconds=30"

Sau khi thu xong, bạn vào chế độ tương tác. Gõ top:

(pprof) top 8
Showing nodes accounting for 2.41s, 85.46% of 2.82s total
      flat  flat%   sum%        cum   cum%
     0.92s 32.62% 32.62%      0.92s 32.62%  runtime.memmove
     0.41s 14.54% 47.16%      1.38s 48.94%  runtime.concatstrings
     0.33s 11.70% 58.87%      0.33s 11.70%  runtime.memclrNoHeapPointers
     0.27s  9.57% 68.44%      0.71s 25.18%  runtime.mallocgc
     0.18s  6.38% 74.82%      0.52s 18.44%  fmt.(*pp).doPrintf
     0.13s  4.61% 79.43%      0.13s  4.61%  strconv.fmtF
     0.10s  3.55% 82.98%      2.47s 87.59%  main.BuildInvoice
     0.07s  2.48% 85.46%      0.21s  7.45%  runtime.scanobject

Cách đọc hai cột quan trọng nhất:

  • flat: thời gian CPU nằm trực tiếp trong hàm đó.
  • cum (cumulative): thời gian của hàm đó cộng mọi hàm nó gọi.

Ở đây main.BuildInvoice có flat nhỏ nhưng cum gần 88%. Phần lớn thời gian rơi vào memmove và concatstrings, tức là việc nối chuỗi. Để xem chi tiết từng dòng, dùng list:

(pprof) list BuildInvoice
ROUTINE ======================== main.BuildInvoice in /app/invoice.go
     100ms      2.47s (flat, cum) 87.59% of Total
         .          .     18:func BuildInvoice(o Order) string {
         .          .     19:	s := ""
      10ms       10ms     20:	for _, it := range o.Items {
      90ms      2.46s     21:		s += fmt.Sprintf("%s x%d = %.2f\n", ...)
         .          .     22:	}

Dòng 21 là thủ phạm. Nếu muốn xem flame graph, bạn mở giao diện web:

go tool pprof -http=:8081 "http://localhost:6060/debug/pprof/profile?seconds=30"

Trình duyệt sẽ mở ra các view Top, Graph, Flame Graph và Source. Trong flame graph, khối càng rộng thì càng tốn CPU.

Bản sửa dùng strings.Builder và fmt.Fprintf:

func BuildInvoiceFast(o Order) string {
	var b strings.Builder
	b.Grow(len(o.Items) * 32) // ước lượng trước, tránh grow nhiều lần
	for _, it := range o.Items {
		fmt.Fprintf(&b, "%s x%d = %.2f\n", it.SKU, it.Qty, it.Price*float64(it.Qty))
	}
	return b.String()
}

5. Heap profile: ai đang giữ bộ nhớ?

go tool pprof http://localhost:6060/debug/pprof/heap

Một heap profile chứa bốn “sample index”. Bạn chọn index bằng cờ -sample_index:

  • inuse_space (mặc định): số byte đang sống tại thời điểm GC gần nhất. Dùng để tìm memory leak.
  • inuse_objects: số object đang sống.
  • alloc_space: tổng byte đã cấp phát từ lúc chương trình chạy. Dùng để tìm chỗ gây áp lực lên GC.
  • alloc_objects: tổng số object đã cấp phát.
go tool pprof -sample_index=alloc_space http://localhost:6060/debug/pprof/heap
(pprof) top 3
      flat  flat%   sum%        cum   cum%
    1.84GB 91.20% 91.20%     1.84GB 91.20%  main.BuildInvoice
    0.12GB  5.95% 97.15%     0.12GB  5.95%  fmt.Sprintf
    0.03GB  1.49% 98.64%     0.03GB  1.49%  encoding/json.Marshal

Kết quả cho thấy BuildInvoice đã cấp phát 1.84GB tổng cộng, dù lượng đang sống có thể rất nhỏ. Đây là dấu hiệu GC phải làm việc nhiều. Tình huống này khớp với lượng runtime.mallocgc và runtime.scanobject bạn thấy trong CPU profile ở mục 4.

Lưu ý: Heap profile cũng là dữ liệu lấy mẫu (mặc định khoảng 1 mẫu mỗi 512KB cấp phát), nên con số chỉ là ước lượng. Đừng so từng byte, hãy nhìn tỉ lệ.

6. Goroutine profile: phát hiện goroutine leak

Nếu số goroutine cứ tăng mãi, bạn có thể xem nhanh qua trình duyệt hoặc curl mà không cần go tool pprof:

curl -s "http://localhost:6060/debug/pprof/goroutine?debug=1" | head -n 15
goroutine profile: total 10432
10398 @ 0x43a5d6 0x4071c5 0x406d78 0x6b2f45 0x46c0e1
#	0x6b2f44	main.(*PaymentService).notify+0x64	/app/payment.go:57

Có 10.398 goroutine cùng kẹt tại payment.go:57. Đây gần như chắc chắn là leak. Đoạn code gây lỗi thường có dạng:

func (s *PaymentService) notify(ctx context.Context, p Payment) {
	result := make(chan error) // unbuffered
	go func() {
		result <- s.gateway.Send(p) // kẹt mãi nếu không ai nhận
	}()
	select {
	case err := <-result:
		log.Println(err)
	case <-ctx.Done():
		return // goroutine bên trong bị bỏ rơi
	}
}

Khi ctx hết hạn trước, không còn ai đọc result, nên goroutine con kẹt vĩnh viễn ở lệnh gửi. Cách sửa đơn giản là dùng make(chan error, 1) để lệnh gửi không bao giờ chặn.

Với debug=2, endpoint in đầy đủ stack trace của từng goroutine, kèm thời gian chờ (ví dụ [chan send, 42 minutes]). Thông tin này rất hữu ích khi điều tra deadlock.

7. Block và mutex profile

Hai profile này tắt mặc định vì có chi phí. Bạn bật chúng trong main:

import "runtime"

func init() {
	// Ghi trung bình 1 sự kiện mutex contention trên 5
	runtime.SetMutexProfileFraction(5)
	// Lấy mẫu 1 sự kiện block cho mỗi 10µs bị chặn
	runtime.SetBlockProfileRate(10_000)
}

Sau đó thu profile như bình thường:

go tool pprof http://localhost:6060/debug/pprof/mutex
go tool pprof http://localhost:6060/debug/pprof/block

Mutex profile cho biết lock nào khiến các goroutine phải xếp hàng chờ nhau, ví dụ một sync.Mutex bảo vệ cache map[int]Customer dùng chung. Block profile cho biết goroutine chờ lâu ở channel hay select nào.

Lưu ý: SetBlockProfileRate(1) ghi lại mọi sự kiện block. Mức này chỉ phù hợp khi debug cục bộ. Trên production, hãy dùng rate lớn hơn, hoặc chỉ bật tạm thời.

8. Profiling từ benchmark

Với một hàm cụ thể, cách gọn nhất là viết benchmark rồi để go test sinh profile. Code dưới đây dùng b.Loop() nên cần Go 1.24 trở lên.

package main

import (
	"fmt"
	"testing"
)

func sampleOrder(n int) Order {
	items := make([]Item, n)
	for i := range items {
		items[i] = Item{SKU: fmt.Sprintf("SKU-%04d", i), Price: 19.99, Qty: i%5 + 1}
	}
	return Order{ID: 1, Items: items}
}

func TestBuildInvoiceFastMatchesOriginal(t *testing.T) {
	order := sampleOrder(200)
	if got, want := BuildInvoiceFast(order), BuildInvoice(order); got != want {
		t.Fatalf("output khác nhau:\n got=%q\nwant=%q", got, want)
	}
}

func BenchmarkBuildInvoice(b *testing.B) {
	order := sampleOrder(500)
	b.ReportAllocs()
	for b.Loop() {
		BuildInvoice(order)
	}
}

func BenchmarkBuildInvoiceFast(b *testing.B) {
	order := sampleOrder(500)
	b.ReportAllocs()
	for b.Loop() {
		BuildInvoiceFast(order)
	}
}

Test TestBuildInvoiceFastMatchesOriginal đảm bảo bản tối ưu cho ra kết quả giống hệt bản cũ. Đừng bỏ bước này: tối ưu mà sai kết quả thì vô nghĩa. Chạy benchmark kèm profile:

go test -run='^$' -bench=BuildInvoice -cpuprofile=cpu.out -memprofile=mem.out
BenchmarkBuildInvoice-8        1543    772410 ns/op   6342817 B/op    1002 allocs/op
BenchmarkBuildInvoiceFast-8   19821     60318 ns/op     36472 B/op     504 allocs/op

Bản dùng strings.Builder nhanh hơn khoảng 12 lần và cấp phát ít hơn khoảng 170 lần. Cờ -run='^$' bỏ qua các test thường để chỉ chạy benchmark. File cpu.out và mem.out được mở bằng:

go tool pprof -http=:8081 cpu.out

9. Profiling chương trình CLI với runtime/pprof

Với tool chạy một lần rồi thoát, chẳng hạn job import đơn hàng, bạn dùng trực tiếp runtime/pprof:

package main

import (
	"log"
	"os"
	"runtime"
	"runtime/pprof"
)

func main() {
	cpuFile, err := os.Create("cpu.out")
	if err != nil {
		log.Fatal(err)
	}
	defer cpuFile.Close()

	if err := pprof.StartCPUProfile(cpuFile); err != nil {
		log.Fatal(err)
	}
	defer pprof.StopCPUProfile()

	importOrders("orders.csv") // công việc chính

	memFile, err := os.Create("mem.out")
	if err != nil {
		log.Fatal(err)
	}
	defer memFile.Close()
	runtime.GC() // cập nhật số liệu inuse trước khi ghi
	if err := pprof.WriteHeapProfile(memFile); err != nil {
		log.Fatal(err)
	}
}

Hai lỗi hay gặp ở đây:

  • Gọi log.Fatal hoặc os.Exit sau StartCPUProfile sẽ bỏ qua defer. Khi đó StopCPUProfile không chạy và file profile bị rỗng hoặc hỏng.
  • Quên runtime.GC() trước WriteHeapProfile. Số liệu inuse_* chỉ được cập nhật sau mỗi lần GC, nên profile có thể phản ánh trạng thái cũ.

10. So sánh hai profile

Sau khi tối ưu, bạn nên đo lại thay vì tin vào cảm giác. Cờ -diff_base trừ profile cũ khỏi profile mới:

go tool pprof -diff_base=cpu_before.out cpu_after.out
(pprof) top 3
      flat  flat%   sum%        cum   cum%
    -0.89s 31.56% 31.56%     -0.89s 31.56%  runtime.memmove
    -0.40s 14.18% 45.74%     -1.35s 47.87%  runtime.concatstrings
    -0.25s  8.87% 54.61%     -0.66s 23.40%  runtime.mallocgc

Giá trị âm nghĩa là thời gian đã giảm. Để kết quả có ý nghĩa, hai profile cần được thu trong cùng điều kiện: cùng tải, cùng thời lượng, cùng máy.

Ngoài ra, từ Go 1.21, CPU profile còn phục vụ Profile-Guided Optimization (PGO). Bạn thu một CPU profile đại diện từ production, đặt tên default.pgo trong thư mục package main, rồi go build sẽ tự dùng profile đó để inline và tối ưu các đường code nóng. Mức cải thiện thường vào khoảng vài phần trăm, và bạn không phải sửa dòng code nào.

11. Lỗi hay gặp và khi nào không nên dùng

  • Profile quá ngắn hoặc không có tải. CPU profile lấy mẫu 100Hz. Nếu chỉ thu 2 giây lúc service rảnh, bạn sẽ chỉ thấy runtime và nhiễu.
  • Nhầm flat với cum. Hàm có cum cao chưa chắc là thủ phạm, có thể nó chỉ gọi thủ phạm.
  • Nhầm inuse_space với alloc_space. Muốn tìm leak thì xem inuse. Muốn giảm áp lực GC thì xem alloc.
  • Đo I/O bằng CPU profile. Thời gian goroutine chờ database hoặc HTTP không tốn CPU nên không xuất hiện trong CPU profile. Hãy dùng block profile, go tool trace, hoặc tracing phân tán.
  • Để pprof công khai trên cổng ứng dụng. Xem lại mục 3.

Lưu ý: pprof trả lời câu hỏi “chỗ nào tốn”, không trả lời “có nên tối ưu không”. Nếu endpoint đã đạt SLA và hàm chỉ chiếm 2% CPU, viết lại cho phức tạp hơn thường không đáng.

12. Kết luận

Trong bài này, bạn đã:

  • bật net/http/pprof an toàn trên một server riêng ở localhost;
  • đọc CPU profile bằng top và list, và phân biệt flat với cum;
  • dùng heap profile với inuse_space và alloc_space;
  • phát hiện goroutine leak qua debug=1 và debug=2;
  • bật block và mutex profile;
  • sinh profile từ benchmark và chương trình CLI;
  • so sánh trước/sau bằng -diff_base.

Quy trình hiệu quả nhất vẫn là: đo → tìm điểm nóng → sửa → viết test giữ đúng hành vi → đo lại. Với pprof có sẵn trong thư viện chuẩn, bạn không cần cài thêm gì để bắt đầu.

golangpprofperformanceprofiling