From d63c7f360ed772b060529df85db7a91ed8efe8fb Mon Sep 17 00:00:00 2001 From: mhenrixon Date: Wed, 29 Jul 2026 16:06:44 +0200 Subject: [PATCH] perf(health-check): retry quickly until a target first answers Cuts the scale-to-zero cold wake from 1154ms to 278ms, measured end to end against a real Docker daemon on the same machine. #19 asked for a cold-wake number before optimising anything, and the number turned out to indict our own code rather than the container runtime. Waking a container whose app was ready almost immediately took 1154ms, of which docker start was only ~215ms. The proxy log showed where the rest went: 15:52:44.733 Healthcheck failed ... connection refused 15:52:45.742 Target health updated ... healthy 15:52:45.743 Service awake `docker start` returns when the container process is created, not when the application is accepting connections, so the immediate probe is routinely refused. The next probe then came a full check interval later. The wake was quantised to the health check interval -- roughly a second of pure waiting, for nothing. The health check now probes immediately, retries from 50ms doubling up to the configured interval until the target first answers, and settles to the configured interval after that. A running target is probed no harder than before, and a container that never comes up backs off rather than spinning. Deploys pay the same tax and get the same benefit: waiting for a new target to become healthy is the same wait. Also fixes a -race flake in TestService_CacheMissWakesASleepingService, which landed with #66. A wake persists state from its own goroutine, and Dispose does not wait for a write already in flight, so the test could race t.TempDir cleanup and fail with "directory not empty". The cleanup now takes saveLock, which returns only once any in-progress save has finished. Closes #59 --- internal/server/health_check.go | 48 ++++++- internal/server/health_check_backoff_test.go | 144 +++++++++++++++++++ internal/server/router_idle_test.go | 6 + 3 files changed, 194 insertions(+), 4 deletions(-) create mode 100644 internal/server/health_check_backoff_test.go diff --git a/internal/server/health_check.go b/internal/server/health_check.go index 59eeba30..6f333dc0 100644 --- a/internal/server/health_check.go +++ b/internal/server/health_check.go @@ -8,6 +8,7 @@ import ( "log/slog" "net/http" "net/url" + "sync/atomic" "time" ) @@ -24,6 +25,11 @@ type HealthCheckConsumer interface { HealthCheckCompleted(success bool) } +// initialHealthCheckDelay is where the retry starts before doubling toward the +// configured interval. Small enough that a container which is listening almost +// immediately is noticed almost immediately. +const initialHealthCheckDelay = 50 * time.Millisecond + type HealthCheck struct { consumer HealthCheckConsumer endpoint *url.URL @@ -33,6 +39,10 @@ type HealthCheck struct { ctx context.Context cancel context.CancelFunc + + // becameHealthy latches on the first successful probe. Until then the retry + // runs on a short backoff; afterwards the configured interval governs. + becameHealthy atomic.Bool } func NewHealthCheck(consumer HealthCheckConsumer, endpoint *url.URL, interval time.Duration, timeout time.Duration, host string) *HealthCheck { @@ -59,22 +69,50 @@ func (hc *HealthCheck) Close() { // Private +// run probes immediately, then retries on a short backoff until the target first +// answers, and only then settles to the configured interval. +// +// The backoff exists because a target is routinely not listening yet at the +// moment we first look: `docker start` returns when the container process is +// created, not when the application is accepting connections. Measured on a real +// daemon, the immediate probe was refused and the next one came a full interval +// later -- 1009ms of pure waiting inside a 1154ms cold wake, for a container +// whose app was ready almost at once. A deploy pays the same tax. +// +// Once a target is healthy the configured interval governs, so a running target +// is not probed any harder than before. func (hc *HealthCheck) run() { - ticker := time.NewTicker(hc.interval) - defer ticker.Stop() - hc.check() + timer := time.NewTimer(hc.nextDelay(initialHealthCheckDelay)) + defer timer.Stop() + + delay := initialHealthCheckDelay + for { select { case <-hc.ctx.Done(): return - case <-ticker.C: + case <-timer.C: hc.check() + + if hc.becameHealthy.Load() { + delay = hc.interval + } else { + delay = min(delay*2, hc.interval) + } + + timer.Reset(hc.nextDelay(delay)) } } } +// nextDelay never returns more than the configured interval, so a proxy +// configured to probe quickly is not slowed down by the backoff. +func (hc *HealthCheck) nextDelay(delay time.Duration) time.Duration { + return min(delay, hc.interval) +} + func (hc *HealthCheck) check() { ctx, cancel := context.WithTimeout(hc.ctx, hc.timeout) defer cancel() @@ -117,6 +155,8 @@ func (hc *HealthCheck) check() { func (hc *HealthCheck) reportResult(success bool, err error) { if !success { slog.Info("Healthcheck failed", "url", hc.endpoint.String(), "error", err) + } else { + hc.becameHealthy.Store(true) } hc.consumer.HealthCheckCompleted(success) diff --git a/internal/server/health_check_backoff_test.go b/internal/server/health_check_backoff_test.go new file mode 100644 index 00000000..0930720e --- /dev/null +++ b/internal/server/health_check_backoff_test.go @@ -0,0 +1,144 @@ +package server + +import ( + "net/http" + "net/http/httptest" + "net/url" + "sync" + "sync/atomic" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +type recordingConsumer struct { + mu sync.Mutex + successes int + failures int + healthy chan struct{} + once sync.Once +} + +func newRecordingConsumer() *recordingConsumer { + return &recordingConsumer{healthy: make(chan struct{})} +} + +func (c *recordingConsumer) HealthCheckCompleted(success bool) { + c.mu.Lock() + if success { + c.successes++ + } else { + c.failures++ + } + c.mu.Unlock() + + if success { + c.once.Do(func() { close(c.healthy) }) + } +} + +func (c *recordingConsumer) counts() (successes, failures int) { + c.mu.Lock() + defer c.mu.Unlock() + return c.successes, c.failures +} + +// A target that is not listening the instant `docker start` returns is the normal +// case, not the exception. Before this, the immediate probe failed and the next +// one came a full interval later -- measured at 1009ms of pure waiting on a +// container whose app was ready almost immediately, which was most of a 1154ms +// cold wake. +func TestHealthCheck_RetriesQuicklyUntilTheFirstSuccess(t *testing.T) { + var ready atomic.Bool + + backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + if !ready.Load() { + // Stands in for a container whose process exists but is not listening. + w.WriteHeader(http.StatusServiceUnavailable) + return + } + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(backend.Close) + + endpoint, err := url.Parse(backend.URL) + require.NoError(t, err) + + consumer := newRecordingConsumer() + + // A one-second interval, the default. Without the backoff the first success + // could not arrive before the first tick. + hc := NewHealthCheck(consumer, endpoint, time.Second, time.Second, "") + t.Cleanup(hc.Close) + + // Ready well inside one interval, but after the immediate probe has failed. + time.Sleep(120 * time.Millisecond) + ready.Store(true) + + start := time.Now() + select { + case <-consumer.healthy: + case <-time.After(900 * time.Millisecond): + t.Fatal("readiness waited for the full check interval instead of retrying") + } + + assert.Less(t, time.Since(start), 700*time.Millisecond, + "a target that became ready must be noticed without waiting out the interval") + + _, failures := consumer.counts() + assert.Positive(t, failures, "the early probes should have failed and been retried") +} + +// Once healthy, the configured interval is what governs -- the fast cadence is +// for catching a boot, not for hammering a running target forever. +func TestHealthCheck_SettlesToTheConfiguredIntervalAfterSuccess(t *testing.T) { + var probes atomic.Int64 + + backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + probes.Add(1) + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(backend.Close) + + endpoint, err := url.Parse(backend.URL) + require.NoError(t, err) + + consumer := newRecordingConsumer() + hc := NewHealthCheck(consumer, endpoint, time.Second, time.Second, "") + t.Cleanup(hc.Close) + + <-consumer.healthy + settled := probes.Load() + + time.Sleep(400 * time.Millisecond) + + assert.LessOrEqual(t, probes.Load()-settled, int64(1), + "a healthy target must be probed at its configured interval, not the wake cadence") +} + +// A target that never comes up must not be probed in a tight loop for the whole +// wake timeout. +func TestHealthCheck_BackoffIsBoundedByTheConfiguredInterval(t *testing.T) { + var probes atomic.Int64 + + backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + probes.Add(1) + w.WriteHeader(http.StatusServiceUnavailable) + })) + t.Cleanup(backend.Close) + + endpoint, err := url.Parse(backend.URL) + require.NoError(t, err) + + hc := NewHealthCheck(newRecordingConsumer(), endpoint, 200*time.Millisecond, time.Second, "") + t.Cleanup(hc.Close) + + time.Sleep(time.Second) + + // Doubling from 50ms and capped at the 200ms interval: roughly + // 50+100+200+200+200 -- far fewer than a 50ms tight loop's 20. + assert.Less(t, probes.Load(), int64(12), + "the retry must back off rather than hammer a container that is not coming up") +} diff --git a/internal/server/router_idle_test.go b/internal/server/router_idle_test.go index 96589963..9767660c 100644 --- a/internal/server/router_idle_test.go +++ b/internal/server/router_idle_test.go @@ -26,6 +26,12 @@ func testIdleRouter(t *testing.T, lifecycle ContainerLifecycle) *Router { for _, service := range router.services.All() { service.Dispose() } + + // Dispose stops the controllers but does not wait for a persist already in + // flight. SaveState takes the same saveLock, so this returns only once any + // in-progress write has finished -- otherwise it races t.TempDir cleanup + // and fails with "directory not empty", which -race makes far more likely. + _ = router.SaveState() }) return router