ทำ Profiling ใน Go (Golang) ด้วย pprof: หาคอขวดด้านประสิทธิภาพที่แท้จริง

วิศวกรทุกคนมีสัญชาตญาณว่าทำไมโค้ดของตัวเองถึงช้า และบ่อยครั้งที่สัญชาตญาณนั้นผิด loop ที่ดูเหมือนจะกินทรัพยากรกลับไม่มีผลอะไรเลย ในขณะที่ fmt.Sprintf หน้าตาไม่มีพิษภัยใน hot path กลับกิน CPU ไปถึง 30% Go จึงมี pprof มาให้ เพื่อให้คุณวัดต้นทุนได้โดยตรงแทนการเดา

ขั้นที่ 0: นิยามคำว่า "ช้า" ด้วย benchmark

คุณปรับปรุงสิ่งที่ยังไม่ได้วัดไม่ได้ ให้เริ่มจากการเขียน benchmark สำหรับ code path ที่คุณสนใจ:

func BenchmarkRenderInvoice(b *testing.B) {
    inv := sampleInvoice()
    b.ReportAllocs()
    for b.Loop() {
        _ = RenderInvoice(inv)
    }
}

รันหลาย ๆ รอบแล้วบันทึกผลลัพธ์ไว้:

go test -bench=RenderInvoice -count=10 ./invoice > before.txt

ภายหลังคุณจะเอาผลนี้เป็น baseline ไปเปรียบเทียบด้วย benchstat ซึ่งจะบอกว่าการเปลี่ยนแปลงนั้นให้ผลจริงหรือเป็นแค่ noise

การเก็บ profile

จาก benchmark

go test -bench=RenderInvoice -cpuprofile=cpu.out -memprofile=mem.out ./invoice

จาก service ที่กำลังรันอยู่

import package ของ handler เพื่อให้มันลงทะเบียน endpoint ให้อัตโนมัติ (side effect) แล้วเปิดไว้บน port ที่ ใช้ภายในเท่านั้น:

import _ "net/http/pprof"

go func() {
    log.Println(http.ListenAndServe("127.0.0.1:6060", nil))
}()

จากนั้นเก็บข้อมูลจาก traffic จริงเป็นเวลา 30 วินาที:

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

flag -http จะเปิด web UI แบบ interactive ที่มีทั้ง flame graph, call graph และ source code พร้อมคำอธิบายประกอบ

อย่าเปิด /debug/pprof ให้เข้าถึงได้จากภายนอกเด็ดขาด เพราะ profile เปิดเผยรายละเอียดภายในของระบบ และบาง endpoint ก็มีต้นทุนในการ serve สูง

profile ที่สำคัญ

mutex profile และ block profile ถูกปิดไว้เป็นค่าเริ่มต้น ให้เปิดใช้ด้วย runtime.SetMutexProfileFraction และ runtime.SetBlockProfileRate เมื่อสงสัยว่ามีการแย่งชิง lock (contention)

การอ่าน flame graph

ในมุมมอง flame graph:

• ความกว้างคือต้นทุน กล่องที่กว้างกว่าหมายถึงมี sample มากกว่าในฟังก์ชันนั้นรวมถึงทุกอย่างที่มันเรียก
• ตำแหน่งแนวตั้งคือความลึกของการเรียก ใน pprof ฟังก์ชันผู้เรียกจะอยู่ด้านบนฟังก์ชันที่ถูกเรียก
• มองหา ที่ราบกว้าง ๆ (wide plateau) ซึ่งหมายถึงฟังก์ชันที่กว้างด้วยตัวเอง ไม่ใช่กว้างเพราะฟังก์ชันลูก ตรงนั้นคือที่ที่เวลาถูกใช้ไปจริง ๆ

สลับไปมาระหว่าง flat และ cumulative ในมุมมอง top โดย flat time คืองานที่ทำในตัวฟังก์ชันเอง ส่วน cumulative time รวมฟังก์ชันที่ถูกเรียกด้วย ฟังก์ชันที่มี cumulative สูงแต่ flat ต่ำคือตัวประสานงาน ให้เจาะลงไปดูข้างในมัน

ผู้ต้องสงสัยประจำ

หลังจากทำ profiling ให้ service ภาษา Go มาหลายตัว ปัญหาเดิม ๆ ไม่กี่อย่างก็โผล่มาซ้ำแล้วซ้ำเล่า

1. Allocation pressure

ต้นทุนของ garbage collector แปรผันตามอัตราการ allocate ใน allocs profile ให้มองหา runtime.mallocgc ที่อยู่ใกล้ด้านบน แล้วไล่ขึ้นไปจนเจอโค้ดของคุณ วิธีแก้ที่พบบ่อย:

จอง slice ล่วงหน้าเมื่อรู้ขนาด:

