diff --git a/adaptive_settled_retime_bar_886_linux_test.go b/adaptive_settled_retime_bar_886_linux_test.go index 73607ef22..45cd96bb0 100644 --- a/adaptive_settled_retime_bar_886_linux_test.go +++ b/adaptive_settled_retime_bar_886_linux_test.go @@ -3,7 +3,9 @@ package celeris import ( + "runtime" "strings" + "sync" "testing" ) @@ -175,3 +177,70 @@ created by github.com/goceleris/celeris/internal/engine/iouring.(*Engine).Listen }) } } + +// TestClassifyLoopStackReadsEveryMutexWait589 (celeris#886 item 27): the +// classifier counted only a sync.(*Mutex).Lock frame. A worker parked on an +// RWMutex, or one whose Lock frame is not in the dump but whose header carries +// the wait reason, is as parked as the verbatim celeris#593 one. The stacks are +// synthetic, built on the shape of that verbatim dump. +func TestClassifyLoopStackReadsEveryMutexWait589(t *testing.T) { + loop := func(header, frames string) string { + return header + "\n" + frames + + "github.com/goceleris/celeris/internal/engine/epoll.(*Loop).run(0xc000123456, {0xdd3928, 0xc000628870})\n" + + "\t/src/internal/engine/epoll/loop.go:100 +0x1688" + } + for _, tc := range []struct { + name, stack, want string + }{ + {"Mutex frame", loop("goroutine 7 [sync.Mutex.Lock]:", "sync.(*Mutex).Lock(...)\n\t/usr/local/go/src/sync/mutex.go:46\n"), "other_Mutex_Lock"}, + {"RWMutex write lock frame", loop("goroutine 7 [sync.RWMutex.Lock]:", "sync.(*RWMutex).Lock(0xc0001)\n\t/usr/local/go/src/sync/rwmutex.go:150 +0x40\n"), "other_Mutex_Lock"}, + {"RWMutex read lock frame", loop("goroutine 7 [sync.RWMutex.RLock]:", "sync.(*RWMutex).RLock(...)\n\t/usr/local/go/src/sync/rwmutex.go:70\n"), "other_Mutex_Lock"}, + {"wait reason in the header only", loop("goroutine 7 [sync.RWMutex.RLock, locked to thread]:", ""), "other_Mutex_Lock"}, + {"Mutex wait reason in the header only", loop("goroutine 7 [sync.Mutex.Lock, 3 minutes]:", ""), "other_Mutex_Lock"}, + {"checkTimeouts on an RWMutex", loop("goroutine 7 [sync.RWMutex.RLock]:", "sync.(*RWMutex).RLock(...)\ngithub.com/goceleris/celeris/internal/engine/epoll.(*Loop).checkTimeouts(0xc0001)\n"), "checkTimeouts_detachMu_Lock"}, + } { + t.Run(tc.name, func(t *testing.T) { + if !isLoopGoroutine589(tc.stack) { + t.Fatalf("the synthetic stack is not an event loop to isLoopGoroutine589:\n%s", tc.stack) + } + got := classifyLoopStack589(tc.stack) + if got != tc.want || !mutexParked589(got) { + t.Errorf("classifyLoopStack589 = %q (parked %v), want %q (parked)", got, mutexParked589(got), tc.want) + } + }) + } + running := loop("goroutine 7 [running]:", "") + if got := classifyLoopStack589(running); mutexParked589(got) { + t.Errorf("a running loop is classified %q, parked", got) + } +} + +// TestFullStackIsNotCutAtItsFirstBuffer589: capture used one fixed 1 MiB buffer +// and read what fitted. A process with enough goroutines to overflow it lost +// the tail of the dump. Park enough goroutines to need more than 1 MiB, and +// require every one of them in the dump. +func TestFullStackIsNotCutAtItsFirstBuffer589(t *testing.T) { + stop := make(chan struct{}) + var wg sync.WaitGroup + const n = 20000 + for range n { + wg.Add(1) + go func() { defer wg.Done(); <-stop }() + } + defer func() { close(stop); wg.Wait() }() + + before := runtime.NumGoroutine() + dump := fullStack589() + after := runtime.NumGoroutine() + if len(dump) <= 1<<20 { + t.Fatalf("%d parked goroutines produced a %d byte dump, not over the 1 MiB first buffer: the test does not reach the growth", n, len(dump)) + } + headers := strings.Count(string(dump), "\ngoroutine ") + 1 + // The lower bound is what the test is for. The upper one only says the + // dump is a dump of this process, and goroutines left by an earlier test + // can exit while it is taken, so it is read on both sides of the dump. + if hi := max(before, after) + 50; headers < n || headers > hi { + t.Errorf("the dump holds %d goroutines, want at least the %d parked ones and at most %d (%d before the dump, %d after)", + headers, n, hi, before, after) + } +} diff --git a/adaptive_settled_retime_linux_test.go b/adaptive_settled_retime_linux_test.go index c6aa3648f..c644b6fa6 100644 --- a/adaptive_settled_retime_linux_test.go +++ b/adaptive_settled_retime_linux_test.go @@ -52,11 +52,28 @@ func mutexParked589(class string) bool { return class == "checkTimeouts_detachMu_Lock" || class == "other_Mutex_Lock" } +// parkedOnMutex589 reports whether a goroutine dump is a goroutine waiting for +// a sync mutex: a frame in a Lock/RLock of sync.Mutex or sync.RWMutex, or the +// wait reason in the goroutine header ("[sync.Mutex.Lock", "[sync.RWMutex.Lock", +// "[sync.RWMutex.RLock"), which survives the inlining that can hide the Lock +// frame (celeris#886 item 27). +func parkedOnMutex589(g string) bool { + for _, m := range [...]string{ + "sync.(*Mutex).Lock", "sync.(*RWMutex).Lock", "sync.(*RWMutex).RLock", + "[sync.Mutex.Lock", "[sync.RWMutex.Lock", "[sync.RWMutex.RLock", + } { + if strings.Contains(g, m) { + return true + } + } + return false +} + func classifyLoopStack589(g string) string { switch { - case strings.Contains(g, "checkTimeouts") && strings.Contains(g, "sync.(*Mutex).Lock"): + case strings.Contains(g, "checkTimeouts") && parkedOnMutex589(g): return "checkTimeouts_detachMu_Lock" - case strings.Contains(g, "sync.(*Mutex).Lock"): + case parkedOnMutex589(g): return "other_Mutex_Lock" case strings.Contains(g, "SubmitAndWait") || strings.Contains(g, "EpollWait"): return "kernel_wait" // io_uring_enter / epoll_wait: the loop is idle, not pinned @@ -86,13 +103,26 @@ func isLoopGoroutine589(g string) bool { return strings.Contains(g, "internal/engine/iouring.(*Worker).run(") || strings.Contains(g, "internal/engine/epoll.(*Loop).run(") } +// fullStack589 is the stack of every goroutine. runtime.Stack truncates +// silently when the buffer is full, and a dump cut short could lose the stack of +// the pinned worker and read as not parked, so the buffer grows until the dump +// fits (celeris#886 item 27). +func fullStack589() []byte { + buf := make([]byte, 1<<20) + for { + if n := runtime.Stack(buf, true); n < len(buf) { + return buf[:n] + } + buf = make([]byte, 2*len(buf)) + } +} + func (st *stackTally589) capture(t *testing.T) { t.Helper() - buf := make([]byte, 1<<20) - n := runtime.Stack(buf, true) + dump := fullStack589() st.captures++ parkedHere := false - for _, g := range strings.Split(string(buf[:n]), "\n\n") { + for _, g := range strings.Split(string(dump), "\n\n") { if !isLoopGoroutine589(g) { continue } @@ -610,11 +640,15 @@ func assertSettledStall589(o stall589Obs) error { // re-timed, so a settled route whose store turns slow is promoted and stops // running on the engine worker. State is asserted on both engines. The latency // observable differs by engine: epoll is judged on the ratio below, io_uring on -// the fraction of post-promotion samples that waited for the blocked Set, -// because io_uring separately pinned its worker in the timeout sweep even when -// every conn is async-dispatched (celeris#593; fixed on main by PR #604). A -// pinned worker shows that fraction at 0.3 and the fixed tree at 0, so it -// needs no reference window and is not subject to the VOID case. +// the worker's own stack (ioUringPin592): no event-loop goroutine parked on a +// mutex in a quarter or more of at least stall592PinMinCaptures captures taken +// while a /ping sat unanswered for 100 ms. io_uring needs that because it +// separately pinned its worker in the timeout sweep even when every conn is +// async-dispatched (celeris#593; fixed on main by PR #604). The stack read +// needs no reference window and is not subject to the VOID case. It replaced a +// bar on the fraction of post-promotion samples that waited for the blocked +// Set (0.3 pinned, 0 fixed), which a starved box moved as much as the pin did +// (celeris#886 item 1). // // The latency observable is RELATIVE (celeris#622). What the settled arm // claims is that a re-timed route stops costing the worker — not that a /ping @@ -1378,6 +1412,39 @@ func runStall589(t *testing.T, engName string, engType EngineType, mode stall589 return time.Since(t0), nil } + // pingWatched is pingOnce on the shape the stack watch needs: the request + // runs on its own goroutine and a 100 ms timer waits for it, and a probe + // still unanswered when the timer fires calls onStall (nil: nothing to do) + // before waiting out the answer. BOTH windows probe through it, with the + // same goroutine and the same timer per probe, so that the two medians + // differ only in the engine state they observed (celeris#622, #886 item 27); + // only the post-promotion window passes an onStall that takes the stacks. + // With CELERIS_589_FRESH the probe is pingOnce's fresh-conn one in both. + pingWatched := func(onStall func()) (time.Duration, error) { + if fresh { + return pingOnce() + } + t0 := time.Now() + done := make(chan error, 1) + go func() { done <- get589(pc, pbr, "/ping") }() + stalled := time.NewTimer(100 * time.Millisecond) + defer stalled.Stop() + select { + case err := <-done: + if err != nil { + return 0, err + } + case <-stalled.C: + if onStall != nil { + onStall() + } + if err := <-done; err != nil { + return 0, err + } + } + return time.Since(t0), nil + } + // celeris#592: the settled classification is re-opened every // adaptiveSettleTTL, the re-timed run is ~D (far over // adaptiveBlockingThreshold) and the route promotes. Wait for that — @@ -1408,7 +1475,7 @@ func runStall589(t *testing.T, engName string, engType EngineType, mode stall589 return default: } - d, err := pingOnce() + d, err := pingWatched(nil) if err != nil { select { case refErr <- err: @@ -1469,38 +1536,22 @@ func runStall589(t *testing.T, engName string, engType EngineType, mode stall589 // (stackTally589, celeris#886 item 1): 100 ms into any /ping that has not // been answered, the event-loop goroutines' stacks are classified. stackDiag := !fresh + if stackDiag { + // 100 ms into EVERY stalled /ping, classify the event-loop goroutines' + // blocking site (tallied on the STACKTALLY589 line; CELERIS_589_STACK=1 + // also dumps the first one in full). + o.stacks = &stackTally589{} + } for time.Since(winStart) < stall589Window { + var onStall func() if stackDiag { - // 100 ms into EVERY stalled /ping, classify the event-loop - // goroutines' blocking site (tallied on the STACKTALLY589 line; - // CELERIS_589_STACK=1 also dumps the first one in full). - if o.stacks == nil { - o.stacks = &stackTally589{} - } - t0 := time.Now() - done := make(chan error, 1) - go func() { done <- get589(pc, pbr, "/ping") }() - select { - case err := <-done: - if err != nil { - t.Fatalf("GET /ping during window: %v", err) - } - case <-time.After(100 * time.Millisecond): - o.stacks.capture(t) - if err := <-done; err != nil { - t.Fatalf("GET /ping during window: %v", err) - } - } - lat = append(lat, time.Since(t0)) - } else { - // The same call the reference window made (celeris#622), so the - // two medians differ only in the engine state they observed. - d, err := pingOnce() - if err != nil { - t.Fatalf("GET /ping during window: %v", err) - } - lat = append(lat, d) + onStall = func() { o.stacks.capture(t) } + } + d, err := pingWatched(onStall) + if err != nil { + t.Fatalf("GET /ping during window: %v", err) } + lat = append(lat, d) time.Sleep(stall589Spacing) } winEnd := time.Now() diff --git a/internal/adaptive/bind_wait_890_linux_test.go b/internal/adaptive/bind_wait_890_linux_test.go new file mode 100644 index 000000000..38d5819cf --- /dev/null +++ b/internal/adaptive/bind_wait_890_linux_test.go @@ -0,0 +1,82 @@ +//go:build linux + +package adaptive + +import ( + "net" + "sync/atomic" + "testing" + "time" +) + +// celeris#890 item 98: s0Bind (and newBoundAdaptiveH) gave Listen 3 s to +// publish its address and failed "adaptive engine never bound"; under CPU +// starvation that deadline was missed 1 time in 400 runs. awaitBind890 is the +// wait that replaced it; these tests drive it with a fake address source. + +func fakeAddr890() net.Addr { return &net.TCPAddr{IP: net.IPv4(127, 0, 0, 1), Port: 4242} } + +// TestAwaitBindOutwaitsTheOldThreeSeconds890: the limit the tests use is well +// past the 3 s that was missed. It pins the constant; that the wait waits is +// what the four tests below show. +func TestAwaitBindOutwaitsTheOldThreeSeconds890(t *testing.T) { + if bindLimit890 < 15*time.Second { + t.Errorf("bindLimit890 = %v, want at least 15 s (it was 3 s when the flake hit)", bindLimit890) + } +} + +func TestAwaitBindReturnsTheAddressAndHowLongItTook890(t *testing.T) { + var published atomic.Pointer[net.Addr] + go func() { + time.Sleep(120 * time.Millisecond) + a := fakeAddr890() + published.Store(&a) + }() + addr := func() net.Addr { + if p := published.Load(); p != nil { + return *p + } + return nil + } + a, took, err := awaitBind890(addr, make(chan struct{}), 10*time.Second) + if err != nil || a == nil { + t.Fatalf("awaitBind890 = %v, %v, %v for an address published after 120 ms", a, took, err) + } + if took < 100*time.Millisecond || took > 5*time.Second { + t.Errorf("took = %v, want about 120 ms", took) + } +} + +func TestAwaitBindStopsWhenListenReturns890(t *testing.T) { + ended := make(chan struct{}) + close(ended) + start := time.Now() + a, _, err := awaitBind890(func() net.Addr { return nil }, ended, 10*time.Second) + if err == nil || a != nil { + t.Fatalf("awaitBind890 = %v, %v after Listen returned, want an error", a, err) + } + if time.Since(start) > 2*time.Second { + t.Errorf("took %v to notice that Listen had returned", time.Since(start)) + } +} + +func TestAwaitBindGivesUpAtTheLimit890(t *testing.T) { + a, took, err := awaitBind890(func() net.Addr { return nil }, make(chan struct{}), 150*time.Millisecond) + if err == nil || a != nil { + t.Fatalf("awaitBind890 = %v, %v with no address, want an error at the limit", a, err) + } + if took < 150*time.Millisecond || took > 5*time.Second { + t.Errorf("took = %v, want about the 150 ms limit", took) + } +} + +// TestAwaitBindSeesAnAddressPublishedAsListenReturns890: an address that is +// there when Listen has returned is an address. +func TestAwaitBindSeesAnAddressPublishedAsListenReturns890(t *testing.T) { + ended := make(chan struct{}) + close(ended) + a, _, err := awaitBind890(fakeAddr890, ended, 10*time.Second) + if err != nil || a == nil { + t.Fatalf("awaitBind890 = %v, %v, want the address", a, err) + } +} diff --git a/internal/adaptive/controller.go b/internal/adaptive/controller.go index 8a20f2bf0..e3cdddaa6 100644 --- a/internal/adaptive/controller.go +++ b/internal/adaptive/controller.go @@ -33,7 +33,9 @@ import ( // sends to peers that had already gone away (celeris#856, see // revertErrors), per unit of work: the larger of the interval's requests // and its connection-seconds, so a streaming workload with a handful of -// requests is not read as faulty (celeris#886 item 9, see faultRate). +// requests is not read as faulty (celeris#886 item 9, see faultRate). An +// interval with fewer than minRevertFaults faults reads rate 0, so one +// stray accept error does not revert an engine (celeris#886 item 29). // // The oscillation lock (3 switches in 5 min → 5 min lock) and the post-switch // cooldown bound any residual thrash and hold io_uring after the fast snap. diff --git a/internal/adaptive/engine.go b/internal/adaptive/engine.go index acddc5b8c..73e2b6d37 100644 --- a/internal/adaptive/engine.go +++ b/internal/adaptive/engine.go @@ -16,6 +16,7 @@ import ( "github.com/goceleris/celeris/internal/engine" "github.com/goceleris/celeris/internal/engine/epoll" "github.com/goceleris/celeris/internal/engine/iouring" + "github.com/goceleris/celeris/internal/platform" "github.com/goceleris/celeris/internal/probe" "github.com/goceleris/celeris/internal/protocol/h2/stream" "github.com/goceleris/celeris/internal/resource" @@ -185,10 +186,11 @@ type Engine struct { // fast-path setup flags); require the "bundles" era (>6.10) OR the 6.1+ // fast tier (DEFER_TASKRUN + SINGLE_ISSUER + MULTISHOT_RECV + PROVIDED_BUFFERS). // - Memlock: io_uring's provided-buffer rings need locked pages per worker -// (minMemlockPerWorker). If RLIMIT_MEMLOCK can't fund the requested workers, -// io_uring caps to a fraction of them and its throughput collapses; epoll -// does not memlock buffer rings, so it keeps all workers. In that case -// io_uring is never the right engine. +// (minMemlockPerWorker). If RLIMIT_MEMLOCK can't fund the workers the +// engines will start (startedLoops: the requested count, or the shorter +// big.LITTLE plan), io_uring caps to a fraction of them and its +// throughput collapses; epoll does not memlock buffer rings, so it keeps +// all workers. In that case io_uring is never the right engine. func ioUringViable(p engine.CapabilityProfile, cfg resource.Config) bool { if !p.IOUringTier.Available() { return false @@ -198,13 +200,36 @@ func ioUringViable(p engine.CapabilityProfile, cfg resource.Config) bool { if !bundlesEra && !fastTier { return false } - wantWorkers := cfg.Resources.Resolve().Workers + // The loops the engines START, not the request: iouring.planWithinMemlock + // caps the plan, and on a big.LITTLE host the plan is shorter than the + // request (celeris#886 item 30). Comparing the request kept the engine off + // io_uring for a ceiling between the plan and the request. + wantWorkers := startedLoops(cfg.Resources.Resolve().Workers, cfg.Resources.Workers > 0) if maxW := maxWorkersForMemlock(); maxW != -1 && maxW < wantWorkers { return false } return true } +// planLoopCPUs is the platform's CPU plan, the one the sub-engines plan their +// loops from, behind a var so tests can stand in a big.LITTLE host. +var planLoopCPUs = platform.PlanWorkerCPUsFor + +// startedLoops is how many loops the engines will start for a request of +// `requested` workers (explicit: Config.Resources.Workers was set by the +// user): the length of the platform's CPU plan. On a big.LITTLE host that is +// one loop per non-little CPU, fewer than GOMAXPROCS (celeris#1036, #1049); on +// every other host it is `requested`. The plan is made without the listen +// address, so the rx-port rule that may leave a few more CPUs out is not +// applied: the count is the upper bound of what the engines start, and the +// memlock test below never says "viable" for fewer loops than they start. It +// plans on the CPU affinity of the thread that calls New, the sub-engines on +// the one that calls Listen (sched_getaffinity is per thread): they differ +// only if an application narrows the mask of one thread. +func startedLoops(requested int, explicit bool) int { + return len(planLoopCPUs(requested, explicit, "").CPUs) +} + // maxWorkersForMemlock is the io_uring memlock worker-ceiling probe behind a var // so tests can inject a low cap without mutating the process RLIMIT_MEMLOCK. var maxWorkersForMemlock = iouring.MaxWorkersForMemlock @@ -578,7 +603,7 @@ func (e *Engine) Listen(ctx context.Context) error { // but if the active sub-engine has already returned an error to errCh // (e.g. ENOMEM at io_uring_setup under low RLIMIT_MEMLOCK), surface it // immediately instead of waiting out the deadline. - deadline := time.Now().Add(listenBindDeadline) + deadline := time.Now().Add(bindDeadline()) tick := time.NewTicker(5 * time.Millisecond) defer tick.Stop() bindWait := time.NewTimer(time.Until(deadline)) @@ -622,7 +647,7 @@ bindLoop: if active.Addr() == nil { innerCancel() wg.Wait() - return fmt.Errorf("active sub-engine failed to initialize within %v deadline", listenBindDeadline) + return fmt.Errorf("active sub-engine failed to initialize within %v deadline", bindDeadline()) } // No standby to pause: only the active engine is in the SO_REUSEPORT group, @@ -1666,10 +1691,22 @@ func reusePortAddr(ln net.Listener) (string, error) { var listenGapHook func(addr string) // listenBindDeadline is how long Listen waits for the start engine to publish -// its address before it gives up. A variable only so that a test can reach -// that return without waiting out 20 s (celeris#886 item 4); nothing else -// writes it. -var listenBindDeadline = 20 * time.Second +// its address before it gives up, as a time.Duration in nanoseconds; 0 means +// defaultListenBindDeadline (read it with bindDeadline). A variable only so +// that a test can reach that return without waiting out 20 s (celeris#886 +// item 4); nothing else writes it. It is atomic because the test writes it +// while a Listen goroutine of an earlier test may still be running and reading +// it (celeris#886 item 27). +var listenBindDeadline atomic.Int64 + +const defaultListenBindDeadline = 20 * time.Second + +func bindDeadline() time.Duration { + if d := listenBindDeadline.Load(); d > 0 { + return time.Duration(d) + } + return defaultListenBindDeadline +} // releasePortHold closes the socket that has held the engine's port since New // (celeris#616), once. Safe from any goroutine: Listen and Shutdown can both diff --git a/internal/adaptive/error_rate_floor_886_linux_test.go b/internal/adaptive/error_rate_floor_886_linux_test.go new file mode 100644 index 000000000..2e3280120 --- /dev/null +++ b/internal/adaptive/error_rate_floor_886_linux_test.go @@ -0,0 +1,157 @@ +//go:build linux + +package adaptive + +import ( + "testing" + "time" + + "github.com/goceleris/celeris/internal/engine" +) + +// celeris#886 item 29 (user decision, 2026-10-25): the io_uring error-rate +// revert has a floor of 3 faults per sampling interval. Below it the interval +// reads rate 0 whatever the divisor: one stray accept error (AcceptCancelled +// counts ECONNABORTED, EINTR, ECANCELED, EBADF) in an idle second of a +// server started on io_uring used to read 1/5 = 0.2, revert, and, with +// connSwitchEnabled false on that start, never come back. The numbers below +// are the decision's, not tunables read from the code: the tests spell the +// floor as 3 so that changing it fails here. + +// TestFaultRateFloor886 is the arithmetic around the floor. +func TestFaultRateFloor886(t *testing.T) { + for _, tc := range []struct { + name string + faults uint64 + reqs uint64 + connSecs float64 + wantRate float64 + wantDenom float64 + wantRevert bool + }{ + // One stray accept error on an idle server: no request, 5 connection-seconds. + {"one fault, idle", 1, 0, 5, 0, 5, false}, + // The old faults/requests rule reverted on 1 fault in 1 to 19 requests. + {"one fault in one request", 1, 1, 1, 0, 1, false}, + {"one fault in nineteen requests", 1, 19, 1, 0, 19, false}, + {"two faults in four requests", 2, 4, 4, 0, 4, false}, + // The floor is exact: the third fault is counted again, as before. + {"three faults in four requests", 3, 4, 4, 0.75, 4, true}, + {"three faults, rate over the bar", 3, 50, 40, 0.06, 50, true}, + {"three faults, rate under the bar", 3, 100, 40, 0.03, 100, false}, + // A storm is not touched by the floor. + {"storm", 580, 3, 10, 580.0 / 10, 10, true}, + // The divisor is still reported when the floor cuts the rate. + {"two faults, connection-seconds dominate", 2, 10, 200, 0, 200, false}, + } { + t.Run(tc.name, func(t *testing.T) { + rate, denom := faultRate(tc.faults, tc.reqs, tc.connSecs) + if !near886(rate, tc.wantRate) || !near886(denom, tc.wantDenom) { + t.Errorf("faultRate(%d, %d, %v) = %v / %v, want %v / %v", + tc.faults, tc.reqs, tc.connSecs, rate, denom, tc.wantRate, tc.wantDenom) + } + if got := rate > newController(nil, nil, nil, testLogger()).errorRevertRate; got != tc.wantRevert { + t.Errorf("rate %v: revert = %v, want %v", rate, got, tc.wantRevert) + } + }) + } +} + +// TestOneStrayAcceptErrorDoesNotRevertAnIdleIOUring886 is the case of the +// issue through the sampler and the controller: an io_uring engine with a few +// idle connections, no request in the second, one accept error. The revert is +// one-way on the opt-in io_uring start, so one stray ECONNABORTED must not +// take it. +func TestOneStrayAcceptErrorDoesNotRevertAnIdleIOUring886(t *testing.T) { + base := engine.EngineMetrics{RequestCount: 1000, ActiveConnections: 5, Workers: 1} + for _, tc := range []struct { + name string + faults uint64 + wantRevert bool + }{ + {"one accept error", 1, false}, + {"two accept errors", 2, false}, + {"three accept errors", 3, true}, + } { + t.Run(tc.name, func(t *testing.T) { + revert, snap := feed886(t, testLogger(), base, func(m *engine.EngineMetrics) { + m.ErrorAcceptCancelled = tc.faults + m.ErrorCount = tc.faults + }) + if revert != tc.wantRevert { + t.Errorf("%d accept errors, 5 idle connections, no request: revert = %v, want %v (error_rate=%v over %v)", + tc.faults, revert, tc.wantRevert, snap.ErrorRate, snap.RateDenominator) + } + // The floor cuts the rate, not the evidence: the bucket still moved + // and the divisor is still the interval's. + if got := snap.ErrorDelta[1]; got != tc.faults { // errorBucketNames[1] is error_accept_cancelled + t.Errorf("ErrorDelta[error_accept_cancelled] = %d, want %d", got, tc.faults) + } + if !near886(snap.RateDenominator, 5) { + t.Errorf("RateDenominator = %v, want 5", snap.RateDenominator) + } + }) + } +} + +// TestFaultsBelowTheFloorDoNotAddUpAcrossIntervals886 pins the floor as a +// per-interval one, which is what the decision says. ONE sampler and ONE +// controller see four consecutive 1 s intervals of an idle pool of 5 +// connections: 2 faults, 2 faults, 1 fault, then 3. None of the first three +// reverts and each reads rate 0, although the first two together are 4 faults +// (and all three 5); the fourth, at the floor, reverts on its own 3. +func TestFaultsBelowTheFloorDoNotAddUpAcrossIntervals886(t *testing.T) { + iou := newMockEngine(engine.IOUring) + live := newLiveSampler(nil) + t0 := time.Now() + clk := t0 + live.clock = func() time.Time { return clk } + sampler := &lastSnapSampler{TelemetrySampler: live} + c := newController(iou, newMockEngine(engine.Epoll), sampler, testLogger()) + c.cooldown = 0 + c.loadDownRevert = false + + m := engine.EngineMetrics{RequestCount: 1000, ActiveConnections: 5, Workers: 1} + iou.SetMetrics(m) + if c.evaluate(clk, false) { + t.Fatal("the baseline tick recommended a switch") + } + var total uint64 + for i, tc := range []struct { + faults uint64 + wantRevert bool + }{{2, false}, {2, false}, {1, false}, {3, true}} { + clk = clk.Add(time.Second) + total += tc.faults + m.ErrorAcceptCancelled, m.ErrorCount = total, total + iou.SetMetrics(m) + revert := c.evaluate(clk, false) + snap := sampler.last + if revert != tc.wantRevert { + t.Errorf("interval %d (%d faults, %d in all so far): revert = %v, want %v (error_rate=%v)", + i+1, tc.faults, total, revert, tc.wantRevert, snap.ErrorRate) + } + if tc.wantRevert { + if !near886(snap.ErrorRate, 3.0/5) { + t.Errorf("interval %d: error_rate = %v, want 3/5 (the interval's own 3 faults, not the %d so far)", i+1, snap.ErrorRate, total) + } + } else if snap.ErrorRate != 0 { + t.Errorf("interval %d (%d faults): error_rate = %v, want 0", i+1, tc.faults, snap.ErrorRate) + } + } +} + +// TestFloorLeavesAStormOnAnIdlePoolReverting886: the other direction. Faults at +// the floor on a mostly idle pool whose sends all fail still revert when the +// rate is over the bar; the floor removes the cases of one and two faults in an interval and nothing else. +func TestFloorLeavesAStormOnAnIdlePoolReverting886(t *testing.T) { + base := engine.EngineMetrics{RequestCount: 1000, ActiveConnections: 40, Workers: 1} + revert, snap := feed886(t, testLogger(), base, func(m *engine.EngineMetrics) { + m.RequestCount += 10 + m.ErrorSend = 10 + m.ErrorCount = 10 + }) + if !revert || !near886(snap.ErrorRate, 10.0/40) { + t.Errorf("10 send faults on 40 connections: revert=%v error_rate=%v, want a revert at 0.25", revert, snap.ErrorRate) + } +} diff --git a/internal/adaptive/error_rate_floor_lowtraffic_886_linux_test.go b/internal/adaptive/error_rate_floor_lowtraffic_886_linux_test.go new file mode 100644 index 000000000..6e29088ab --- /dev/null +++ b/internal/adaptive/error_rate_floor_lowtraffic_886_linux_test.go @@ -0,0 +1,111 @@ +//go:build linux + +package adaptive + +import ( + "testing" + "time" + + "github.com/goceleris/celeris/internal/engine" +) + +// PIN: this test documents a CONSEQUENCE of the 3-fault floor (celeris#886 +// item 29, user decision U-14 "at least 3 faults per interval"), found in the +// review of the PR that added it. It pins today's behaviour; it is not a claim +// that the behaviour is wanted. +// +// The floor is a count per sampling interval, so a server whose traffic is low +// enough never has 3 faults in a one-second interval, however large the share +// of failing requests: with a fault ratio p over the 0.05 revert rate, a rate of +// fewer than 3/p requests a second (at most 60 a second) never reverts. On the +// opt-in io_uring start (WorkloadHint=HighConcurrency or +// CELERIS_ADAPTIVE_START=iouring, connSwitchEnabled false) the revert is the +// only switch the controller can make, so such a server stays on a failing +// io_uring. Before the floor it went back to epoll within a second. +// +// The same steady load behaves differently by interval length: the floor is a +// count and the interval after a switch spans the 30 s cooldown, so 2 faults a +// second at 2 requests a second reverts on that one long interval (60 faults +// over 60 requests) and never on the 1 s ones. +// +// If the maintainer chooses a windowed floor (3 faults accumulated over the last +// N samples, with the rate over the same window) or a floor scaled by elapsed +// time, this test and TestFaultsBelowTheFloorDoNotAddUpAcrossIntervals886 must be +// FLIPPED: the "never" rows below become reverts. Do not delete it to make a +// change pass; change the expectation, and the release note with it. + +// stormRevertInterval886 runs io_uring as the active engine on the opt-in +// start with `conns` connections, `rps` requests and `fps` engine faults +// (ErrorSend) per second for `secs` intervals of 1 s, the first one `first` +// long when it is not 0 (the counters of that interval are scaled to it). It +// returns the interval that recommended the revert, 0 for none. +func stormRevertInterval886(conns int64, rps, fps uint64, secs int, first time.Duration) int { + iou := newMockEngine(engine.IOUring) + live := newLiveSampler(nil) + clk := time.Now() + live.clock = func() time.Time { return clk } + c := newController(iou, newMockEngine(engine.Epoll), live, testLogger()) + c.cooldown = 0 + c.loadDownRevert = false + c.connSwitchEnabled = false // the opt-in io_uring start + m := engine.EngineMetrics{RequestCount: 1000, ActiveConnections: conns, Workers: 2} + iou.SetMetrics(m) + c.evaluate(clk, false) + for i := 1; i <= secs; i++ { + d, mult := time.Second, uint64(1) + if i == 1 && first > 0 { + d, mult = first, uint64(first/time.Second) + } + clk = clk.Add(d) + m.RequestCount += rps * mult + m.ErrorSend += fps * mult + m.ErrorCount += fps * mult + iou.SetMetrics(m) + if c.evaluate(clk, false) { + return i + } + } + return 0 +} + +func TestPinFloorLetsALowTrafficFailingServerStayOnIOUring886(t *testing.T) { + for _, tc := range []struct { + name string + conns int64 + rps, fps uint64 + wantAt int // interval of the revert, 0 = never in 600 s + oldReverts bool // the rule before the floor reverted at interval 1 + }{ + {"1 rps, 100% failing", 1, 1, 1, 0, true}, + {"2 rps, 100% failing", 2, 2, 2, 0, true}, + {"4 rps, 50% failing", 4, 4, 2, 0, true}, + {"10 rps, 20% failing", 10, 10, 2, 0, true}, + {"33 rps, 6% failing", 4, 33, 2, 0, true}, + // At the floor the revert is back: 3 faults a second in 10 requests. + {"10 rps, 30% failing (3 a second)", 10, 10, 3, 1, true}, + } { + t.Run(tc.name, func(t *testing.T) { + if got := stormRevertInterval886(tc.conns, tc.rps, tc.fps, 600, 0); got != tc.wantAt { + t.Errorf("reverted at interval %d of 600 (0 = never), pinned %d", got, tc.wantAt) + } + // The premise of the pin: the rate is over the revert rate, so the + // rule before the floor reverted at once. + denom := max(float64(tc.rps), float64(tc.conns)) + if old := float64(tc.fps) / denom; (old > 0.05) != tc.oldReverts { + t.Errorf("without the floor %d/%v = %v: reverts = %v, want %v", tc.fps, denom, old, old > 0.05, tc.oldReverts) + } + }) + } +} + +// TestPinFloorIsACountSoALongIntervalReverts886: the steady 2 faults a second at +// 2 requests a second that never reverts on 1 s intervals reverts on the first +// sample after a switch, one 30 s interval of 60 faults over 60 requests. +func TestPinFloorIsACountSoALongIntervalReverts886(t *testing.T) { + if got := stormRevertInterval886(2, 2, 2, 600, 0); got != 0 { + t.Errorf("1 s intervals: reverted at %d, pinned: never", got) + } + if got := stormRevertInterval886(2, 2, 2, 600, 30*time.Second); got != 1 { + t.Errorf("first interval 30 s: reverted at %d, pinned: 1", got) + } +} diff --git a/internal/adaptive/error_rate_peer_gone_856_linux_test.go b/internal/adaptive/error_rate_peer_gone_856_linux_test.go index f892b7802..740dff2c9 100644 --- a/internal/adaptive/error_rate_peer_gone_856_linux_test.go +++ b/internal/adaptive/error_rate_peer_gone_856_linux_test.go @@ -142,9 +142,12 @@ func TestPeerGoneIsSubtractedNotTheWholeErrorCount856(t *testing.T) { wantRevert bool wantRate float64 }{ - {"mostly abandonment", 500, 1, 100, false, 0.01}, + // One real fault is under the floor of minRevertFaults (celeris#886 + // item 29) and reads 0; it read 0.01 before. + {"mostly abandonment", 500, 1, 100, false, 0}, {"abandonment hides a real fault", 500, 10, 100, true, 0.10}, {"faults only", 0, 4, 100, false, 0.04}, + {"abandonment and faults at the floor", 500, 3, 100, false, 0.03}, } { t.Run(tc.name, func(t *testing.T) { revert, snap := feed856(t, func(m *engine.EngineMetrics) { diff --git a/internal/adaptive/flap_conns_per_ring_test.go b/internal/adaptive/flap_conns_per_ring_test.go index d0451495a..e82cc5f63 100644 --- a/internal/adaptive/flap_conns_per_ring_test.go +++ b/internal/adaptive/flap_conns_per_ring_test.go @@ -258,16 +258,60 @@ func s0Bind(t *testing.T, cfg resource.Config, h stream.Handler) (*Engine, strin } e.ctrl.cooldown = 0 e.FreezeSwitching() + addr, stop := listenAndAwaitBind890(t, e) + return e, addr, stop +} + +// bindLimit890 bounds how long the adaptive tests wait for Listen to publish +// the engine's address. It is a guard against a hang, not an expectation: Listen +// gives up on its own after listenBindDeadline (20 s) and returns its error, +// which listenAndAwaitBind890 reports. The 3 s it replaces was missed once in +// 400 runs at --cpus 2 with two busy loops (celeris#890 item 98) by a poll that +// may have been starved, or by a Listen that was slow: the wait now says which. +const bindLimit890 = 30 * time.Second + +// awaitBind890 polls addr every 10 ms until it is non-nil and returns it with +// the time the wait took. It stops with an error when ended is closed (Listen +// returned without binding) or limit has passed. +func awaitBind890(addr func() net.Addr, ended <-chan struct{}, limit time.Duration) (net.Addr, time.Duration, error) { + start := time.Now() + tick := time.NewTicker(10 * time.Millisecond) + defer tick.Stop() + limitC := time.NewTimer(limit) + defer limitC.Stop() + for { + if a := addr(); a != nil { + return a, time.Since(start), nil + } + select { + case <-ended: + if a := addr(); a != nil { + return a, time.Since(start), nil + } + return nil, time.Since(start), errors.New("Listen returned before the engine published an address") + case <-limitC.C: + return nil, time.Since(start), fmt.Errorf("no address after %v", limit) + case <-tick.C: + } + } +} + +// listenAndAwaitBind890 starts e.Listen, waits for the bound address (see +// awaitBind890), logs how long the bind took, and returns the address with a +// stop func that cancels Listen and joins it. It fails the test with Listen's +// own error when Listen returned first. +func listenAndAwaitBind890(t *testing.T, e *Engine) (string, func()) { + t.Helper() ctx, cancel := context.WithCancel(context.Background()) done := make(chan error, 1) - go func() { done <- e.Listen(ctx) }() - for dl := time.Now().Add(3 * time.Second); e.Addr() == nil && time.Now().Before(dl); { - time.Sleep(10 * time.Millisecond) - } - if e.Addr() == nil { + ended := make(chan struct{}) + go func() { done <- e.Listen(ctx); close(ended) }() + a, took, err := awaitBind890(e.Addr, ended, bindLimit890) + if err != nil { cancel() - <-done - t.Fatal("adaptive engine never bound") + lerr := <-done + t.Fatalf("adaptive engine never bound: %v (waited %v; Listen: %v)", err, took, lerr) } - return e, e.Addr().String(), func() { cancel(); <-done } + t.Logf("adaptive engine bound %v after Listen started", took.Round(time.Millisecond)) + return a.String(), func() { cancel(); <-done } } diff --git a/internal/adaptive/iouring_viable_loops_886_linux_test.go b/internal/adaptive/iouring_viable_loops_886_linux_test.go new file mode 100644 index 000000000..63117893f --- /dev/null +++ b/internal/adaptive/iouring_viable_loops_886_linux_test.go @@ -0,0 +1,131 @@ +//go:build linux + +package adaptive + +import ( + "runtime" + "testing" + + "github.com/goceleris/celeris/internal/engine" + "github.com/goceleris/celeris/internal/platform" + "github.com/goceleris/celeris/internal/resource" +) + +// celeris#886 item 30 (1), from PR #1049: on a big.LITTLE host the engines +// start one pinned loop per non-little CPU, 8 of 12 on msr1, fewer than the +// requested GOMAXPROCS. ioUringViable compared the REQUESTED count with the +// RLIMIT_MEMLOCK worker ceiling, so a ceiling of 8 to 11 workers kept the +// engine off io_uring although the plan needs only 8 (iouring.planWithinMemlock +// caps the plan, not the request). These tests stand in the big.LITTLE host +// with planLoopCPUs and a memlock ceiling; the real planner is covered by the +// platform package. + +// withPlan886 makes planLoopCPUs plan `loops` pinned loops whatever is asked +// (a big.LITTLE host with `loops` non-little CPUs), and records the request. +func withPlan886(t *testing.T, loops int) (gotRequested *int, gotExplicit *bool) { + t.Helper() + var req int + var explicit bool + prev := planLoopCPUs + planLoopCPUs = func(n int, exp bool, _ string) platform.CPUPlan { + req, explicit = n, exp + cpus := make([]int, loops) + for i := range cpus { + cpus[i] = i + 4 // the CPUs after four little ones + } + return platform.CPUPlan{Requested: n, CPUs: cpus, Heterogeneous: true} + } + t.Cleanup(func() { planLoopCPUs = prev }) + return &req, &explicit +} + +// withGOMAXPROCS886 sets GOMAXPROCS, the default worker request, for the test. +func withGOMAXPROCS886(t *testing.T, n int) { + t.Helper() + prev := runtime.GOMAXPROCS(n) + t.Cleanup(func() { runtime.GOMAXPROCS(prev) }) +} + +// TestIOUringViableCountsTheLoopsTheEnginesStart886 is the band of the issue: +// 12 requested, 8 started, a ceiling of 8 to 11. +func TestIOUringViableCountsTheLoopsTheEnginesStart886(t *testing.T) { + withGOMAXPROCS886(t, 12) + gotReq, gotExplicit := withPlan886(t, 8) + for _, tc := range []struct { + ceiling int + want bool + }{ + {-1, true}, // no ceiling + {12, true}, + {11, true}, // the band: the plan needs 8, the request was 12 + {10, true}, + {9, true}, + {8, true}, // exactly funds the 8 loops + {7, false}, + {1, false}, + } { + withMemlock(t, tc.ceiling) + if got := ioUringViable(viableProfile(), resource.Config{}); got != tc.want { + t.Errorf("memlock ceiling %d, 12 requested, 8 planned: ioUringViable = %v, want %v", tc.ceiling, got, tc.want) + } + } + if *gotReq != 12 || *gotExplicit { + t.Errorf("the plan was asked for %d workers (explicit=%v), want 12 (explicit=false): the default request is GOMAXPROCS", *gotReq, *gotExplicit) + } +} + +// TestIOUringViablePlansAUserSetWorkerCountAsExplicit886: a Config.Workers is +// planned as the engines plan it (explicit), so the plan honours it. +func TestIOUringViablePlansAUserSetWorkerCountAsExplicit886(t *testing.T) { + gotReq, gotExplicit := withPlan886(t, 10) + withMemlock(t, 10) + cfg := resource.Config{Resources: resource.Resources{Workers: 10}} + if !ioUringViable(viableProfile(), cfg) { + t.Error("10 workers planned, ceiling 10: not viable") + } + if *gotReq != 10 || !*gotExplicit { + t.Errorf("the plan was asked for %d workers (explicit=%v), want 10 (explicit=true)", *gotReq, *gotExplicit) + } + withMemlock(t, 9) + if ioUringViable(viableProfile(), cfg) { + t.Error("10 workers planned, ceiling 9: viable") + } +} + +// TestChooseStartEngineUsesThePlannedLoops886 is the user-visible side: the +// WorkloadHint=HighConcurrency start on io_uring, which a ceiling inside the +// band took away from a big.LITTLE host. +func TestChooseStartEngineUsesThePlannedLoops886(t *testing.T) { + t.Setenv("CELERIS_ADAPTIVE_START", "") + withGOMAXPROCS886(t, 12) + withPlan886(t, 8) + withMemlock(t, 10) + cfg := resource.Config{Protocol: engine.HTTP1, Resources: resource.Resources{WorkloadHint: resource.WorkloadHighConcurrency}} + if got := chooseStartEngine(viableProfile(), cfg); got != engine.IOUring { + t.Errorf("chooseStartEngine = %v on a host that plans 8 loops under a ceiling of 10, want io_uring", got) + } +} + +// TestIOUringViableOnAHostOfAlikeCPUsIsUnchanged886: where the plan is as long +// as the request (every host measured but the big.LITTLE ones), nothing moves. +func TestIOUringViableOnAHostOfAlikeCPUsIsUnchanged886(t *testing.T) { + withGOMAXPROCS886(t, 6) + prev := planLoopCPUs + t.Cleanup(func() { planLoopCPUs = prev }) + planLoopCPUs = func(n int, exp bool, addr string) platform.CPUPlan { + cpus := make([]int, n) + for i := range cpus { + cpus[i] = i + } + return platform.CPUPlan{Requested: n, CPUs: cpus} + } + for _, tc := range []struct { + ceiling int + want bool + }{{-1, true}, {6, true}, {5, false}} { + withMemlock(t, tc.ceiling) + if got := ioUringViable(viableProfile(), resource.Config{}); got != tc.want { + t.Errorf("ceiling %d, 6 requested and planned: ioUringViable = %v, want %v", tc.ceiling, got, tc.want) + } + } +} diff --git a/internal/adaptive/metrics_workers_sum_886_linux_test.go b/internal/adaptive/metrics_workers_sum_886_linux_test.go new file mode 100644 index 000000000..00a672233 --- /dev/null +++ b/internal/adaptive/metrics_workers_sum_886_linux_test.go @@ -0,0 +1,66 @@ +//go:build linux + +package adaptive + +import ( + "testing" + "time" + + "github.com/goceleris/celeris/internal/engine" +) + +// celeris#886 item 31 (from PR #1062): on a big.LITTLE host the two +// sub-engines can start different numbers of loops (PR #1062's NIC interrupt +// placement can add one or two pinned loops to one of them), and the only test +// of Metrics().Workers summed 12 + 12. + +// TestMetricsWorkersSumsUnequalSubEngines886: 8 loops on epoll and 10 on +// io_uring (8 plus two extra pinned loops) are 18, the divisor that matches the +// summed ActiveConnections; a standby that has not been built yet adds none. +func TestMetricsWorkersSumsUnequalSubEngines886(t *testing.T) { + e, _ := newAdaptiveStartingOnEpoll(t) + e.primary.(*mockEngine).SetMetrics(engine.EngineMetrics{Workers: 8, ActiveConnections: 96}) + e.secondary.(*mockEngine).SetMetrics(engine.EngineMetrics{Workers: 10, ActiveConnections: 30}) + + m := e.Metrics() + if m.Workers != 18 { + t.Errorf("Metrics().Workers = %d for 8 + 10 loops, want 18", m.Workers) + } + if m.ActiveConnections != 126 { + t.Errorf("Metrics().ActiveConnections = %d, want 126", m.ActiveConnections) + } + + // The lazy shape: the io_uring standby is built at the first switch. + e.slotsMu.Lock() + e.secondary = nil + e.slotsMu.Unlock() + if got := e.Metrics().Workers; got != 8 { + t.Errorf("Metrics().Workers = %d with the standby not built, want 8", got) + } +} + +// TestControllerDividesByTheActiveEnginesOwnLoops886: the controller's +// conns-per-worker is the ACTIVE engine's connections over the ACTIVE engine's +// loops, not over the adaptive sum. It is driven through ctrl.evaluate, so that +// it is the engine the controller hands to the sampler that is under test. This +// is the divisor 886 item 30 (2) asks about on a big.LITTLE host (8 loops, not +// GOMAXPROCS 12); the thresholds are not changed by this test, only the +// arithmetic is pinned. +func TestControllerDividesByTheActiveEnginesOwnLoops886(t *testing.T) { + epoll, iou := newMockEngine(engine.Epoll), newMockEngine(engine.IOUring) + epoll.SetMetrics(engine.EngineMetrics{Workers: 8, ActiveConnections: 192}) + iou.SetMetrics(engine.EngineMetrics{Workers: 10, ActiveConnections: 1000}) + sampler := &lastSnapSampler{TelemetrySampler: newLiveSampler(nil)} + c := newController(epoll, iou, sampler, testLogger()) + c.cooldown = 0 + c.evaluate(time.Now(), false) + // 192 connections are 24/worker on 8 loops, at the up-threshold. The same + // 192 connections on the 12 loops a host of alike CPUs would start are 16; + // divided by the sum of both engines' loops they would be 10.67. + if got := sampler.last.ConnsPerWorker; got != 24 { + t.Errorf("ConnsPerWorker = %v for 192 connections on 8 loops, want 24 (not 192/18 = %v)", got, 192.0/18) + } + if sampler.last.ConnsPerWorker < c.upThreshold { + t.Errorf("ConnsPerWorker %v is under the up-threshold %v", sampler.last.ConnsPerWorker, c.upThreshold) + } +} diff --git a/internal/adaptive/port_hold_early_return_616_linux_test.go b/internal/adaptive/port_hold_early_return_616_linux_test.go index b0da6d552..9f96245b1 100644 --- a/internal/adaptive/port_hold_early_return_616_linux_test.go +++ b/internal/adaptive/port_hold_early_return_616_linux_test.go @@ -27,7 +27,10 @@ import ( // error; // - "start engine fails": the start engine's Listen returns an error without // ever publishing an address, as an io_uring engine whose worker init -// failed does, and Listen takes its "sub-engine startup failed" return. +// failed does, and Listen takes its "sub-engine startup failed" return; +// - "bind deadline passes": the start engine runs but publishes no address +// within listenBindDeadline (cut to 200 ms), and Listen takes its +// "failed to initialize within" return. // // Each arm checks that the injection made Listen return early (no address // published; the explicit return of a started engine is not the one under @@ -61,14 +64,14 @@ func TestAdaptiveListenEarlyReturnReleasesHold616(t *testing.T) { wantErr: "injected standby Listen failure"}, {name: "bind deadline passes/epoll", env: "epoll", want: engine.Epoll, inject: func(e *Engine, _ context.CancelFunc) { - listenBindDeadline = 200 * time.Millisecond + listenBindDeadline.Store(int64(200 * time.Millisecond)) var silent engine.Engine = &lateBindingStandby{mockEngine: newMockEngine(engine.Epoll), listenEnded: make(chan struct{})} e.active.Store(&silent) }, wantErr: "failed to initialize within"}, } - savedDeadline := listenBindDeadline - defer func() { listenBindDeadline = savedDeadline }() + savedDeadline := listenBindDeadline.Load() + defer func() { listenBindDeadline.Store(savedDeadline) }() for _, a := range arms { t.Run(a.name, func(t *testing.T) { e, addr, _ := newGapEngine(t, a.env, a.want) @@ -85,7 +88,7 @@ func TestAdaptiveListenEarlyReturnReleasesHold616(t *testing.T) { } else { listenGapHook = func(string) { hooked = true } } - defer func() { listenGapHook = nil; listenBindDeadline = savedDeadline }() + defer func() { listenGapHook = nil; listenBindDeadline.Store(savedDeadline) }() lerr := e.Listen(ctx) listenGapHook = nil diff --git a/internal/adaptive/porthold.go b/internal/adaptive/porthold.go index d7fea305b..5c06c312c 100644 --- a/internal/adaptive/porthold.go +++ b/internal/adaptive/porthold.go @@ -154,6 +154,16 @@ func bindHold(family int, ta *net.TCPAddr, reuseAddr bool) (string, *os.File, er if err != nil { return fail("getsockname", err) } + // The bound string is built here, with its own zoneName below, and not by + // bindiag.BoundAddr (celeris#925, #986), which does the same job: bindiag + // lives at internal/engine/internal/bindiag, and Go's internal rule keeps + // it out of reach of this package (internal/adaptive is not under + // internal/engine). The rule is the same one (the zone is the interface + // name, or the number when no interface has the index, and absent for + // scope id 0); the difference is that zoneName below uses + // net.InterfaceByIndex, which bindiag avoids on the accept path. Here it + // runs once per hold, from New, never on an event loop. A change + // to the zone rule has to be made in both places. var resolved string switch b := bound.(type) { case *unix.SockaddrInet4: @@ -233,7 +243,10 @@ func zoneIndex(zone string) uint32 { } // zoneName is the inverse, as net.Listener.Addr spells it: the interface -// name, or the number when no interface has it. +// name, or the number when no interface has it. It is a copy of the rule of +// bindiag's zoneName (internal/engine/internal/bindiag, celeris#986), kept here +// because that package cannot be imported from internal/adaptive; see the +// comment at the call in bindHold. func zoneName(id uint32) string { if id == 0 { return "" diff --git a/internal/adaptive/ramp_transplant_test.go b/internal/adaptive/ramp_transplant_test.go index 900198de6..8578061b9 100644 --- a/internal/adaptive/ramp_transplant_test.go +++ b/internal/adaptive/ramp_transplant_test.go @@ -48,18 +48,8 @@ func newRampAdaptive(t *testing.T, h stream.Handler, cfg resource.Config) (*Engi afterNew886(e) } - ctx, cancel := context.WithCancel(context.Background()) - done := make(chan error, 1) - go func() { done <- e.Listen(ctx) }() - for dl := time.Now().Add(3 * time.Second); e.Addr() == nil && time.Now().Before(dl); { - time.Sleep(10 * time.Millisecond) - } - if e.Addr() == nil { - cancel() - <-done - t.Fatal("adaptive engine never bound") - } - return e, e.Addr().String(), func() { cancel(); <-done } + addr, stop := listenAndAwaitBind890(t, e) + return e, addr, stop } // errExemplarCap bounds how many DISTINCT verbatim error strings are retained diff --git a/internal/adaptive/reverse_transplant_test.go b/internal/adaptive/reverse_transplant_test.go index e617caae4..5333667af 100644 --- a/internal/adaptive/reverse_transplant_test.go +++ b/internal/adaptive/reverse_transplant_test.go @@ -60,18 +60,17 @@ func newBoundAdaptiveH(t *testing.T, h stream.Handler, async bool) (*Engine, str skipOrFailUpswitch662(t, "adaptive.New unsupported here: %v", err) } e.ctrl.cooldown = 0 - ctx, cancel := context.WithCancel(context.Background()) - done := make(chan error, 1) - go func() { done <- e.Listen(ctx) }() - for dl := time.Now().Add(3 * time.Second); e.Addr() == nil && time.Now().Before(dl); { - time.Sleep(10 * time.Millisecond) - } - if e.Addr() == nil { - cancel() - <-done - t.Fatal("adaptive engine never bound") - } - return e, e.Addr().String(), func() { cancel(); <-done } + // The callers drive every switch with ForceSwitch and put 64 keep-alive + // conns on the engine. The controller's own conns-per-worker policy must not + // add switches of its own: with 2 workers (GOMAXPROCS 2, a 2-CPU container) + // 64 conns read 32 conns/worker, over the 24 up-threshold, so the tick loop + // promoted the conns back to io_uring about 2 s after every revert to epoll + // and the tests read the wrong engine (reverse-transplant and flap tests + // failed 40 of 40 runs at --cpus 2 and passed 40 of 40 at --cpus 4, where + // 64 conns are 16/worker). The error-rate revert is independent of this flag. + e.ctrl.connSwitchEnabled = false + addr, stop := listenAndAwaitBind890(t, e) + return e, addr, stop } // driveKeepAlive opens `conns` keep-alive HTTP/1.1 connections that loop diff --git a/internal/adaptive/slots_publish_886_linux_test.go b/internal/adaptive/slots_publish_886_linux_test.go new file mode 100644 index 000000000..af53e12a6 --- /dev/null +++ b/internal/adaptive/slots_publish_886_linux_test.go @@ -0,0 +1,159 @@ +//go:build linux + +package adaptive + +import ( + "context" + "runtime" + "strings" + "sync" + "testing" + "time" + + "github.com/goceleris/celeris/internal/engine" + "github.com/goceleris/celeris/internal/resource" +) + +// celeris#886 item 26 (PR #1012 final review): Metrics reads the two sub-engine +// slots under slotsMu, a leaf lock, so performSwitch's two slot-publish blocks +// must write them under it. No test caught dropping slotsMu from the block that +// publishes the lazily built EPOLL standby (e.primary, on a server that starts +// on io_uring); dropping it from the io_uring block was caught only by the race +// detector, if a Metrics poll happened to overlap. +// +// This test needs neither -race nor an overlap. It holds slotsMu itself, runs a +// switch that has to build and publish a standby, and requires that +// performSwitch parks on the lock before it publishes or commits anything. A +// publish without the lock is not parked: the switch carries on and commits +// while the test still holds slotsMu. + +// lazySwitch886 builds the lazy shapes of New: `active` is the eager start +// engine, the other slot is nil until the first switch builds it. +func lazySwitch886(t *testing.T, startOnIOUring bool) (e *Engine, built chan struct{}) { + t.Helper() + built = make(chan struct{}) + sampler := newSyntheticSampler() + startType, standbyType := engine.Epoll, engine.IOUring + if startOnIOUring { + startType, standbyType = engine.IOUring, engine.Epoll + } + active := newMockEngine(startType) + standby := newMockEngine(standbyType) + e = &Engine{ + cfg: resource.Config{Protocol: engine.HTTP1}, + logger: testLogger(), + startType: startType, + } + if startOnIOUring { + e.secondary = active + } else { + e.primary = active + } + e.buildStandby = func() (engine.Engine, error) { + close(built) + return standby, nil + } + e.ctrl = newController(e.primary, e.secondary, sampler, e.logger) + e.ctrl.state.activeIsPrimary = !startOnIOUring + e.ctrl.cooldown = 0 + var ap engine.Engine = active + e.active.Store(&ap) + + ctx, cancel := context.WithCancel(t.Context()) + t.Cleanup(cancel) + var wg sync.WaitGroup + wg.Add(1) + t.Cleanup(wg.Done) + e.listenCtx = ctx + e.listenWG = &wg + return e, built +} + +// performSwitchParkedOnAMutex886 reports whether a goroutine is inside +// performSwitch and parked in a sync.Mutex.Lock. The test holds only slotsMu, +// so that is the lock it is parked on. +func performSwitchParkedOnAMutex886() bool { + buf := make([]byte, 1<<16) + for { + n := runtime.Stack(buf, true) + if n < len(buf) { + buf = buf[:n] + break + } + buf = make([]byte, 2*len(buf)) + } + for _, g := range strings.Split(string(buf), "\n\n") { + if strings.Contains(g, "(*Engine).performSwitch(") && + (strings.Contains(g, "sync.(*Mutex).Lock") || strings.Contains(g, "sync.(*Mutex).lockSlow") || + strings.Contains(g, "[sync.Mutex.Lock")) { + return true + } + } + return false +} + +func TestPerformSwitchPublishesTheBuiltStandbyUnderSlotsMu886(t *testing.T) { + for _, tc := range []struct { + name string + startOnIOUring bool + wantActive engine.EngineType + }{ + // e.secondary = the lazily built io_uring standby of an epoll start. + {"io_uring standby of an epoll start (secondary block)", false, engine.IOUring}, + // e.primary = the lazily built epoll standby of an io_uring start. + {"epoll standby of an io_uring start (primary block)", true, engine.Epoll}, + } { + t.Run(tc.name, func(t *testing.T) { + e, built := lazySwitch886(t, tc.startOnIOUring) + + e.slotsMu.Lock() + held := true + defer func() { + if held { + e.slotsMu.Unlock() + } + }() + done := make(chan struct{}) + go func() { defer close(done); e.performSwitch() }() + + select { + case <-built: + case <-time.After(10 * time.Second): + t.Fatal("performSwitch never built the standby") + } + // The standby is built; the switch must now park on slotsMu to + // publish it. A switch that publishes without the lock commits + // instead (active changes) and never parks. + deadline := time.Now().Add(10 * time.Second) + for !performSwitchParkedOnAMutex886() { + if now := (*e.active.Load()).Type(); now == tc.wantActive { + t.Fatalf("performSwitch built the %v standby, published it and made it active while the test held slotsMu: "+ + "the slot-publish block does not take slotsMu", tc.wantActive) + } + if time.Now().After(deadline) { + t.Fatal("performSwitch neither parked on slotsMu nor committed the switch within 10 s") + } + time.Sleep(time.Millisecond) + } + if got := (*e.active.Load()).Type(); got == tc.wantActive { + t.Fatalf("the switch to %v committed while slotsMu was held", got) + } + + e.slotsMu.Unlock() + held = false + select { + case <-done: + case <-time.After(10 * time.Second): + t.Fatal("performSwitch did not finish after slotsMu was released") + } + if got := (*e.active.Load()).Type(); got != tc.wantActive { + t.Errorf("active = %v after the switch, want %v", got, tc.wantActive) + } + // The slot is published and Metrics sees it. + if tc.startOnIOUring && e.primary == nil || !tc.startOnIOUring && e.secondary == nil { + t.Error("the built standby is in no slot after the switch") + } + e.Metrics() + }) + } +} diff --git a/internal/adaptive/telemetry.go b/internal/adaptive/telemetry.go index bee08bd41..4f149bdcf 100644 --- a/internal/adaptive/telemetry.go +++ b/internal/adaptive/telemetry.go @@ -21,7 +21,9 @@ type TelemetrySnapshot struct { // the larger of the interval's requests and its connection-seconds). It // drives the error-rate safety revert, so it is a measure of the ENGINE // failing, not of the clients leaving. It is not capped at 1: it is a - // ratio of two counters. + // ratio of two counters. It is 0 for an interval with fewer than + // minRevertFaults faults (the floor, celeris#886 item 29); ErrorDelta still + // holds what each bucket grew by. ErrorRate float64 // RateDenominator is what ErrorRate was divided by: max(requests, // ConnSeconds) of the interval, 0 on the first sample of an engine and for @@ -200,19 +202,34 @@ func connSeconds(prevActive, curActive int64, elapsed float64) float64 { // An interval with no request used to have rate 0 whatever the faults. It now // has the faults per connection-second, so faults on a stream with no new // request count. An interval with neither requests nor connections (nothing -// to divide by) is 0, and so is one whose counters fell (satSub). There is no -// floor on the faults or on the divisor: one accept error (AcceptCancelled -// counts ECONNABORTED, EINTR, ECANCELED, EBADF) in a second of fewer than 20 -// connection-seconds and no request reads above errorRevertRate, as one fault -// in one to nineteen requests did before. +// to divide by) is 0, and so is one whose counters fell (satSub). +// +// An interval with fewer than minRevertFaults faults has rate 0 as well +// (celeris#886 item 29, decided A on 2026-10-25), and the divisor is still +// returned. Without the floor one accept error (AcceptCancelled counts +// ECONNABORTED, EINTR, ECANCELED, EBADF) in a second of fewer than 20 +// connection-seconds and no request read above errorRevertRate, as one fault +// in one to nineteen requests did before, and on the opt-in io_uring start the +// revert is one-way. The floor is per interval and does not carry over: two +// faults a second for ever never revert. The divisor is not floored: idle +// connections still dilute a real rate, which is the cost of max(requests, +// connection-seconds). func faultRate(faults, reqs uint64, connSecs float64) (rate, denom float64) { denom = max(float64(reqs), connSecs) if denom <= 0 { return 0, 0 } + if faults < minRevertFaults { + return 0, denom + } return float64(faults) / denom, denom } +// minRevertFaults is the fewest faults in one sampling interval that count +// toward the error rate: with fewer, the rate is 0 (celeris#886 item 29). The +// maintainer's value, "for example 3"; not calibrated on a measurement. +const minRevertFaults = 3 + func newLiveSampler(cpuMon engine.CPUMonitor) *liveSampler { return &liveSampler{ prevMetrics: make(map[engine.EngineType]engine.EngineMetrics),