Advanced Profiling Techniques
Beyond basic CPU and memory profiling, Go offers several specialized profiling tools for specific performance issues.
Goroutine Profiling
Goroutine profiling helps identify concurrency issues and goroutine leaks:
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"runtime"
"sync"
"time"
)
// Global WaitGroup that we'll intentionally never finish
var wg sync.WaitGroup
// Function that leaks goroutines
func leakGoroutines() {
fmt.Println("Starting to leak goroutines...")
// Leak goroutines by never calling wg.Done()
for i := 0; i < 10000; i++ {
wg.Add(1)
go func(id int) {
// This goroutine will never exit because we never call wg.Done()
fmt.Printf("Goroutine %d is leaked\n", id)
time.Sleep(1 * time.Hour) // Sleep for a long time
// wg.Done() is never called
}(i)
// Print stats every 1000 goroutines
if i > 0 && i%1000 == 0 {
fmt.Printf("Created %d goroutines, total: %d\n", i, runtime.NumGoroutine())
time.Sleep(100 * time.Millisecond)
}
}
}
// Function that demonstrates proper goroutine management
func properGoroutineManagement() {
fmt.Println("Demonstrating proper goroutine management...")
var localWg sync.WaitGroup
// Create goroutines with proper cleanup
for i := 0; i < 10000; i++ {
localWg.Add(1)
go func(id int) {
defer localWg.Done() // Ensure we always mark as done
// Do some work
time.Sleep(10 * time.Millisecond)
}(i)
// Print stats every 1000 goroutines
if i > 0 && i%1000 == 0 {
fmt.Printf("Created %d goroutines, total: %d\n", i, runtime.NumGoroutine())
}
}
// Wait for all goroutines to finish
fmt.Println("Waiting for all goroutines to finish...")
localWg.Wait()
fmt.Printf("All goroutines finished, remaining: %d\n", runtime.NumGoroutine())
}
// Function that demonstrates goroutine blocking
func demonstrateGoroutineBlocking() {
fmt.Println("Demonstrating goroutine blocking...")
// Create a channel without a buffer
ch := make(chan int)
// Start goroutines that will block on the channel
for i := 0; i < 100; i++ {
go func(id int) {
fmt.Printf("Goroutine %d waiting to send...\n", id)
ch <- id // This will block until someone receives
fmt.Printf("Goroutine %d sent value\n", id)
}(i)
}
// Let goroutines block for a while
time.Sleep(1 * time.Second)
fmt.Printf("After blocking: %d goroutines\n", runtime.NumGoroutine())
// Receive from some goroutines to unblock them
for i := 0; i < 10; i++ {
fmt.Printf("Received: %d\n", <-ch)
}
fmt.Printf("After receiving 10 values: %d goroutines\n", runtime.NumGoroutine())
}
func main() {
// Start pprof server
go func() {
fmt.Println("Starting pprof server on :8080")
http.ListenAndServe(":8080", nil)
}()
// Wait for pprof server to start
time.Sleep(100 * time.Millisecond)
// Print initial goroutine count
fmt.Printf("Initial goroutine count: %d\n", runtime.NumGoroutine())
// Demonstrate proper goroutine management
properGoroutineManagement()
// Demonstrate goroutine blocking
demonstrateGoroutineBlocking()
// Leak goroutines (comment out to avoid actual leaking)
// leakGoroutines()
fmt.Println("\nTo analyze goroutines:")
fmt.Println("1. View goroutine profile: go tool pprof http://localhost:8080/debug/pprof/goroutine")
fmt.Println("2. Get text listing: curl http://localhost:8080/debug/pprof/goroutine?debug=1")
fmt.Println("3. View full goroutine stack traces: curl http://localhost:8080/debug/pprof/goroutine?debug=2")
// Keep the program running to allow pprof access
fmt.Println("\nPress Ctrl+C to exit")
select {}
}
Mutex Profiling
Mutex profiling helps identify lock contention issues:
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"runtime"
"sync"
"time"
)
// Global mutex for demonstration
var globalMutex sync.Mutex
// Counter protected by mutex
var counter int
// Function with high mutex contention
func highContentionFunction() {
var wg sync.WaitGroup
// Enable mutex profiling
runtime.SetMutexProfileFraction(5) // 1/5 of mutex events are sampled
fmt.Println("Running high contention scenario...")
// Create many goroutines that all try to access the same mutex
for i := 0; i < 100; i++ {
wg.Add(1)
go func() {
defer wg.Done()
// Each goroutine acquires and releases the mutex 1000 times
for j := 0; j < 1000; j++ {
globalMutex.Lock()
counter++
globalMutex.Unlock()
}
}()
}
wg.Wait()
fmt.Printf("High contention counter: %d\n", counter)
}
// Function with optimized locking strategy
func lowContentionFunction() {
var wg sync.WaitGroup
counter = 0
fmt.Println("Running low contention scenario...")
// Create many goroutines with local counters
for i := 0; i < 100; i++ {
wg.Add(1)
go func() {
defer wg.Done()
// Each goroutine maintains its own counter
localCounter := 0
for j := 0; j < 1000; j++ {
localCounter++
}
// Only lock once at the end to update the global counter
globalMutex.Lock()
counter += localCounter
globalMutex.Unlock()
}()
}
wg.Wait()
fmt.Printf("Low contention counter: %d\n", counter)
}
// Function demonstrating read-write mutex
func readWriteMutexDemo() {
var rwMutex sync.RWMutex
var data = make(map[int]int)
counter = 0
var wg sync.WaitGroup
fmt.Println("Running read-write mutex scenario...")
// Start writer goroutines (fewer)
for i := 0; i < 5; i++ {
wg.Add(1)
go func(id int) {
defer wg.Done()
// Writers need exclusive access
for j := 0; j < 100; j++ {
rwMutex.Lock()
data[j] = id
rwMutex.Unlock()
// Simulate some processing time
time.Sleep(1 * time.Millisecond)
}
}(i)
}
// Start reader goroutines (many more)
for i := 0; i < 100; i++ {
wg.Add(1)
go func() {
defer wg.Done()
// Readers can access concurrently
for j := 0; j < 1000; j++ {
rwMutex.RLock()
_ = data[j%100]
rwMutex.RUnlock()
// Count reads
globalMutex.Lock()
counter++
globalMutex.Unlock()
}
}()
}
wg.Wait()
fmt.Printf("Read-write mutex: %d reads performed\n", counter)
}
func main() {
// Start pprof server
go func() {
fmt.Println("Starting pprof server on :8080")
http.ListenAndServe(":8080", nil)
}()
// Wait for pprof server to start
time.Sleep(100 * time.Millisecond)
// Run high contention scenario
highContentionFunction()
// Run low contention scenario
lowContentionFunction()
// Run read-write mutex scenario
readWriteMutexDemo()
fmt.Println("\nTo analyze mutex contention:")
fmt.Println("1. View mutex profile: go tool pprof http://localhost:8080/debug/pprof/mutex")
fmt.Println("2. Get text listing: curl http://localhost:8080/debug/pprof/mutex?debug=1")
// Keep the program running to allow pprof access
fmt.Println("\nPress Ctrl+C to exit")
select {}
}
Block Profiling
Block profiling helps identify where goroutines spend time waiting:
package main
import (
"fmt"
"net/http"
_ "net/http/pprof"
"os"
"runtime"
"runtime/pprof"
"sync"
"time"
)
// Function demonstrating channel blocking
func channelBlockingDemo() {
fmt.Println("Running channel blocking demo...")
// Create a channel with small buffer
ch := make(chan int, 5)
var wg sync.WaitGroup
// Producer goroutines
for i := 0; i < 10; i++ {
wg.Add(1)
go func(id int) {
defer wg.Done()
for j := 0; j < 100; j++ {
// This will block when the channel is full
ch <- id*1000 + j
time.Sleep(1 * time.Millisecond)
}
}(i)
}
// Consumer goroutine - intentionally slow
wg.Add(1)
go func() {
defer wg.Done()
for i := 0; i < 1000; i++ {
val := <-ch
fmt.Printf("Received: %d\n", val)
time.Sleep(5 * time.Millisecond) // Slower than producers
}
}()
wg.Wait()
}
// Function demonstrating I/O blocking
func ioBlockingDemo() {
fmt.Println("Running I/O blocking demo...")
var wg sync.WaitGroup
// Create temporary files
tempFiles := make([]*os.File, 5)
for i := range tempFiles {
file, err := os.CreateTemp("", "block-profile-demo")
if err != nil {
fmt.Printf("Error creating temp file: %v\n", err)
continue
}
defer os.Remove(file.Name())
defer file.Close()
tempFiles[i] = file
}
// Goroutines performing file I/O
for i := 0; i < 10; i++ {
wg.Add(1)
go func(id int) {
defer wg.Done()
// Choose a file
fileIndex := id % len(tempFiles)
file := tempFiles[fileIndex]
// Write data to file (may block)
data := make([]byte, 1024*1024) // 1MB
for j := range data {
data[j] = byte(id)
}
for j := 0; j < 10; j++ {
_, err := file.Write(data)
if err != nil {
fmt.Printf("Error writing to file: %v\n", err)
}
// Sync to disk (will block)
file.Sync()
}
}(i)
}
wg.Wait()
}
// Function demonstrating mutex blocking
func mutexBlockingDemo() {
fmt.Println("Running mutex blocking demo...")
var mu sync.Mutex
var wg sync.WaitGroup
// Goroutine that holds the lock for a long time
wg.Add(1)
go func() {
defer wg.Done()
for i := 0; i < 5; i++ {
mu.Lock()
fmt.Println("Long operation has the lock")
time.Sleep(100 * time.Millisecond) // Hold lock for a long time
mu.Unlock()
// Give other goroutines a chance
time.Sleep(10 * time.Millisecond)
}
}()
// Goroutines that need the lock frequently
for i := 0; i < 10; i++ {
wg.Add(1)
go func(id int) {
defer wg.Done()
for j := 0; j < 10; j++ {
mu.Lock() // Will block waiting for the long operation
fmt.Printf("Goroutine %d got the lock\n", id)
time.Sleep(1 * time.Millisecond) // Short operation
mu.Unlock()
// Do some work without the lock
time.Sleep(5 * time.Millisecond)
}
}(i)
}
wg.Wait()
}
func main() {
// Enable block profiling
runtime.SetBlockProfileRate(1) // Sample every blocking event
// Start pprof server
go func() {
fmt.Println("Starting pprof server on :8080")
http.ListenAndServe(":8080", nil)
}()
// Wait for pprof server to start
time.Sleep(100 * time.Millisecond)
// Run demos
channelBlockingDemo()
ioBlockingDemo()
mutexBlockingDemo()
// Save block profile
f, err := os.Create("block.prof")
if err != nil {
fmt.Printf("Error creating profile file: %v\n", err)
} else {
pprof.Lookup("block").WriteTo(f, 0)
f.Close()
fmt.Println("Block profile written to block.prof")
}
fmt.Println("\nTo analyze blocking:")
fmt.Println("1. View block profile: go tool pprof http://localhost:8080/debug/pprof/block")
fmt.Println("2. Analyze saved profile: go tool pprof -http=:8081 block.prof")
// Keep the program running to allow pprof access
fmt.Println("\nPress Ctrl+C to exit")
select {}
}