// Before: grows and copies repeatedly
var ids []string
for _, u := range users {
    ids = append(ids, u.ID)
}

// After: one allocation
ids := make([]string, 0, len(users))
for _, u := range users {
    ids = append(ids, u.ID)
}

ใช้ strings.Builder แทนการต่อ string ซ้ำ ๆ และเรียก Grow ถ้าประเมินขนาดสุดท้ายได้

นำ buffer อายุสั้นกลับมาใช้ใหม่ด้วย sync.Pool ใน hot path อย่างเช่น encoder:

var bufPool = sync.Pool{New: func() any { return new(bytes.Buffer) }}

func encode(v any) ([]byte, error) {
    buf := bufPool.Get().(*bytes.Buffer)
    buf.Reset()
    defer bufPool.Put(buf)
    if err := json.NewEncoder(buf).Encode(v); err != nil {
        return nil, err
    }
    return bytes.Clone(buf.Bytes()), nil
}

2. การ escape ไปยัง heap

value ที่มีอายุยาวกว่าฟังก์ชันของมันจะ "escape" ไปอยู่บน heap ลองถาม compiler ดูว่า value ตัวไหนบ้างที่ escape:

go build -gcflags='-m' ./invoice 2>&1 | grep escapes

สาเหตุที่พบบ่อยคือการ return pointer ของ struct ขนาดเล็ก การเก็บ value ไว้ใน interface และการ capture ตัวแปรใน closure การ return struct ขนาดเล็กแบบ by value มักเร็วกว่าการ return pointer

3. Serialization ที่พึ่งพา reflection หนัก ๆ

encoding/json ใช้ reflection ถ้า JSON encoding กิน CPU profile เป็นส่วนใหญ่ ให้พิจารณาใช้ encoder แบบ code generation สำหรับ type ที่ถูกใช้บ่อยที่สุด หรือลดปริมาณข้อมูลที่ต้อง serialize ตั้งแต่ต้น

4. ต้นทุนแฝงของ fmt

fmt.Sprintf ใน hot loop จะ allocate และ parse format string ทุกครั้ง สำหรับการแปลงค่าแบบง่าย ๆ strconv.Itoa และ strconv.AppendInt ถูกกว่ามาก

5. Lock contention

ถ้า CPU usage ต่ำแต่ latency สูง ให้ดูที่ mutex profile lock ตัวเดียวที่ครอบ map แบบ global สามารถทำให้ทั้ง service ทำงานแบบเรียงคิวทีละตัวได้ ทางเลือกมีทั้งการแบ่ง map เป็น shard การใช้ sync.RWMutex สำหรับการเข้าถึงที่อ่านเป็นหลัก หรือออกแบบใหม่ให้ goroutine ไม่ต้องแชร์ state กันเลย

ยืนยันผลด้วย benchstat

หลังจากแก้ไขแล้ว ให้รัน benchmark ใหม่แล้วเปรียบเทียบ:

go test -bench=RenderInvoice -count=10 ./invoice > after.txt
benchstat before.txt after.txt

name             old time/op    new time/op    delta
RenderInvoice-8    48.2µs ± 2%    21.7µs ± 1%   -55.0%
name             old allocs/op  new allocs/op  delta
RenderInvoice-8       412 ± 0%        37 ± 0%   -91.0%

delta ที่สูงพร้อม ± ที่ต่ำหมายความว่าการปรับปรุงนั้นได้ผลจริง แต่ถ้าช่วงความเชื่อมั่น (confidence interval) ซ้อนทับกัน สิ่งที่คุณเห็นก็เป็นแค่ noise

Continuous profiling

ปัญหาบางอย่างจะปรากฏเฉพาะภายใต้รูปแบบ traffic จริงบน production เท่านั้น continuous profiler จะเก็บ sample จากทุก instance ด้วย overhead ต่ำ และให้คุณเปรียบเทียบ profile ข้ามการ deploy แต่ละครั้งได้ ทำให้ตอบคำถามอย่าง "release เมื่อวานทำให้อะไรช้าลง?" ได้ภายในไม่กี่นาที

วงจรการทำงานอย่างมีวินัย

1. เขียน benchmark ที่จำลอง path ที่ช้าได้
2. ทำ profile แล้วหาที่ราบที่กว้างที่สุด
3. แก้ไข ทีละหนึ่ง จุด
4. ยืนยันผลด้วย benchstat
5. ทำซ้ำจนกว่า service จะเร็วพอ แล้วหยุด

ขั้นตอนสุดท้ายนี้สำคัญ การ optimize เกินกว่า latency budget ที่ตั้งไว้ทำให้โค้ดอ่านยากขึ้น โดยที่ผู้ใช้ไม่ได้รับประโยชน์อะไรที่มองเห็นได้เลย