add dev-only profiling with pprof, runtime/trace, and operation timing
Wire up Go's standard profiling toolkit so it's automatically available in dev builds and completely absent from production. The profiling package uses build tags (dev/!dev) to eliminate all pprof, trace, and timing code from release binaries with zero new dependencies. - backend/profiling: pprof HTTP server on :6060, /debug/trace endpoint, block/mutex profiling, and TimeOp helper for structured operation timing - scripts/profile.sh: interactive menu-driven script that auto-selects free ports (8080-8089) so multiple profiles can be open simultaneously - Instrumented key operations: app init, database init, player load/restore, queue set/restore - Makefile targets: profile, profile-cpu, profile-heap, profile-trace - .gitignore: exclude trace-*.out and *.pprof artifacts
This commit is contained in:
@@ -0,0 +1,56 @@
|
||||
// Package profiling provides dev-only performance profiling via pprof and runtime/trace.
|
||||
//
|
||||
// In dev builds (build tag "dev"), Start launches an HTTP server on localhost:6060
|
||||
// exposing the standard pprof endpoints and a /debug/trace endpoint for capturing
|
||||
// execution traces. It also enables block and mutex profiling at reasonable sampling
|
||||
// rates.
|
||||
//
|
||||
// In production builds, all exported functions are no-ops and the pprof/trace
|
||||
// imports are excluded from the binary entirely.
|
||||
//
|
||||
// # Quick start
|
||||
//
|
||||
// Run the app in dev mode (pprof starts automatically):
|
||||
//
|
||||
// make dev
|
||||
//
|
||||
// Then, in a separate terminal, use the interactive profiling helper:
|
||||
//
|
||||
// ./scripts/profile.sh
|
||||
//
|
||||
// The script provides a menu-driven interface that opens results in your
|
||||
// browser as flame graphs. No pprof knowledge required. You can also
|
||||
// invoke it directly:
|
||||
//
|
||||
// ./scripts/profile.sh cpu # CPU profile
|
||||
// ./scripts/profile.sh heap # Heap (memory) profile
|
||||
// ./scripts/profile.sh allocs # Allocation profile
|
||||
// ./scripts/profile.sh goroutine # Goroutine dump
|
||||
// ./scripts/profile.sh block # Block (sync) profile
|
||||
// ./scripts/profile.sh mutex # Mutex contention profile
|
||||
// ./scripts/profile.sh trace # Execution trace
|
||||
// ./scripts/profile.sh health # Quick runtime health check
|
||||
//
|
||||
// # Manual usage
|
||||
//
|
||||
// If you prefer the CLI directly:
|
||||
//
|
||||
// go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30 # CPU
|
||||
// go tool pprof http://localhost:6060/debug/pprof/heap # Memory
|
||||
// go tool pprof http://localhost:6060/debug/pprof/goroutine # Goroutines
|
||||
// curl -o trace.out http://localhost:6060/debug/trace?seconds=5 # Trace
|
||||
// go tool trace trace.out
|
||||
//
|
||||
// # Programmatic usage
|
||||
//
|
||||
// stop := profiling.Start(logger)
|
||||
// defer stop()
|
||||
//
|
||||
// # Operation timing
|
||||
//
|
||||
// Use TimeOp to log the duration of any operation in dev builds:
|
||||
//
|
||||
// defer profiling.TimeOp(logger, "player.LoadFile")()
|
||||
//
|
||||
// In production builds TimeOp is a no-op with zero overhead.
|
||||
package profiling
|
||||
@@ -0,0 +1,159 @@
|
||||
//go:build dev
|
||||
|
||||
package profiling
|
||||
|
||||
import (
|
||||
"context"
|
||||
"errors"
|
||||
"fmt"
|
||||
"log/slog"
|
||||
"net"
|
||||
"net/http"
|
||||
"net/http/pprof"
|
||||
"runtime"
|
||||
"runtime/trace"
|
||||
"strconv"
|
||||
"time"
|
||||
)
|
||||
|
||||
const (
|
||||
// pprofAddr is the address the pprof HTTP server listens on.
|
||||
pprofAddr = "localhost:6060"
|
||||
|
||||
// defaultTraceSecs is the default trace capture duration.
|
||||
defaultTraceSecs = 5
|
||||
|
||||
// blockProfileRate controls the fraction of goroutine blocking
|
||||
// events reported. 1 = every event (most detailed, slight overhead).
|
||||
blockProfileRate = 1
|
||||
|
||||
// mutexProfileFraction controls the fraction of mutex contention
|
||||
// events reported. 5 = 1/5 of events.
|
||||
mutexProfileFraction = 5
|
||||
|
||||
// serverShutdownTimeout is the maximum time to wait for the
|
||||
// pprof server to drain connections on shutdown.
|
||||
serverShutdownTimeout = 5 * time.Second
|
||||
)
|
||||
|
||||
// Start launches the pprof HTTP server and enables block/mutex profiling.
|
||||
// It returns a stop function that gracefully shuts down the server.
|
||||
func Start(logger *slog.Logger) func() {
|
||||
plog := logger.WithGroup("profiling")
|
||||
|
||||
// Enable block and mutex profiling so /debug/pprof/block and
|
||||
// /debug/pprof/mutex return useful data.
|
||||
runtime.SetBlockProfileRate(blockProfileRate)
|
||||
runtime.SetMutexProfileFraction(mutexProfileFraction)
|
||||
|
||||
mux := http.NewServeMux()
|
||||
|
||||
// Register the standard pprof handlers.
|
||||
mux.HandleFunc("/debug/pprof/", pprof.Index)
|
||||
mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
|
||||
mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
|
||||
mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
|
||||
mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
|
||||
|
||||
// Custom endpoint: capture a runtime/trace for a configurable
|
||||
// duration and stream it back. Usage:
|
||||
// curl -o trace.out http://localhost:6060/debug/trace?seconds=5
|
||||
// go tool trace trace.out
|
||||
mux.HandleFunc("/debug/trace", traceHandler(plog))
|
||||
|
||||
srv := &http.Server{
|
||||
Addr: pprofAddr,
|
||||
Handler: mux,
|
||||
ReadHeaderTimeout: 5 * time.Second,
|
||||
}
|
||||
|
||||
// Use a listener so we can log the actual bound address.
|
||||
ln, err := net.Listen("tcp", pprofAddr)
|
||||
if err != nil {
|
||||
plog.Error(
|
||||
"Failed to start pprof server",
|
||||
"addr", pprofAddr, "err", err,
|
||||
)
|
||||
|
||||
return func() {}
|
||||
}
|
||||
|
||||
plog.Info(
|
||||
fmt.Sprintf(
|
||||
"pprof server listening on http://%s/debug/pprof/",
|
||||
ln.Addr().String(),
|
||||
),
|
||||
)
|
||||
|
||||
go func() {
|
||||
if serveErr := srv.Serve(ln); serveErr != nil &&
|
||||
!errors.Is(serveErr, http.ErrServerClosed) {
|
||||
plog.Error("pprof server error", "err", serveErr)
|
||||
}
|
||||
}()
|
||||
|
||||
return func() {
|
||||
plog.Info("Shutting down pprof server")
|
||||
|
||||
ctx, cancel := context.WithTimeout(
|
||||
context.Background(), serverShutdownTimeout,
|
||||
)
|
||||
defer cancel()
|
||||
|
||||
if shutErr := srv.Shutdown(ctx); shutErr != nil {
|
||||
plog.Error(
|
||||
"pprof server shutdown error",
|
||||
"err", shutErr,
|
||||
)
|
||||
}
|
||||
|
||||
// Disable block/mutex profiling.
|
||||
runtime.SetBlockProfileRate(0)
|
||||
runtime.SetMutexProfileFraction(0)
|
||||
}
|
||||
}
|
||||
|
||||
// traceHandler returns an HTTP handler that captures a runtime/trace
|
||||
// for the requested number of seconds (default 5).
|
||||
func traceHandler(logger *slog.Logger) http.HandlerFunc {
|
||||
return func(w http.ResponseWriter, r *http.Request) {
|
||||
secs := defaultTraceSecs
|
||||
|
||||
if s := r.URL.Query().Get("seconds"); s != "" {
|
||||
if v, err := strconv.Atoi(s); err == nil && v > 0 {
|
||||
secs = v
|
||||
}
|
||||
}
|
||||
|
||||
logger.Info(
|
||||
"Starting trace capture",
|
||||
"seconds", secs,
|
||||
)
|
||||
|
||||
w.Header().Set(
|
||||
"Content-Type", "application/octet-stream",
|
||||
)
|
||||
w.Header().Set(
|
||||
"Content-Disposition",
|
||||
"attachment; filename=trace.out",
|
||||
)
|
||||
|
||||
if err := trace.Start(w); err != nil {
|
||||
http.Error(
|
||||
w,
|
||||
fmt.Sprintf("trace already in progress: %v", err),
|
||||
http.StatusConflict,
|
||||
)
|
||||
|
||||
return
|
||||
}
|
||||
|
||||
time.Sleep(time.Duration(secs) * time.Second)
|
||||
trace.Stop()
|
||||
|
||||
logger.Info(
|
||||
"Trace capture complete",
|
||||
"seconds", secs,
|
||||
)
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,11 @@
|
||||
//go:build !dev
|
||||
|
||||
package profiling
|
||||
|
||||
import "log/slog"
|
||||
|
||||
// Start is a no-op in production builds. The pprof and runtime/trace
|
||||
// imports are excluded entirely, adding zero overhead to the binary.
|
||||
func Start(_ *slog.Logger) func() {
|
||||
return func() {}
|
||||
}
|
||||
@@ -0,0 +1,29 @@
|
||||
//go:build dev
|
||||
|
||||
package profiling
|
||||
|
||||
import (
|
||||
"log/slog"
|
||||
"time"
|
||||
)
|
||||
|
||||
// TimeOp starts a timer and returns a function that, when called, logs the
|
||||
// elapsed duration. Intended for use with defer:
|
||||
//
|
||||
// defer profiling.TimeOp(logger, "database.Init")()
|
||||
//
|
||||
// The extra () is required — defer evaluates the outer call immediately
|
||||
// (capturing the start time) and defers the returned closure.
|
||||
func TimeOp(logger *slog.Logger, operation string) func() {
|
||||
start := time.Now()
|
||||
|
||||
logger.Debug("operation started", "op", operation)
|
||||
|
||||
return func() {
|
||||
logger.Info(
|
||||
"operation completed",
|
||||
"op", operation,
|
||||
"duration", time.Since(start),
|
||||
)
|
||||
}
|
||||
}
|
||||
@@ -0,0 +1,13 @@
|
||||
//go:build !dev
|
||||
|
||||
package profiling
|
||||
|
||||
import "log/slog"
|
||||
|
||||
func noop() {}
|
||||
|
||||
// TimeOp is a no-op in production builds. The compiler will inline
|
||||
// and eliminate this entirely.
|
||||
func TimeOp(_ *slog.Logger, _ string) func() {
|
||||
return noop
|
||||
}
|
||||
Reference in New Issue
Block a user