diff --git a/CHANGELOG.md b/CHANGELOG.md index bc5e641..fdc6668 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,25 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Added +- **`initial_delay` no longer defaults to 5 seconds.** An unset delay now + means "probe immediately" - the old silent default made every container's + readiness gate sleep 5s before the FIRST health probe, which was the + single largest component of cold start (php-fpm listens ~50ms after + start; nginx then waited out the delay on the dependency chain). An + explicitly configured `initial_delay` is honored unchanged, and + fast-start probing (below) keeps failure semantics on the steady-state + schedule. +- **Fast-start health probing.** Until a process's first successful health + check, the monitor probes every 250ms instead of waiting the steady-state + period - php-fpm listens ~50ms after start, and losing the race against + the immediate first probe used to cost a full period (5s in the shipped + images) of container cold start. Failure semantics are unchanged: at most + one failure is counted per period (the extra discovery probes are silent), + so a never-up process is declared unhealthy on exactly the old schedule. + Restarted instances get the same fast discovery. Measured on the + php-baseimages benchmark: the dependency gate between php-fpm and nginx + dropped from ~5.0s to sub-second. + - **`fpm_tune.cpu_ceiling` and `fpm_tune.cpu_headroom`.** The embedded autotuner sizes pools to the memory budget; on CPU-bound workloads that oversubscribes the CPU and costs throughput (measured: a 2-CPU container diff --git a/internal/config/types.go b/internal/config/types.go index 12a8735..33b656d 100644 --- a/internal/config/types.go +++ b/internal/config/types.go @@ -566,9 +566,13 @@ func (c *Config) setProcessHealthCheckDefaults(proc *Process) { return } hc := proc.HealthCheck - if hc.InitialDelay == 0 { - hc.InitialDelay = 5 - } + // initial_delay deliberately has NO default: an unset delay means probing + // starts immediately, and fast-start probing (see process.HealthMonitor) + // discovers readiness within FastStartInterval while still counting + // failures at steady-state cadence. The old default of 5 silently added + // five seconds to every container's cold start - the readiness gate slept + // through the dependency chain even though php-fpm listens within ~50ms. + // An explicitly configured initial_delay is honored unchanged. if hc.Period == 0 { hc.Period = 10 } diff --git a/internal/config/types_test.go b/internal/config/types_test.go index 3462d3f..b3044cc 100644 --- a/internal/config/types_test.go +++ b/internal/config/types_test.go @@ -171,8 +171,11 @@ func TestSetDefaults(t *testing.T) { }, validate: func(t *testing.T, c *Config) { hc := c.Processes["test"].HealthCheck - if hc.InitialDelay != 5 { - t.Errorf("InitialDelay = %v, want 5", hc.InitialDelay) + // initial_delay has no default anymore: unset means probe immediately + // (fast-start probing discovers readiness; the old default of 5 added + // five silent seconds to every container cold start). + if hc.InitialDelay != 0 { + t.Errorf("InitialDelay = %v, want 0 (no default)", hc.InitialDelay) } if hc.Period != 10 { t.Errorf("Period = %v, want 10", hc.Period) diff --git a/internal/process/healthcheck.go b/internal/process/healthcheck.go index 07b1d77..d159295 100644 --- a/internal/process/healthcheck.go +++ b/internal/process/healthcheck.go @@ -178,8 +178,25 @@ type HealthMonitor struct { consecutiveSuccess int currentlyHealthy bool graceUntil time.Time // checks are skipped until this time (warmup after (re)start) + + // Fast-start probing: until the first successful check after (re)start, + // probe at FastStartInterval instead of the steady-state period. Success + // is discovered within one FastStartInterval; failures keep their exact + // steady-state timing - at most one failure is counted (and emitted) per + // period, the extra discovery probes that fail are silent. Readiness gets + // fast without changing how quickly a never-up process goes unhealthy. + // fastUntil bounds the window as a safety valve. + everSucceeded bool + fastUntil time.Time + lastCountedFail time.Time } +// FastStartInterval is the probe cadence before the first success. First +// readiness is a discovery problem, not a failure-detection problem: php-fpm +// listens ~50ms after start, and waiting a full period to notice was the +// single largest component of container cold start. +const FastStartInterval = 100 * time.Millisecond + // NewHealthMonitor creates a new health monitor func NewHealthMonitor(processName string, cfg *config.HealthCheck, log *slog.Logger) (*HealthMonitor, error) { checker, err := NewHealthChecker(cfg) @@ -216,10 +233,12 @@ func (hm *HealthMonitor) Start(ctx context.Context) <-chan HealthStatus { // Guard the send on ctx: if the consumer has already exited (its own ctx // cancelled) with a status buffered, an unguarded send on the // capacity-1 channel blocks this goroutine — and its ticker — forever. - select { - case statusCh <- status: - case <-ctx.Done(): - return + if !status.suppress { + select { + case statusCh <- status: + case <-ctx.Done(): + return + } } // A non-positive period panics time.NewTicker, and this runs in a @@ -233,24 +252,28 @@ func (hm *HealthMonitor) Start(ctx context.Context) <-chan HealthStatus { hm.logger.Warn("Health check period is not positive; using the default", "configured", hm.config.Period, "using", period) } - ticker := time.NewTicker(period) - defer ticker.Stop() + hm.armFastStart(period) + + timer := time.NewTimer(hm.nextInterval(period)) + defer timer.Stop() for { select { - case <-ticker.C: + case <-timer.C: // Skip checks during a warmup grace window (initial start or a // re-arm after a health-triggered restart), so a slow-booting // replacement isn't killed before it can come up. - if hm.inGrace() { - continue - } - status := hm.performCheck(ctx) - select { - case statusCh <- status: - case <-ctx.Done(): - return + if !hm.inGrace() { + status := hm.performCheck(ctx) + if !status.suppress { + select { + case statusCh <- status: + case <-ctx.Done(): + return + } + } } + timer.Reset(hm.nextInterval(period)) case <-ctx.Done(): return } @@ -275,6 +298,19 @@ func (hm *HealthMonitor) Rearm() { if hm.config != nil && hm.config.InitialDelay > 0 { hm.graceUntil = time.Now().Add(time.Duration(hm.config.InitialDelay) * time.Second) } + // The replacement instance gets the same fast readiness discovery the + // first instance got. + period := DefaultHealthCheckPeriod + if hm.config != nil && hm.config.Period > 0 { + period = time.Duration(hm.config.Period) * time.Second + } + threshold := 1 + if hm.config != nil && hm.config.FailureThreshold > 0 { + threshold = hm.config.FailureThreshold + } + hm.everSucceeded = false + hm.lastCountedFail = time.Time{} + hm.fastUntil = time.Now().Add(time.Duration(threshold) * period) } // inGrace reports whether the monitor is inside a warmup grace window, during @@ -285,6 +321,32 @@ func (hm *HealthMonitor) inGrace() bool { return !hm.graceUntil.IsZero() && time.Now().Before(hm.graceUntil) } +// armFastStart opens the fast-probing window for a fresh start: probes run at +// FastStartInterval until the first success, bounded by failure_threshold x +// period (when steady-state semantics would have settled the question anyway). +func (hm *HealthMonitor) armFastStart(period time.Duration) { + hm.mu.Lock() + defer hm.mu.Unlock() + threshold := 1 + if hm.config != nil && hm.config.FailureThreshold > 0 { + threshold = hm.config.FailureThreshold + } + hm.everSucceeded = false + hm.lastCountedFail = time.Time{} + hm.fastUntil = time.Now().Add(time.Duration(threshold) * period) +} + +// nextInterval picks the probe cadence: FastStartInterval inside the +// fast-start window (pre-first-success), the steady-state period otherwise. +func (hm *HealthMonitor) nextInterval(period time.Duration) time.Duration { + hm.mu.Lock() + defer hm.mu.Unlock() + if !hm.everSucceeded && time.Now().Before(hm.fastUntil) && period > FastStartInterval { + return FastStartInterval + } + return period +} + func (hm *HealthMonitor) performCheck(ctx context.Context) HealthStatus { checkCtx, cancel := context.WithTimeout(ctx, time.Duration(hm.config.Timeout)*time.Second) defer cancel() @@ -304,6 +366,21 @@ func (hm *HealthMonitor) performCheck(ctx context.Context) HealthStatus { } if err != nil { + // Inside the fast-start window, failures are throttled to steady-state + // timing: at most one is counted (and emitted) per period, so the + // extra discovery probes change nothing about failure semantics. + if !hm.everSucceeded && time.Now().Before(hm.fastUntil) { + period := DefaultHealthCheckPeriod + if hm.config != nil && hm.config.Period > 0 { + period = time.Duration(hm.config.Period) * time.Second + } + if !hm.lastCountedFail.IsZero() && time.Since(hm.lastCountedFail) < period { + hm.logger.Debug("Health check not yet passing (fast-start window)", + "error", err) + return HealthStatus{Healthy: true, LastCheckSucceeded: false, suppress: true} + } + hm.lastCountedFail = time.Now() + } // Health check failed hm.consecutiveFails++ hm.consecutiveSuccess = 0 // Reset success counter on failure @@ -334,6 +411,7 @@ func (hm *HealthMonitor) performCheck(ctx context.Context) HealthStatus { } // Health check succeeded + hm.everSucceeded = true hm.consecutiveSuccess++ hm.consecutiveFails = 0 // Reset failure counter on success @@ -366,6 +444,10 @@ func (hm *HealthMonitor) performCheck(ctx context.Context) HealthStatus { // HealthStatus represents the result of a health check type HealthStatus struct { + // suppress marks a fast-start probe whose failure was throttled (not + // counted); the monitor loop drops it instead of emitting. + suppress bool + Healthy bool // Whether process should be considered healthy (for liveness/restart decisions) LastCheckSucceeded bool // Whether the most recent health check actually succeeded (for readiness) Error error // Error from the health check, if any diff --git a/internal/process/healthcheck_faststart_test.go b/internal/process/healthcheck_faststart_test.go new file mode 100644 index 0000000..b0c7edc --- /dev/null +++ b/internal/process/healthcheck_faststart_test.go @@ -0,0 +1,69 @@ +package process + +import ( + "context" + "log/slog" + "net" + "os" + "testing" + "time" + + "github.com/cboxdk/init/internal/config" +) + +// A service that starts listening shortly after the monitor starts must be +// discovered within the fast-start cadence, not after a full period. This was +// the single largest component of container cold start: php-fpm listened 50ms +// after the immediate first probe, and readiness waited the full 5s period. +func TestHealthMonitor_FastStartDiscovery(t *testing.T) { + logger := slog.New(slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelWarn})) + + // Reserve a port, close it, and re-listen 600ms later - after the + // monitor's immediate first probe has already failed. + l, err := net.Listen("tcp", "127.0.0.1:0") + if err != nil { + t.Fatal(err) + } + addr := l.Addr().String() + _ = l.Close() + + cfg := &config.HealthCheck{ + Type: "tcp", + Address: addr, + Period: 5, + Timeout: 1, + FailureThreshold: 3, + } + monitor, err := NewHealthMonitor("fast-start", cfg, logger) + if err != nil { + t.Fatal(err) + } + + go func() { + time.Sleep(600 * time.Millisecond) + l2, err := net.Listen("tcp", addr) + if err != nil { + return + } + defer l2.Close() + time.Sleep(5 * time.Second) + }() + + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + + start := time.Now() + statusCh := monitor.Start(ctx) + for status := range statusCh { + if status.LastCheckSucceeded { + elapsed := time.Since(start) + // Old behavior: first success at ~period (5s). Fast-start must + // find it within ~600ms + a couple of probe intervals. + if elapsed > 2*time.Second { + t.Fatalf("first success took %v; fast-start should discover readiness well before the 5s period", elapsed) + } + return + } + } + t.Fatal("monitor channel closed without a successful check") +}