diff --git a/.gitignore b/.gitignore index ea76931..900ed8d 100644 --- a/.gitignore +++ b/.gitignore @@ -8,6 +8,7 @@ bin/ coverage.html *.prof coverage.out +!docs/profiles/*.prof test.go diff --git a/cmd/gobalancer/serve.go b/cmd/gobalancer/serve.go index c21319a..79532ea 100644 --- a/cmd/gobalancer/serve.go +++ b/cmd/gobalancer/serve.go @@ -9,6 +9,7 @@ import ( "github.com/Sachinxmpl/gobalancer/internal/balancer" "github.com/Sachinxmpl/gobalancer/internal/config" + "github.com/Sachinxmpl/gobalancer/internal/debug" "github.com/Sachinxmpl/gobalancer/internal/health" "github.com/Sachinxmpl/gobalancer/internal/listener" "github.com/Sachinxmpl/gobalancer/internal/metrics" @@ -34,6 +35,12 @@ func Serve(args []string) error { "metrics server address", ) + debugAddr := fs.String( + "debug-addr", + "", + "pprof debug server address, e.g. 127.0.0.1:6060 (empty = disabled)", + ) + if err := fs.Parse(args); err != nil { return err } @@ -62,6 +69,15 @@ func Serve(args []string) error { return err } + var debugSrv *debug.Server + if *debugAddr != "" { + debugSrv = debug.NewServer(*debugAddr, log) + if err := debugSrv.Start(); err != nil { + log.Error("failed to start debug server", "addr", *debugAddr, "err", err) + return err + } + } + balancer, err := balancer.New(cfg.Balancer, registry) if err != nil { log.Error("failed to create balancer", "algorithm", cfg.Balancer, "err", err) @@ -138,6 +154,12 @@ func Serve(args []string) error { log.Warn("Failed to shutdown metrics server", "err", err) } + if debugSrv != nil { + if err := debugSrv.ShutDown(shutdownCtx); err != nil { + log.Warn("failed to shutdown debug server", "err", err) + } + } + log.Info("stopped") return nil } diff --git a/configl7.example.yaml b/configl7.example.yaml index 3ab0ad8..ce33f20 100644 --- a/configl7.example.yaml +++ b/configl7.example.yaml @@ -1,10 +1,39 @@ # example configuration file mode: l7 -listen: "127.0.0.1:8080" +listen: "0.0.0.0:8080" + +balancer: round_robin + +timeouts: + dial: 300ms + read: 30s + write: 30s + idle: 60s + request: 30s + drain: 15s + +health: + active: + interval: 2s + timeout: 500ms + rise: 2 + passive: + fall: 3 + cooldown: 10s + +rate_limit: + global_rps: 0 + per_client_rps: 0 + routes: - - match: { path_prefix: "/" } - pool: default + - match: + path_prefix: "/" + pool: web + pools: - default: + web: - addr: "127.0.0.1:9001" + weight: 1 + - addr: "127.0.0.1:9002" + weight: 1 diff --git a/docs/benchmark.md b/docs/benchmark.md index 92ec04e..3eba7f8 100644 --- a/docs/benchmark.md +++ b/docs/benchmark.md @@ -135,6 +135,10 @@ Both served every request successfully at ~965/s. **What it proves.** With one sick backend and round-robin balancing, enabling the passive path reduces mean latency from 106 ms to 8.3 ms and p90 from 307 ms to 6.7 ms. With the passive path disabled, round-robin sends approximately one-third of requests to the sick backend; each times out after 300 ms and is retried, so a third of all requests are slow for the entire run. With the passive path enabled, the sick backend is evicted after 3 failures and traffic goes only to the healthy backends. In GoBalancer the passive path is the only mechanism that evicts a backend — the active prober only readmits — so active-only means no eviction at all. The passive+active p999 of 308 ms reflects brief flapping: the active prober's TCP-only probe succeeds against the sick backend (it accepts connections), readmitting it momentarily before the passive path evicts it again. +## Profiling + +Where the CPU and memory actually go under load — CPU, heap, and goroutine profiles captured with pprof — is written up separately in [profiling.md](profiling.md). In short: the proxy spends its CPU on network syscalls and scheduling, holds under 4 MB of live memory, and runs the load on less than one core. + ## Limitations All traffic runs on a single machine over loopback. This measures GoBalancer's own overhead — CPU and memory — not real-world network behaviour. On a real network the round-trip time between machines dwarfs the sub-millisecond cost measured here. Read these as "how much does the balancer add," not "how fast is a request in production." diff --git a/docs/profiles/cpu-top.txt b/docs/profiles/cpu-top.txt new file mode 100644 index 0000000..9d73452 --- /dev/null +++ b/docs/profiles/cpu-top.txt @@ -0,0 +1,213 @@ +File: gobalancer +Build ID: 5a6a7a4d1855a0a9b02d6e6cfbb5336c091cea4a +Type: cpu +Time: 2026-08-24 18:48:58 +0545 +Duration: 30s, Total samples = 25.77s (85.90%) +Showing nodes accounting for 17.89s, 69.42% of 25.77s total +Dropped 590 nodes (cum <= 0.13s) + flat flat% sum% cum cum% + 6.19s 24.02% 24.02% 6.19s 24.02% internal/runtime/syscall/linux.Syscall6 + 2.44s 9.47% 33.49% 2.44s 9.47% runtime.futex + 0.52s 2.02% 35.51% 1.56s 6.05% runtime.stealWork + 0.41s 1.59% 37.10% 0.41s 1.59% runtime.nextFreeFast (inline) + 0.36s 1.40% 38.49% 0.36s 1.40% runtime.usleep + 0.33s 1.28% 39.77% 0.41s 1.59% runtime.lock2 + 0.31s 1.20% 40.98% 0.31s 1.20% runtime.nanotime (inline) + 0.30s 1.16% 42.14% 6.21s 24.10% runtime.findRunnable + 0.26s 1.01% 43.15% 0.27s 1.05% runtime.(*mspan).writeHeapBitsSmall + 0.23s 0.89% 44.04% 0.23s 0.89% runtime.memclrNoHeapPointers + 0.22s 0.85% 44.90% 0.33s 1.28% net/textproto.CanonicalMIMEHeaderKey + 0.21s 0.81% 45.71% 0.79s 3.07% runtime.selectgo + 0.21s 0.81% 46.53% 0.24s 0.93% runtime.unlock2 + 0.19s 0.74% 47.26% 0.20s 0.78% runtime.(*timers).wakeTime (inline) + 0.19s 0.74% 48.00% 1.71s 6.64% runtime.netpoll + 0.16s 0.62% 48.62% 0.16s 0.62% runtime.memmove + 0.15s 0.58% 49.20% 0.52s 2.02% runtime.runqgrab + 0.15s 0.58% 49.79% 0.15s 0.58% time.runtimeNow + 0.14s 0.54% 50.33% 0.14s 0.54% aeshashbody + 0.14s 0.54% 50.87% 0.14s 0.54% indexbytebody + 0.13s 0.5% 51.38% 1.85s 7.18% runtime.mallocgc + 0.12s 0.47% 51.84% 0.13s 0.5% internal/sync.(*Mutex).Lock (inline) + 0.12s 0.47% 52.31% 1.10s 4.27% runtime.newobject + 0.11s 0.43% 52.74% 0.19s 0.74% internal/runtime/maps.(*Map).getWithoutKeySmallFastStr + 0.11s 0.43% 53.16% 1.52s 5.90% runtime.notesleep + 0.11s 0.43% 53.59% 0.18s 0.7% runtime.scanObjectsSmall + 0.10s 0.39% 53.98% 0.19s 0.74% context.(*cancelCtx).Done + 0.10s 0.39% 54.37% 0.22s 0.85% runtime.tryDeferToSpanScan + 0.09s 0.35% 54.71% 0.15s 0.58% runtime.casgstatus + 0.09s 0.35% 55.06% 0.17s 0.66% runtime.ifaceeq + 0.09s 0.35% 55.41% 0.16s 0.62% sync.(*Pool).Get + 0.08s 0.31% 55.72% 4.23s 16.41% github.com/Sachinxmpl/gobalancer/internal/proxy/l7.(*Server).forwardOnce + 0.08s 0.31% 56.03% 2.37s 9.20% net/http.(*conn).readRequest + 0.08s 0.31% 56.34% 0.24s 0.93% runtime.(*timer).modify + 0.08s 0.31% 56.66% 1.41s 5.47% runtime.mallocgcSmallScanNoHeader + 0.08s 0.31% 56.97% 0.33s 1.28% runtime.mapaccess1_faststr + 0.07s 0.27% 57.24% 1.81s 7.02% internal/poll.(*FD).Read + 0.07s 0.27% 57.51% 1.74s 6.75% net/http.(*Transport).roundTrip + 0.07s 0.27% 57.78% 1.38s 5.36% net/http.readRequest + 0.07s 0.27% 58.05% 0.24s 0.93% net/textproto.canonicalMIMEHeaderKey + 0.07s 0.27% 58.32% 0.17s 0.66% runtime.pidleget + 0.07s 0.27% 58.60% 0.21s 0.81% runtime.scanblock + 0.06s 0.23% 58.83% 1.82s 7.06% bufio.(*Reader).Peek + 0.06s 0.23% 59.06% 0.60s 2.33% internal/poll.runtime_pollSetDeadline + 0.06s 0.23% 59.29% 1.06s 4.11% net/textproto.readMIMEHeader + 0.06s 0.23% 59.53% 0.46s 1.79% runtime.mapassign_faststr + 0.05s 0.19% 59.72% 0.64s 2.48% io.copyBuffer + 0.05s 0.19% 59.91% 0.30s 1.16% net/http.(*Transport).queueForIdleConn + 0.05s 0.19% 60.11% 11.76s 45.63% net/http.(*conn).serve + 0.05s 0.19% 60.30% 2.53s 9.82% net/http.(*persistConn).readLoop + 0.05s 0.19% 60.50% 0.30s 1.16% net/http.(*persistConn).readLoop.func4 + 0.05s 0.19% 60.69% 0.75s 2.91% net/http.(*persistConn).roundTrip + 0.05s 0.19% 60.88% 0.14s 0.54% net/http.Header.sortedKeyValues + 0.05s 0.19% 61.08% 0.33s 1.28% net/http.Header.writeSubset + 0.05s 0.19% 61.27% 1.44s 5.59% runtime.futexsleep + 0.05s 0.19% 61.47% 0.19s 0.74% runtime.makechan + 0.05s 0.19% 61.66% 0.19s 0.74% runtime.makeslice + 0.05s 0.19% 61.85% 6.68s 25.92% runtime.park_m + 0.05s 0.19% 62.05% 0.13s 0.5% runtime.scanObject + 0.05s 0.19% 62.24% 6.60s 25.61% runtime.schedule + 0.04s 0.16% 62.40% 1.76s 6.83% bufio.(*Reader).fill + 0.04s 0.16% 62.55% 0.23s 0.89% context.(*cancelCtx).cancel + 0.04s 0.16% 62.71% 0.42s 1.63% context.WithDeadlineCause + 0.04s 0.16% 62.86% 0.13s 0.5% context.parentCancelCtx + 0.04s 0.16% 63.02% 0.16s 0.62% fmt.(*pp).doPrintf + 0.04s 0.16% 63.17% 4.48s 17.38% github.com/Sachinxmpl/gobalancer/internal/proxy/l7.(*Server).ServeHTTP + 0.04s 0.16% 63.33% 0.39s 1.51% io.(*LimitedReader).Read + 0.04s 0.16% 63.48% 1.90s 7.37% net.(*conn).Read + 0.04s 0.16% 63.64% 2.98s 11.56% net/http.(*persistConn).writeLoop + 0.04s 0.16% 63.80% 0.21s 0.81% net/http.readTransfer + 0.04s 0.16% 63.95% 0.42s 1.63% runtime.(*timers).check + 0.04s 0.16% 64.11% 0.38s 1.47% runtime.markroot + 0.04s 0.16% 64.26% 0.56s 2.17% runtime.runqsteal + 0.03s 0.12% 64.38% 4.41s 17.11% bufio.(*Writer).Flush + 0.03s 0.12% 64.49% 0.22s 0.85% github.com/Sachinxmpl/gobalancer/internal/proxy/l7.copyHeader + 0.03s 0.12% 64.61% 0.13s 0.5% internal/poll.(*pollDesc).wait + 0.03s 0.12% 64.73% 0.23s 0.89% internal/runtime/maps.(*Map).Delete + 0.03s 0.12% 64.84% 1.45s 5.63% internal/runtime/syscall/linux.EpollWait + 0.03s 0.12% 64.96% 0.23s 0.89% net/http.(*Request).Clone + 0.03s 0.12% 65.08% 2.86s 11.10% net/http.(*response).finishRequest + 0.03s 0.12% 65.19% 0.28s 1.09% net/http.Header.Clone (inline) + 0.03s 0.12% 65.31% 2.03s 7.88% net/http.checkConnErrorWriter.Write + 0.03s 0.12% 65.42% 0.30s 1.16% net/textproto.MIMEHeader.Del (inline) + 0.03s 0.12% 65.54% 0.18s 0.7% runtime.mapassign + 0.03s 0.12% 65.66% 6.82s 26.46% runtime.mcall + 0.03s 0.12% 65.77% 0.20s 0.78% runtime.newproc1 + 0.03s 0.12% 65.89% 1.61s 6.25% runtime.stopm + 0.02s 0.078% 65.97% 0.36s 1.40% context.(*cancelCtx).propagateCancel + 0.02s 0.078% 66.05% 0.25s 0.97% github.com/Sachinxmpl/gobalancer/internal/metrics.(*Metrics).RequestObserved + 0.02s 0.078% 66.12% 0.13s 0.5% github.com/prometheus/client_golang/prometheus.(*MetricVec).GetMetricWithLabelValues + 0.02s 0.078% 66.20% 0.35s 1.36% internal/runtime/maps.(*Map).growToSmall + 0.02s 0.078% 66.28% 3.93s 15.25% net.(*netFD).Write + 0.02s 0.078% 66.36% 0.24s 0.93% net/http.(*Transport).tryPutIdleConn + 0.02s 0.078% 66.43% 0.36s 1.40% net/http.(*bodyEOFSignal).Read + 0.02s 0.078% 66.51% 1.05s 4.07% net/http.(*connReader).Read + 0.02s 0.078% 66.59% 0.37s 1.44% net/http.(*connReader).backgroundRead + 0.02s 0.078% 66.67% 0.57s 2.21% net/http.(*response).ReadFrom + 0.02s 0.078% 66.74% 0.76s 2.95% net/http.ReadResponse + 0.02s 0.078% 66.82% 1.95s 7.57% net/http.persistConnWriter.Write + 0.02s 0.078% 66.90% 0.14s 0.54% net/textproto.(*Reader).readLineSlice + 0.02s 0.078% 66.98% 0.40s 1.55% runtime.(*mcache).nextFree + 0.02s 0.078% 67.05% 0.44s 1.71% runtime.chansend + 0.02s 0.078% 67.13% 0.43s 1.67% runtime.lockWithRank (inline) + 0.02s 0.078% 67.21% 0.14s 0.54% runtime.mapIterStart + 0.02s 0.078% 67.29% 0.13s 0.5% runtime.mapdelete_faststr + 0.02s 0.078% 67.37% 0.32s 1.24% runtime.reentersyscall + 0.02s 0.078% 67.44% 0.23s 0.89% runtime.slicebytetostring + 0.02s 0.078% 67.52% 0.90s 3.49% runtime.startm + 0.02s 0.078% 67.60% 0.14s 0.54% runtime.sweepone + 0.02s 0.078% 67.68% 2.70s 10.48% runtime.systemstack + 0.02s 0.078% 67.75% 0.26s 1.01% runtime.unlockWithRank (inline) + 0.02s 0.078% 67.83% 1.43s 5.55% syscall.Read (inline) + 0.02s 0.078% 67.91% 5.22s 20.26% syscall.Syscall + 0.02s 0.078% 67.99% 3.84s 14.90% syscall.write + 0.01s 0.039% 68.02% 0.13s 0.5% context.WithCancelCause.func1 + 0.01s 0.039% 68.06% 0.16s 0.62% context.removeChild + 0.01s 0.039% 68.10% 0.25s 0.97% context.withCancel (inline) + 0.01s 0.039% 68.14% 0.27s 1.05% fmt.Fprintf + 0.01s 0.039% 68.18% 0.31s 1.20% github.com/Sachinxmpl/gobalancer/internal/proxy/l7.stripHopByHop + 0.01s 0.039% 68.22% 0.13s 0.5% github.com/prometheus/client_golang/prometheus.(*CounterVec).GetMetricWithLabelValues (inline) + 0.01s 0.039% 68.26% 0.14s 0.54% github.com/prometheus/client_golang/prometheus.(*CounterVec).WithLabelValues + 0.01s 0.039% 68.30% 5.38s 20.88% internal/poll.ignoringEINTRIO (inline) + 0.01s 0.039% 68.34% 0.79s 3.07% internal/poll.setDeadlineImpl + 0.01s 0.039% 68.37% 0.33s 1.28% internal/runtime/maps.newGroups (inline) + 0.01s 0.039% 68.41% 0.32s 1.24% internal/runtime/maps.newarray + 0.01s 0.039% 68.45% 1.83s 7.10% net.(*netFD).Read + 0.01s 0.039% 68.49% 0.86s 3.34% net/http.(*Request).write + 0.01s 0.039% 68.53% 0.47s 1.82% net/http.(*Transport).getConn + 0.01s 0.039% 68.57% 0.16s 0.62% net/http.(*Transport).prepareTransportCancel.func1 + 0.01s 0.039% 68.61% 0.40s 1.55% net/http.(*chunkWriter).writeHeader + 0.01s 0.039% 68.65% 0.33s 1.28% net/http.(*connReader).abortPendingRead + 0.01s 0.039% 68.68% 0.67s 2.60% net/http.(*persistConn).Read + 0.01s 0.039% 68.72% 0.25s 0.97% net/http.(*persistConn).readLoop.func2 + 0.01s 0.039% 68.76% 4.49s 17.42% net/http.serverHandler.ServeHTTP + 0.01s 0.039% 68.80% 1.07s 4.15% net/textproto.(*Reader).ReadMIMEHeader (inline) + 0.01s 0.039% 68.84% 0.13s 0.5% net/url.ParseRequestURI + 0.01s 0.039% 68.88% 0.35s 1.36% runtime.(*mcache).refill + 0.01s 0.039% 68.92% 0.35s 1.36% runtime.entersyscall + 0.01s 0.039% 68.96% 0.25s 0.97% runtime.entersyscallWakeSysmon + 0.01s 0.039% 68.99% 0.13s 0.5% runtime.funcname (inline) + 0.01s 0.039% 69.03% 1.06s 4.11% runtime.futexwakeup + 0.01s 0.039% 69.07% 0.73s 2.83% runtime.goready (inline) + 0.01s 0.039% 69.11% 0.31s 1.20% runtime.newarray + 0.01s 0.039% 69.15% 1.07s 4.15% runtime.notewakeup + 0.01s 0.039% 69.19% 0.70s 2.72% runtime.ready + 0.01s 0.039% 69.23% 0.55s 2.13% runtime.send.goready.func1 + 0.01s 0.039% 69.27% 1.05s 4.07% runtime.wakep + 0.01s 0.039% 69.31% 4.78s 18.55% syscall.RawSyscall6 + 0.01s 0.039% 69.34% 1.41s 5.47% syscall.read + 0.01s 0.039% 69.38% 0.16s 0.62% time.Now + 0.01s 0.039% 69.42% 0.17s 0.66% time.Until + 0 0% 69.42% 0.22s 0.85% context.WithCancel + 0 0% 69.42% 0.42s 1.63% context.WithDeadline (inline) + 0 0% 69.42% 0.42s 1.63% context.WithTimeout + 0 0% 69.42% 0.62s 2.41% internal/poll.(*FD).SetReadDeadline (inline) + 0 0% 69.42% 0.17s 0.66% internal/poll.(*FD).SetWriteDeadline (inline) + 0 0% 69.42% 3.91s 15.17% internal/poll.(*FD).Write + 0 0% 69.42% 0.13s 0.5% internal/poll.(*pollDesc).waitRead (inline) + 0 0% 69.42% 0.59s 2.29% io.Copy (inline) + 0 0% 69.42% 0.52s 2.02% io.CopyBuffer + 0 0% 69.42% 0.62s 2.41% net.(*conn).SetReadDeadline + 0 0% 69.42% 0.17s 0.66% net.(*conn).SetWriteDeadline + 0 0% 69.42% 3.93s 15.25% net.(*conn).Write + 0 0% 69.42% 0.62s 2.41% net.(*netFD).SetReadDeadline (inline) + 0 0% 69.42% 0.17s 0.66% net.(*netFD).SetWriteDeadline (inline) + 0 0% 69.42% 1.74s 6.75% net/http.(*Transport).RoundTrip (inline) + 0 0% 69.42% 0.30s 1.16% net/http.(*bodyEOFSignal).condfn (inline) + 0 0% 69.42% 0.40s 1.55% net/http.(*chunkWriter).Write + 0 0% 69.42% 0.15s 0.58% net/http.(*conn).readRequest.func1 + 0 0% 69.42% 0.13s 0.5% net/http.(*connLRU).remove (inline) + 0 0% 69.42% 0.45s 1.75% net/http.(*connReader).startBackgroundRead + 0 0% 69.42% 0.76s 2.95% net/http.(*persistConn).readResponse + 0 0% 69.42% 0.15s 0.58% net/http.(*response).WriteHeader + 0 0% 69.42% 0.16s 0.62% net/http.Header.Add (inline) + 0 0% 69.42% 0.30s 1.16% net/http.Header.Del (inline) + 0 0% 69.42% 0.18s 0.7% net/http.Header.WriteSubset (inline) + 0 0% 69.42% 0.17s 0.66% net/textproto.(*Reader).ReadLine (inline) + 0 0% 69.42% 0.16s 0.62% net/textproto.MIMEHeader.Add (inline) + 0 0% 69.42% 0.24s 0.93% runtime.(*mcentral).cacheSpan + 0 0% 69.42% 0.17s 0.66% runtime.(*mcentral).grow + 0 0% 69.42% 0.13s 0.5% runtime.(*timer).maybeAdd + 0 0% 69.42% 0.17s 0.66% runtime.bgsweep + 0 0% 69.42% 0.44s 1.71% runtime.chansend1 + 0 0% 69.42% 0.95s 3.69% runtime.gcBgMarkWorker + 0 0% 69.42% 0.83s 3.22% runtime.gcBgMarkWorker.func2 + 0 0% 69.42% 0.83s 3.22% runtime.gcDrain + 0 0% 69.42% 0.48s 1.86% runtime.gcDrainMarkWorkerDedicated (inline) + 0 0% 69.42% 0.35s 1.36% runtime.gcDrainMarkWorkerIdle (inline) + 0 0% 69.42% 0.27s 1.05% runtime.heapSetTypeNoHeader (inline) + 0 0% 69.42% 0.14s 0.54% runtime.isSystemGoroutine + 0 0% 69.42% 0.43s 1.67% runtime.lock (inline) + 0 0% 69.42% 1.52s 5.90% runtime.mPark (inline) + 0 0% 69.42% 0.22s 0.85% runtime.markroot.func1 + 0 0% 69.42% 0.15s 0.58% runtime.netpollgoready + 0 0% 69.42% 0.15s 0.58% runtime.netpollgoready.goready.func1 + 0 0% 69.42% 0.40s 1.55% runtime.newproc + 0 0% 69.42% 0.40s 1.55% runtime.newproc.func1 + 0 0% 69.42% 0.23s 0.89% runtime.resetspinning + 0 0% 69.42% 0.25s 0.97% runtime.scanSpan + 0 0% 69.42% 0.13s 0.5% runtime.scanframeworker + 0 0% 69.42% 0.20s 0.78% runtime.scanstack + 0 0% 69.42% 0.56s 2.17% runtime.send + 0 0% 69.42% 0.26s 1.01% runtime.unlock (inline) + 0 0% 69.42% 0.13s 0.5% sync.(*Mutex).Lock (inline) + 0 0% 69.42% 3.84s 14.90% syscall.Write (inline) diff --git a/docs/profiles/cpu.prof b/docs/profiles/cpu.prof new file mode 100644 index 0000000..5dfc739 Binary files /dev/null and b/docs/profiles/cpu.prof differ diff --git a/docs/profiles/goroutine-top.txt b/docs/profiles/goroutine-top.txt new file mode 100644 index 0000000..3004cc5 --- /dev/null +++ b/docs/profiles/goroutine-top.txt @@ -0,0 +1,61 @@ +File: gobalancer +Build ID: 5a6a7a4d1855a0a9b02d6e6cfbb5336c091cea4a +Type: goroutine +Time: 2026-08-24 18:49:28 +0545 +Showing nodes accounting for 67, 98.53% of 68 total + flat flat% sum% cum cum% + 63 92.65% 92.65% 63 92.65% runtime.gopark + 1 1.47% 94.12% 1 1.47% github.com/Sachinxmpl/gobalancer/internal/proxy/l7.stripHopByHop + 1 1.47% 95.59% 1 1.47% runtime.goroutineProfileWithLabels + 1 1.47% 97.06% 1 1.47% runtime.notetsleepg + 1 1.47% 98.53% 1 1.47% syscall.Syscall + 0 0% 98.53% 44 64.71% bufio.(*Reader).Peek + 0 0% 98.53% 44 64.71% bufio.(*Reader).fill + 0 0% 98.53% 1 1.47% github.com/Sachinxmpl/gobalancer/internal/debug.(*Server).Start.func1 + 0 0% 98.53% 2 2.94% github.com/Sachinxmpl/gobalancer/internal/health.(*Manager).Sync.func1 + 0 0% 98.53% 2 2.94% github.com/Sachinxmpl/gobalancer/internal/health.(*Manager).probeLoop + 0 0% 98.53% 1 1.47% github.com/Sachinxmpl/gobalancer/internal/metrics.(*Server).Start.func1 + 0 0% 98.53% 1 1.47% github.com/Sachinxmpl/gobalancer/internal/proxy/l7.(*Server).ServeHTTP + 0 0% 98.53% 1 1.47% github.com/Sachinxmpl/gobalancer/internal/proxy/l7.(*Server).Start.func2 + 0 0% 98.53% 1 1.47% github.com/Sachinxmpl/gobalancer/internal/proxy/l7.(*Server).forwardOnce + 0 0% 98.53% 3 4.41% internal/poll.(*FD).Accept + 0 0% 98.53% 45 66.18% internal/poll.(*FD).Read + 0 0% 98.53% 47 69.12% internal/poll.(*pollDesc).wait + 0 0% 98.53% 47 69.12% internal/poll.(*pollDesc).waitRead (inline) + 0 0% 98.53% 1 1.47% internal/poll.ignoringEINTRIO (inline) + 0 0% 98.53% 47 69.12% internal/poll.runtime_pollWait + 0 0% 98.53% 1 1.47% main.Serve + 0 0% 98.53% 1 1.47% main.Serve.func1 + 0 0% 98.53% 1 1.47% main.main + 0 0% 98.53% 1 1.47% main.run + 0 0% 98.53% 3 4.41% net.(*TCPListener).Accept + 0 0% 98.53% 3 4.41% net.(*TCPListener).accept + 0 0% 98.53% 45 66.18% net.(*conn).Read + 0 0% 98.53% 45 66.18% net.(*netFD).Read + 0 0% 98.53% 3 4.41% net.(*netFD).accept + 0 0% 98.53% 1 1.47% net/http.(*ServeMux).ServeHTTP + 0 0% 98.53% 3 4.41% net/http.(*Server).Serve + 0 0% 98.53% 35 51.47% net/http.(*conn).serve + 0 0% 98.53% 33 48.53% net/http.(*connReader).Read + 0 0% 98.53% 1 1.47% net/http.(*connReader).backgroundRead + 0 0% 98.53% 11 16.18% net/http.(*persistConn).Read + 0 0% 98.53% 11 16.18% net/http.(*persistConn).readLoop + 0 0% 98.53% 11 16.18% net/http.(*persistConn).writeLoop + 0 0% 98.53% 1 1.47% net/http.HandlerFunc.ServeHTTP + 0 0% 98.53% 2 2.94% net/http.serverHandler.ServeHTTP + 0 0% 98.53% 1 1.47% net/http/pprof.Index + 0 0% 98.53% 1 1.47% net/http/pprof.handler.ServeHTTP + 0 0% 98.53% 1 1.47% os/signal.NotifyContext.func1 + 0 0% 98.53% 1 1.47% os/signal.loop + 0 0% 98.53% 1 1.47% os/signal.signal_recv + 0 0% 98.53% 1 1.47% runtime.chanrecv + 0 0% 98.53% 1 1.47% runtime.chanrecv1 + 0 0% 98.53% 1 1.47% runtime.main + 0 0% 98.53% 47 69.12% runtime.netpollblock + 0 0% 98.53% 1 1.47% runtime.pprof_goroutineProfileWithLabels + 0 0% 98.53% 15 22.06% runtime.selectgo + 0 0% 98.53% 1 1.47% runtime/pprof.(*Profile).WriteTo + 0 0% 98.53% 1 1.47% runtime/pprof.writeGoroutine + 0 0% 98.53% 1 1.47% runtime/pprof.writeRuntimeProfile + 0 0% 98.53% 1 1.47% syscall.Read (inline) + 0 0% 98.53% 1 1.47% syscall.read diff --git a/docs/profiles/goroutine.prof b/docs/profiles/goroutine.prof new file mode 100644 index 0000000..cbed277 Binary files /dev/null and b/docs/profiles/goroutine.prof differ diff --git a/docs/profiles/heap-top.txt b/docs/profiles/heap-top.txt new file mode 100644 index 0000000..85b75ca --- /dev/null +++ b/docs/profiles/heap-top.txt @@ -0,0 +1,45 @@ +File: gobalancer +Build ID: 5a6a7a4d1855a0a9b02d6e6cfbb5336c091cea4a +Type: inuse_space +Time: 2026-08-24 18:49:28 +0545 +Showing nodes accounting for 3691.07kB, 100% of 3691.07kB total + flat flat% sum% cum cum% + 902.59kB 24.45% 24.45% 2136.21kB 57.88% compress/flate.NewWriter (inline) + 650.62kB 17.63% 42.08% 1233.63kB 33.42% compress/flate.(*compressor).init + 583.01kB 15.80% 57.88% 583.01kB 15.80% compress/flate.newDeflateFast (inline) + 528.17kB 14.31% 72.18% 528.17kB 14.31% net/http.init.func16 + 513.69kB 13.92% 86.10% 513.69kB 13.92% syscall.init.func1 + 513kB 13.90% 100% 513kB 13.90% runtime.mallocgc + 0 0% 100% 2136.21kB 57.88% compress/gzip.(*Writer).Write + 0 0% 100% 513.69kB 13.92% google.golang.org/protobuf/internal/impl.init + 0 0% 100% 513.69kB 13.92% google.golang.org/protobuf/internal/impl.init.func1 (inline) + 0 0% 100% 528.17kB 14.31% net/http.(*Request).write + 0 0% 100% 528.17kB 14.31% net/http.(*persistConn).writeLoop + 0 0% 100% 528.17kB 14.31% net/http.(*transferWriter).doBodyCopy + 0 0% 100% 528.17kB 14.31% net/http.(*transferWriter).writeBody + 0 0% 100% 528.17kB 14.31% net/http.getCopyBuf (inline) + 0 0% 100% 513.69kB 13.92% os.Getenv + 0 0% 100% 513kB 13.90% runtime.allocm + 0 0% 100% 513.69kB 13.92% runtime.doInit (inline) + 0 0% 100% 513.69kB 13.92% runtime.doInit1 + 0 0% 100% 513.69kB 13.92% runtime.main + 0 0% 100% 513kB 13.90% runtime.mstart + 0 0% 100% 513kB 13.90% runtime.mstart0 + 0 0% 100% 513kB 13.90% runtime.mstart1 + 0 0% 100% 513kB 13.90% runtime.newm + 0 0% 100% 513kB 13.90% runtime.newobject + 0 0% 100% 513kB 13.90% runtime.resetspinning + 0 0% 100% 513kB 13.90% runtime.schedule + 0 0% 100% 513kB 13.90% runtime.startm + 0 0% 100% 513kB 13.90% runtime.wakep + 0 0% 100% 2136.21kB 57.88% runtime/pprof.(*profileBuilder).appendLocsForStack + 0 0% 100% 2136.21kB 57.88% runtime/pprof.(*profileBuilder).build + 0 0% 100% 2136.21kB 57.88% runtime/pprof.(*profileBuilder).emitLocation + 0 0% 100% 2136.21kB 57.88% runtime/pprof.(*profileBuilder).flush + 0 0% 100% 2136.21kB 57.88% runtime/pprof.profileWriter + 0 0% 100% 513.69kB 13.92% sync.(*Once).Do + 0 0% 100% 513.69kB 13.92% sync.(*Once).doSlow + 0 0% 100% 528.17kB 14.31% sync.(*Pool).Get + 0 0% 100% 513.69kB 13.92% syscall.Getenv + 0 0% 100% 513.69kB 13.92% syscall.init.OnceFunc.func3 + 0 0% 100% 513.69kB 13.92% syscall.init.OnceFunc.func3.1 diff --git a/docs/profiles/heap.prof b/docs/profiles/heap.prof new file mode 100644 index 0000000..b93cdc6 Binary files /dev/null and b/docs/profiles/heap.prof differ diff --git a/docs/profiling.md b/docs/profiling.md new file mode 100644 index 0000000..d087a40 --- /dev/null +++ b/docs/profiling.md @@ -0,0 +1,156 @@ +# Profiling + +This document shows where GoBalancer spends CPU time and heap memory under load, using Go's built-in `pprof` profiler. + +The profiling results complement the [benchmarks](benchmark.md): + +- **Benchmarks** measure *how much*: latency, throughput, memory, and scaling. +- **Profiling** investigates *why*: which functions consume CPU, where memory is retained, and what goroutines are doing. + +## How to reproduce + +GoBalancer exposes pprof on a separate, localhost-only debug port. Profiling is disabled by default and enabled with the `-debug-addr` flag. + +To capture the complete profile set: + +```bash +bash test/bench/profile.sh +``` + +The script starts two backends and the balancer (with `-debug-addr 127.0.0.1:6060`), drives constant load, and saves three profiles plus their `-top` summaries into `docs/profiles/`: + +- `cpu.prof` — a 30-second CPU profile taken while under load +- `heap.prof` — a snapshot of live memory +- `goroutine.prof` — a snapshot of every goroutine + +Profiles can be inspected with: `go tool pprof -top bin/gobalancer docs/profiles/cpu.prof`, or `go tool pprof -http=:8081 bin/gobalancer docs/profiles/cpu.prof` for a flame graph. + +## Environment + +Same machine as the benchmarks: + +``` +cpu: 13th Gen Intel(R) Core(TM) i5-13420H +cores: 12 +go: go1.26.5 +``` + +The workload was approximately 3,000 requests/second through the L7 proxy, with two fast backends configured with a 0 ms delay. + +--- + +## CPU — where the time goes + +**What it measures.** During CPU profiling, pprof periodically samples the function currently executing on the CPU. Functions with more samples account for more CPU time. + +Two measurements are useful: +- Flat time — time spent directly inside the function itself. +- Cumulative time — time spent in the function plus functions it calls. + +**Result.** During the 30-second capture, GoBalancer consumed approximately 25.8 CPU-seconds, equivalent to about 0.86 of one CPU core on average. + +The largest flat CPU consumers were: + +| function (flat) | self-time | +|-----------------|----------:| +| `syscall.Syscall6` (socket read/write) | 24.0% | +| `runtime.futex` (scheduler wakeups) | 9.5% | +| everything else | < 2% each | + +Grouped by area (cumulative time): + +| area | cum | functions | +|------|----:|-----------| +| socket writes / reads | 15% / 5% | `syscall.write`, `syscall.read` | +| flushing responses | 17% | `bufio.(*Writer).Flush` | +| goroutine scheduling | ~24% | `findRunnable`, `schedule`, `futex` | +| allocation + GC | ~10% | `mallocgc`, `newobject`, `gcBgMarkWorker` | +| HTTP header parsing | ~4% | `readMIMEHeader`, `CanonicalMIMEHeaderKey` | +| body copy | ~2.5% | `io.copyBuffer`, `memmove` | + +GoBalancer's own functions appear prominently in cumulative time: +- ServeHTTP — 17% +- forwardOnce — 16% + +However, their flat CPU time is very small: +- ServeHTTP — 0.16% +- forwardOnce — 0.31% + + +### What it proves. +The CPU profile has the expected signature for a proxy: a large portion of CPU time is spent in socket I/O and goroutine scheduling, rather than in application-level computation. + +The secondary costs are: +- goroutine scheduling — the cost of coordinating many I/O-blocked goroutines +- HTTP header processing — the L7 work required to inspect and rewrite requests and responses +- allocation and garbage collection — approximately 10% of cumulative CPU time + +The proxy consumed less than one CPU core on average for the offered workload, so this particular run was not CPU-bound. + +Body copying accounts for only a small fraction of CPU time because the benchmark responses are only a few bytes. A workload with larger response bodies would be expected to shift more CPU time toward buffer copying and memory movement. + +--- + +## Memory — the live heap + +**What it measures.** A snapshot of the objects currently live on the heap, grouped by the code that allocated them. + +**Result.** Total live heap was 3.7 MB. The largest entries were the pprof endpoint's own gzip buffer (~2.1 MB) and one-time process initialization (`net/http`, `syscall`, and protobuf `init` functions). No per-request allocation site retained significant memory. + +### What it proves. +The profile shows no significant accumulation of live heap attributable to request processing in this workload. + +The largest allocation, the pprof gzip buffer, is an artifact of profiling itself: fetching a profile over HTTP causes the profile response to be compressed and temporarily allocates memory for that operation. + +Therefore, it should not be interpreted as normal GoBalancer workload memory. + +The result is also consistent with the E2 connection-scaling benchmark, which showed that 10,000 live connections remained below 200 MB of process memory. + +--- + +## Goroutines — what they are all doing + +**What it measures.** A snapshot of every goroutine and the function it is currently sitting in. + +**Result.** +The snapshot contained 68 goroutines. + +Of these, 63 were parked in runtime.gopark, primarily waiting for I/O or synchronization. + +The goroutines mapped to expected components of the system: +- net/http.(*conn).serve — incoming client connections +- persistConn read/write loops — pooled backend connections +- 2 health-prober goroutines +- listener Accept loops for the proxy, metrics, and debug servers +- signal handling + +### What it proves. +The goroutine population is consistent with the expected architecture. The snapshot did not show an unexpected accumulation of goroutines or an obvious stuck worker population. + +The large number of parked goroutines is not itself a problem: a goroutine blocked waiting for network I/O is normally idle and consumes very little CPU. + +This provides additional evidence supporting: + +- the no-leak result from the chaos test +- the linear goroutine scaling observed in E2 + +The goroutine profile is a point-in-time snapshot, so it should be treated as supporting evidence rather than proof that a leak can never occur. + +--- + +## Verdict +For this workload, GoBalancer shows the expected profile of a healthy network proxy: + +- CPU time is dominated by socket I/O and runtime scheduling. +- The proxy uses less than one CPU core for approximately 3,000 requests/second. +- The captured live Go heap is approximately 3.7 MB. +- No significant request-related heap retention was visible. +- Goroutines correspond to expected client connections, backend connections, health - probes, and listeners. +- No unexpected goroutine accumulation was visible in the captured snapshot. +- No obvious CPU hot spot, runaway allocation, or goroutine leak was identified. + +Together with the benchmark and chaos-test results, the profile provides evidence that GoBalancer's resource usage is consistent with its intended design. + +## Limitations + +The load generator, not the proxy, was the bottleneck, so these profiles show where CPU and memory go — not GoBalancer's maximum throughput. Responses were a few bytes, which understates byte-copying relative to a large-payload workload. All traffic was loopback on one machine. diff --git a/internal/debug/server.go b/internal/debug/server.go new file mode 100644 index 0000000..62873a5 --- /dev/null +++ b/internal/debug/server.go @@ -0,0 +1,62 @@ +package debug + +import ( + "context" + "fmt" + "log/slog" + "net" + "net/http" + "net/http/pprof" + "time" +) + +// http server that mounts Go's pprof handlers +// Exposes Go's pprof profiling endpoints on private debug port. +// Bounded to localhost only , not publicly reachable + +type Server struct { + httpSrv *http.Server + ln net.Listener + log *slog.Logger +} + +func NewServer(addr string, log *slog.Logger) *Server { + mux := http.NewServeMux() + + 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) + + return &Server{ + httpSrv: &http.Server{ + Addr: addr, + Handler: mux, + ReadHeaderTimeout: 5 * time.Second, + }, + log: log, + } +} + +func (s *Server) Start() error { + ln, err := net.Listen("tcp", s.httpSrv.Addr) + if err != nil { + return fmt.Errorf("listen on %s: %w", s.httpSrv.Addr, err) + } + s.ln = ln + + go func(ln net.Listener) { + err := s.httpSrv.Serve(ln) + if err != nil && err != http.ErrServerClosed { + s.log.Error("debug server stopped unexpectedly", "err", err) + } + }(ln) + + s.log.Info("debug server listening", "addr", ln.Addr().String()) + return nil +} + +func (s *Server) ShutDown(ctx context.Context) error { + return s.httpSrv.Shutdown(ctx) +} diff --git a/test/bench/profile.sh b/test/bench/profile.sh new file mode 100644 index 0000000..5ef4641 --- /dev/null +++ b/test/bench/profile.sh @@ -0,0 +1,61 @@ +#!/usr/bin/env bash + +# Captures CPU, heap, and goroutine profiles from GoBalancer while it is under load, +# using the separate pprof debug port. Saves the raw profiles and their -top summaries +# into docs/profiles/. Not part of `make bench` -- profiling is an on-demand step. + +set -euo pipefail + +ROOT="$(cd "$(dirname "$0")/../.." && pwd)" +OUT="$ROOT/docs/profiles" +mkdir -p "$OUT" + +GOBAL="$ROOT/bin/gobalancer" +BACKEND="$ROOT/bin/testbackend" +LOADGEN="$ROOT/bin/loadgen" + +CONFIG="${CONFIG:-$ROOT/configl7.example.yaml}" +DEBUG="127.0.0.1:6060" +TARGET="http://127.0.0.1:8080/" +RATE="${RATE:-5000}" +CPU_SECONDS="${CPU_SECONDS:-30}" + +echo "building binaries..." +go build -o "$GOBAL" ./cmd/gobalancer +go build -o "$BACKEND" ./testbackend +go build -o "$LOADGEN" ./test/loadgen + +pids=() +cleanup() { for p in "${pids[@]:-}"; do kill "$p" 2>/dev/null || true; done; } +trap cleanup EXIT + +wait_up() { for _ in $(seq 1 100); do curl -s -o /dev/null "$1" && return 0; sleep 0.1; done; echo "timeout $1" >&2; exit 1; } + +# Fast (0ms) backends: keeps the proxy busy doing proxy work rather than waiting on a +# slow backend, so the CPU profile shows where the proxy itself spends time. +NAME=b1 PORT=9001 "$BACKEND" & pids+=($!) +NAME=b2 PORT=9002 "$BACKEND" & pids+=($!) +wait_up "http://127.0.0.1:9001/health" +wait_up "http://127.0.0.1:9002/health" + +# Balancer with the pprof debug port enabled. +"$GOBAL" run -c "$CONFIG" -debug-addr "$DEBUG" -log-level error >/dev/null 2>&1 & pids+=($!) +wait_up "http://$DEBUG/debug/pprof/" +wait_up "$TARGET" + +# Drive load long enough to cover the CPU capture plus the two snapshots. +LOAD_SECONDS=$((CPU_SECONDS + 15)) +"$LOADGEN" -target "$TARGET" -rate "$RATE" -duration "${LOAD_SECONDS}s" -out /dev/null >/dev/null 2>&1 & pids+=($!) +sleep 3 # warm up + +echo "capturing profiles (cpu = ${CPU_SECONDS}s under load)..." +curl -s "http://$DEBUG/debug/pprof/profile?seconds=$CPU_SECONDS" > "$OUT/cpu.prof" +curl -s "http://$DEBUG/debug/pprof/heap" > "$OUT/heap.prof" +curl -s "http://$DEBUG/debug/pprof/goroutine" > "$OUT/goroutine.prof" + +echo "writing -top summaries..." +go tool pprof -top "$GOBAL" "$OUT/cpu.prof" > "$OUT/cpu-top.txt" +go tool pprof -top "$GOBAL" "$OUT/heap.prof" > "$OUT/heap-top.txt" +go tool pprof -top "$GOBAL" "$OUT/goroutine.prof" > "$OUT/goroutine-top.txt" + +echo "done. raw profiles and -top summaries are in docs/profiles/"