diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 71c3f2d..140813c 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -31,16 +31,23 @@ jobs: restore-keys: | ${{ runner.os }}-go- + # The recorder adapters are separate modules, so ./... stops at them - name: Download dependencies - run: go mod download + run: | + for d in . promrecorder otelrecorder examples/observability; do + (cd $d && go mod download) + done - name: Run tests - run: go test -race -v -coverprofile=coverage.out ./... + run: | + for d in . promrecorder otelrecorder; do + (cd $d && go test -race -v -coverprofile=coverage.out ./...) + done - name: Upload coverage uses: codecov/codecov-action@v4 with: - file: ./coverage.out + files: ./coverage.out,./promrecorder/coverage.out,./otelrecorder/coverage.out flags: unittests name: codecov-umbrella @@ -64,6 +71,30 @@ jobs: args: --timeout=5m only-new-issues: true + - name: Run golangci-lint (promrecorder) + uses: golangci/golangci-lint-action@v8 + with: + version: latest + args: --timeout=5m + only-new-issues: true + working-directory: promrecorder + + - name: Run golangci-lint (otelrecorder) + uses: golangci/golangci-lint-action@v8 + with: + version: latest + args: --timeout=5m + only-new-issues: true + working-directory: otelrecorder + + - name: Run golangci-lint (examples/observability) + uses: golangci/golangci-lint-action@v8 + with: + version: latest + args: --timeout=5m + only-new-issues: true + working-directory: examples/observability + benchmark: name: Benchmark runs-on: ubuntu-latest @@ -78,7 +109,10 @@ jobs: go-version: '1.25' - name: Run benchmarks - run: go test -bench=. -benchmem -benchtime=5s ./... | tee benchmark.txt + run: | + for d in . promrecorder otelrecorder; do + (cd $d && go test -bench=. -benchmem -benchtime=5s ./...) + done | tee benchmark.txt - name: Upload benchmark results uses: actions/upload-artifact@v4 diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index c18ca9f..5645d42 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -16,9 +16,9 @@ If you want to contribute, here's how to do it without making things complicated ## Pull requests 1. Fork the repo and make your branch. -2. Run the tests: `go test -race -v ./adaptivepool/`. +2. Run the tests: `make test`. The recorder adapters are separate modules, so `go test ./...` at the root doesn't cover them. 3. Check for leaks: We use goleak in every test. -4. Lint your code: `golangci-lint run ./...`. +4. Lint your code: `make lint`. 5. Submit the PR. ## Testing checklist @@ -37,3 +37,20 @@ If you want to contribute, here's how to do it without making things complicated ## Questions Just open an issue if you're unsure about something. + +## Modules and releases + +The core module has no dependency on any metrics backend. `promrecorder`, +`otelrecorder` and `examples/observability` are separate modules with their own +`go.mod`; each uses a `replace` directive to build against the core in this +checkout. Dependencies are tidied per module: `cd && go mod tidy`. + +Sub-modules are tagged with their directory as a prefix. To release: + +1. Tag the core, for example `v0.1.0`. +2. In each adapter, require that version and delete the `replace` directive: + `go get github.com/iyashjayesh/go-adaptive-pool@v0.1.0`. +3. Tag the adapters: `promrecorder/v0.1.0`, `otelrecorder/v0.1.0`. + +`examples/observability` is never imported, so it keeps its `replace` +directives and always builds against this checkout. diff --git a/Makefile b/Makefile index 4a25586..9d39aa4 100644 --- a/Makefile +++ b/Makefile @@ -1,4 +1,4 @@ -.PHONY: all build test lint bench run-http run-batch help clean +.PHONY: all build test lint bench run-http run-batch run-observability help clean # Go parameters GOCMD=go @@ -8,6 +8,14 @@ GOTEST=$(GOCMD) test GOMOD=$(GOCMD) mod GOLINT=golangci-lint +# The recorder adapters and the observability example are separate modules, +# which ./... does not enter, so each target runs in every module. +MODULES=. promrecorder otelrecorder examples/observability +TESTED_MODULES=. promrecorder otelrecorder +define each + @for d in $(1); do echo "== $$d"; (cd $$d && $(2)) || exit 1; done +endef + # Main targets all: lint build test @@ -21,25 +29,26 @@ help: @echo " bench Run all benchmarks" @echo " run-http Run the HTTP server example" @echo " run-batch Run the batch processor example" + @echo " run-observability Run the Prometheus/Grafana observability example" @echo " clean Clean build artifacts and coverage files" @echo " help Show this help message" build: @echo "Building adaptivepool..." - $(GOBUILD) ./... + $(call each,$(MODULES),$(GOBUILD) -o /dev/null ./...) test: @echo "Running tests with race detector and coverage..." - $(GOTEST) -race -v -coverprofile=coverage.out ./... - @echo "To view coverage report: go tool cover -html=coverage.out" + $(call each,$(TESTED_MODULES),$(GOTEST) -race -v -coverprofile=coverage.out ./...) + @echo "To view a coverage report: cd && go tool cover -html=coverage.out" lint: @echo "Running lint check..." - $(GOLINT) run ./... + $(call each,$(MODULES),$(GOLINT) run ./...) bench: @echo "Running benchmarks..." - $(GOTEST) -bench=. -benchmem ./... + $(call each,$(TESTED_MODULES),$(GOTEST) -bench=. -benchmem ./...) run-http: @echo "Running HTTP server example..." @@ -49,6 +58,10 @@ run-batch: @echo "Running batch processor example..." $(GOCMD) run examples/batch_processor/main.go +run-observability: + @echo "Running observability example (metrics on :2112/metrics unless ARGS sets -metrics-addr)..." + $(GOCMD) run -C examples/observability . $(ARGS) + run-1m-with: @echo "Running 1M RPS simulator WITH adaptivepool..." $(GOCMD) run examples/one_million_simulator/with_pool/main.go diff --git a/README.md b/README.md index c69ef35..f041291 100644 --- a/README.md +++ b/README.md @@ -20,7 +20,8 @@ It provides: - Bounded concurrency via a fixed-size queue - Adaptive worker lifecycle. Workers scale up and down based on queue pressure - Explicit backpressure. When the queue is full, submissions block or fail fast -- Observability via built-in Prometheus metrics +- Observability via vendor-agnostic metrics (Prometheus and OpenTelemetry recorders included), structured `slog` logs and an `OnTaskDone` hook +- Inline retries with pluggable backoff, jitter and time budgets - Safe shutdown with graceful draining and no goroutine leaks The `adaptive` behavior here is worker lifecycle adaptation, not request-level concurrency control. @@ -34,10 +35,15 @@ The `adaptive` behavior here is worker lifecycle adaptation, not request-level c - *Explicit backpressure* - When overloaded, submissions block or are rejected. The caller must handle it. - *Observability* - - Built-in Prometheus metrics: - - queue depth - - throughput - - latency + - Metrics per pool and task kind: workers (active/busy), queue depth and wait, throughput, execution time, failures by reason, retries + - No metrics dependency in the core: plug in the bundled Prometheus or OpenTelemetry recorder, or your own + - Structured `log/slog` logging with task ID, kind, status and attempts + - `OnTaskDone` hook to react to each task's outcome (dead-letter queues, tracing) + - Ready-made Grafana dashboard in [`examples/observability`](examples/observability) +- *Retries* + - Run inline on the worker (no re-queueing, no extra goroutines), zero allocations on the hot path + - Constant, linear and exponential backoff, full jitter, per-wait cap and total time budget + - `Permanent` errors, `RetryAfter` hints and per-error attempt limits - *Safe shutdown* - Graceful draining of queued jobs and clean worker shutdown with no leaks. @@ -47,6 +53,13 @@ The `adaptive` behavior here is worker lifecycle adaptation, not request-level c go get github.com/iyashjayesh/go-adaptive-pool ``` +The core has no dependency on Prometheus or OpenTelemetry. The metrics adapters are separate modules; add the one you use: + +```bash +go get github.com/iyashjayesh/go-adaptive-pool/promrecorder # Prometheus +go get github.com/iyashjayesh/go-adaptive-pool/otelrecorder # OpenTelemetry +``` + ## Quick Start ```go @@ -107,8 +120,20 @@ pool, err := adaptivepool.New( // Cooldown between scaling operations (default: 5s) adaptivepool.WithScaleCooldown(3*time.Second), - // Enable/disable metrics (default: true) - adaptivepool.WithMetricsEnabled(true), + // Name attached to logs and metrics (default: "") + adaptivepool.WithName("orders"), + + // Export metrics: promrecorder, otelrecorder or your own (default: none) + adaptivepool.WithRecorder(promrecorder.New(prometheus.DefaultRegisterer)), + + // Structured logger (default: slog.Default()) + adaptivepool.WithLogger(slog.New(slog.NewJSONHandler(os.Stdout, nil))), + + // Called once per finished task (default: none) + adaptivepool.WithOnTaskDone(func(r adaptivepool.TaskResult) { /* ... */ }), + + // Retry failed jobs (default: disabled) + adaptivepool.WithRetry(adaptivepool.RetryPolicy{MaxAttempts: 3}), ) ``` @@ -118,35 +143,89 @@ The pool enforces backpressure when the queue is full: ```go // Block until capacity is available -ctx := context.Background() -err := pool.Submit(ctx, job) +err := pool.Submit(context.Background(), job) -// Timeout after 5 seconds -ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) +// Wait at most 5 seconds for capacity +waitCtx, cancel := context.WithTimeout(context.Background(), 5*time.Second) defer cancel() -err := pool.Submit(ctx, job) -if err == adaptivepool.ErrTimeout { +err := pool.SubmitTask(waitCtx, adaptivepool.Task{ + Context: context.Background(), // the job's own context, unaffected by waitCtx + Run: job, +}) +if errors.Is(err, adaptivepool.ErrTimeout) { // Handle overload } -// Return immediately if full -ctx, cancel := context.WithTimeout(context.Background(), 0) -defer cancel() -err := pool.Submit(ctx, job) +// Don't wait at all if the queue is full +err := pool.TrySubmit(context.Background(), adaptivepool.Task{Run: job}) +if errors.Is(err, adaptivepool.ErrQueueFull) { + // Drop or handle overload +} ``` -## Metrics +The context passed to `Submit` is also the context the job runs with, so a +wait deadline on it would also cancel the job. `Task.Context` separates the +two; see [Submit context vs execution context](docs/RETRY_AND_OBSERVABILITY.md#submit-context-vs-execution-context). -Access pool metrics for observability: +## Retries + +```go +pool, _ := adaptivepool.New( + adaptivepool.WithRetry(adaptivepool.RetryPolicy{ + MaxAttempts: 5, + Backoff: adaptivepool.ExponentialBackoff{Base: 100 * time.Millisecond}, + MaxDelay: 2 * time.Second, + MaxElapsedTime: 10 * time.Second, + Jitter: true, + }), +) + +job := func(ctx context.Context) error { + if err := validate(req); err != nil { + return adaptivepool.Permanent(err) // never retried + } + return callAPI(ctx) // retried with backoff +} +``` + +See the [Retries and Observability guide](docs/RETRY_AND_OBSERVABILITY.md) for every option and its use case. + +## Observability + +Identify tasks so logs and metrics can tell them apart: + +```go +pool.SubmitTask(ctx, adaptivepool.Task{ + ID: "order-8812", // unique: logs and OnTaskDone only + Kind: "send_email", // bounded: metric label + Run: sendEmail, +}) +``` + +Export metrics through a recorder. With Prometheus, plot them with the bundled [Grafana dashboard](examples/observability): + +```go +reg := prometheus.NewRegistry() +pool, _ := adaptivepool.New( + adaptivepool.WithName("orders"), + adaptivepool.WithRecorder(promrecorder.New(reg)), +) +http.Handle("/metrics", promhttp.HandlerFor(reg, promhttp.HandlerOpts{})) +``` + +With OpenTelemetry, use `otelrecorder.New(meterProvider)` instead; any other backend needs a four-method `Recorder`. See [Metrics](docs/RETRY_AND_OBSERVABILITY.md#metrics). + +In-process metrics are always available: ```go metrics := pool.Metrics() fmt.Printf("Queue Depth: %d\n", metrics.QueueDepth()) -fmt.Printf("Active Workers: %d\n", metrics.ActiveWorkers()) -fmt.Printf("Jobs Processed: %d\n", metrics.JobsProcessed()) +fmt.Printf("Active / Busy Workers: %d / %d\n", metrics.ActiveWorkers(), metrics.BusyWorkers()) +fmt.Printf("Jobs Processed / Failed: %d / %d\n", metrics.JobsProcessed(), metrics.JobsFailed()) fmt.Printf("Jobs Rejected: %d\n", metrics.JobsRejected()) -fmt.Printf("Avg Latency: %v\n", metrics.AvgJobLatency()) +fmt.Printf("Retries: %d\n", metrics.RetryAttempts()) +fmt.Printf("Avg Latency / Queue Wait: %v / %v\n", metrics.AvgJobLatency(), metrics.AvgQueueWait()) ``` ## Graceful Shutdown @@ -165,7 +244,7 @@ Shutdown behavior: 1. Stops accepting new jobs (returns `ErrPoolShutdown`) 2. Drains in-flight jobs within timeout 3. Terminates all workers deterministically -4. Returns error if jobs were dropped +4. If the timeout expires, drops queued jobs (each reported to `OnTaskDone` with status `shutdown`) and returns a `*ShutdownError` with the count, which wraps the context error ## Examples @@ -194,6 +273,15 @@ cd examples/batch_processor go run main.go ``` +### Observability with Prometheus and Grafana + +See [examples/observability](examples/observability) for a pool under bursty load with retries, plus a Prometheus and Grafana stack with a provisioned dashboard: + +```bash +make run-observability +cd examples/observability && docker compose up # Grafana on http://localhost:3000 +``` + ## Scope and non-goals This library is intentionally narrow in scope. @@ -280,7 +368,7 @@ Producer → Submit(ctx) → Bounded Queue → Dispatcher → Adaptive Workers Key components: - **Bounded Queue**: Buffered channel with fixed capacity - **Dispatcher**: Routes jobs to workers and monitors scaling -- **Workers**: Execute jobs with panic recovery and metrics tracking +- **Workers**: Execute jobs with panic recovery, inline retries and metrics tracking - **Scaling Logic**: Adjusts worker count based on queue utilization ## Comparison with Other Libraries @@ -289,23 +377,24 @@ Key components: |---------|-----------------|------|------|----------| | Adaptive Scaling | Yes | No | Yes | No | | Explicit Backpressure | Yes | Partial | Partial | No | -| Prometheus Metrics | Yes | No | No | No | +| Prometheus / OpenTelemetry Metrics | Yes | No | No | No | | Graceful Shutdown | Yes | Yes | Yes | Yes | | Context Support | Yes | Partial | Yes | Yes | | Zero Global State | Yes | No | Yes | Yes | ## Testing -Run tests with race detector: +The repository has four Go modules (the core, `promrecorder`, `otelrecorder` and `examples/observability`), and `./...` does not cross module boundaries. `make test` runs every module with the race detector: ```bash -go test -race -v ./... +make test ``` -Run with coverage: +To test one module, run `go test` inside its directory: ```bash -go test -race -coverprofile=coverage.out ./... +go test -race -v ./... +cd promrecorder && go test -race -coverprofile=coverage.out ./... go tool cover -html=coverage.out ``` @@ -326,6 +415,7 @@ Inspired by: ## Related Documentation +- [Retries and Observability](docs/RETRY_AND_OBSERVABILITY.md) - Retry policy, logging, metrics and hooks - [Examples](examples/) - Complete working examples - [Benchmarks](.) - Performance comparisons diff --git a/backoff_test.go b/backoff_test.go new file mode 100644 index 0000000..275ff3c --- /dev/null +++ b/backoff_test.go @@ -0,0 +1,60 @@ +package adaptivepool + +import ( + "math" + "testing" + "time" + + "github.com/stretchr/testify/assert" +) + +func TestBackoffSequences(t *testing.T) { + ms := time.Millisecond + tests := []struct { + name string + backoff Backoff + want []time.Duration + }{ + {"constant", ConstantBackoff{Delay: 50 * ms}, []time.Duration{50 * ms, 50 * ms, 50 * ms}}, + {"linear", LinearBackoff{Base: 100 * ms}, []time.Duration{100 * ms, 200 * ms, 300 * ms}}, + {"exponential default multiplier", ExponentialBackoff{Base: 100 * ms}, []time.Duration{100 * ms, 150 * ms, 225 * ms}}, + {"exponential x2", ExponentialBackoff{Base: 100 * ms, Multiplier: 2}, []time.Duration{100 * ms, 200 * ms, 400 * ms}}, + {"pointer receiver", &LinearBackoff{Base: ms}, []time.Duration{ms, 2 * ms, 3 * ms}}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + for i, want := range tt.want { + assert.Equal(t, want, tt.backoff.Next(i+1), "retry %d", i+1) + } + }) + } +} + +func TestBackoffOverflowClamps(t *testing.T) { + assert.Equal(t, time.Duration(math.MaxInt64), ExponentialBackoff{Base: time.Second, Multiplier: 10}.Next(100)) + assert.Equal(t, time.Duration(math.MaxInt64), LinearBackoff{Base: time.Hour}.Next(math.MaxInt32)) +} + +func TestBackoffValidation(t *testing.T) { + invalid := []Backoff{ + ConstantBackoff{Delay: -1}, + LinearBackoff{Base: -1}, + ExponentialBackoff{Base: -1}, + ExponentialBackoff{Base: time.Second, Multiplier: 0.5}, + &ExponentialBackoff{Base: time.Second, Multiplier: 0.5}, + ExponentialBackoff{Base: time.Second, Multiplier: math.NaN()}, + ExponentialBackoff{Base: time.Second, Multiplier: math.Inf(1)}, + } + for _, b := range invalid { + _, err := New(WithRetry(RetryPolicy{MaxAttempts: 2, Backoff: b})) + assert.ErrorIs(t, err, ErrInvalidConfig, "%#v", b) + } +} + +// Regression: Base 0 with enough retries for the power to overflow made +// 0 * +Inf a NaN, which converts to a huge negative Duration on amd64. +func TestExponentialBackoffZeroBase(t *testing.T) { + for _, retry := range []int{1, 1023, 1024, 5000} { + assert.Zero(t, ExponentialBackoff{Multiplier: 2}.Next(retry), "retry %d", retry) + } +} diff --git a/backpressure_test.go b/backpressure_test.go index 6e026c9..03338a1 100644 --- a/backpressure_test.go +++ b/backpressure_test.go @@ -225,3 +225,138 @@ func TestConcurrentSubmissions(t *testing.T) { assert.Equal(t, int64(expectedJobs), pool.Metrics().JobsProcessed()) } + +// Regression: with an already-expired submit context and Task.Context set, +// SubmitTask raced the queue send against ctx.Done() and rejected about half +// of submissions at random even though the queue had space. +func TestSubmitPrefersQueueSpaceOverDoneContext(t *testing.T) { + p := newTestPool(t, WithMinWorkers(1), WithMaxWorkers(1), WithQueueSize(1000), WithLogger(discardLogger())) + + release := make(chan struct{}) + defer close(release) + task := Task{Context: context.Background(), Run: func(context.Context) error { //nolint:unparam + <-release + return nil + }} + + for i := range 1000 { + ctx, cancel := context.WithTimeout(context.Background(), 0) + err := p.SubmitTask(ctx, task) + cancel() + require.NoError(t, err, "submit %d rejected with queue space available", i) + } + + // The worker holds one job; refill its slot so the queue is full + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + require.NoError(t, p.SubmitTask(context.Background(), task)) + + // Once the queue is full, a done context rejects immediately + ctx, cancel := context.WithTimeout(context.Background(), 0) + defer cancel() + assert.ErrorIs(t, p.SubmitTask(ctx, task), ErrTimeout) +} + +// Regression: a done ctx that is also the job's context was queued, so the +// job started with a cancelled context and could still report success. +func TestSubmitRejectsDoneContextUsedAsJobContext(t *testing.T) { + rec := &fakeRecorder{} + p := newTestPool(t, WithLogger(discardLogger()), WithRecorder(rec)) + var ran atomic.Int64 + run := func(context.Context) error { ran.Add(1); return nil } //nolint:unparam + + canceled, cancel := context.WithCancel(context.Background()) + cancel() + expired, cancelExpired := context.WithTimeout(context.Background(), 0) + defer cancelExpired() + + for _, submit := range []func(context.Context) error{ + func(ctx context.Context) error { return p.Submit(ctx, run) }, + func(ctx context.Context) error { return p.SubmitTask(ctx, Task{Kind: "k", Run: run}) }, + func(ctx context.Context) error { return p.TrySubmit(ctx, Task{Kind: "k", Run: run}) }, + } { + assert.ErrorIs(t, submit(canceled), context.Canceled) + assert.ErrorIs(t, submit(expired), ErrTimeout) + } + + time.Sleep(20 * time.Millisecond) + assert.Zero(t, ran.Load(), "no job should have been queued") + assert.Equal(t, int64(6), p.Metrics().JobsRejected()) + rec.mu.Lock() + defer rec.mu.Unlock() + assert.Empty(t, rec.submitted) + assert.Equal(t, []string{ + "default/canceled", "default/timeout", "k/canceled", "k/timeout", "k/canceled", "k/timeout", + }, rec.rejected) +} + +func TestTrySubmitQueueFull(t *testing.T) { + rec := &fakeRecorder{} + p := newTestPool(t, WithMinWorkers(1), WithMaxWorkers(1), WithQueueSize(1), WithLogger(discardLogger()), WithRecorder(rec)) + + release := make(chan struct{}) + defer close(release) + block := func(context.Context) error { //nolint:unparam + <-release + return nil + } + + ctx := context.Background() + require.NoError(t, p.TrySubmit(ctx, Task{Run: block})) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + require.NoError(t, p.TrySubmit(ctx, Task{Run: block})) + + assert.ErrorIs(t, p.TrySubmit(ctx, Task{Kind: "email", Run: block}), ErrQueueFull) + assert.Equal(t, int64(1), p.Metrics().JobsRejected()) + rec.mu.Lock() + defer rec.mu.Unlock() + assert.Equal(t, []string{"email/queue_full"}, rec.rejected) +} + +func TestTrySubmitContext(t *testing.T) { + p := newTestPool(t, WithLogger(discardLogger())) + + type key struct{} + got := make(chan any, 2) + run := func(ctx context.Context) error { + got <- ctx.Value(key{}) + return nil + } + + ctx := context.WithValue(context.Background(), key{}, "submit") + require.NoError(t, p.TrySubmit(ctx, Task{Run: run})) + assert.Equal(t, "submit", <-got) + + taskCtx := context.WithValue(context.Background(), key{}, "task") + require.NoError(t, p.TrySubmit(ctx, Task{Run: run, Context: taskCtx})) + assert.Equal(t, "task", <-got) +} + +func TestTrySubmitErrors(t *testing.T) { + p, err := New(WithLogger(discardLogger())) + require.NoError(t, err) + + ctx := context.Background() + assert.ErrorIs(t, p.TrySubmit(ctx, Task{}), ErrNilJob) + require.NoError(t, p.Shutdown(ctx)) + assert.ErrorIs(t, p.TrySubmit(ctx, Task{Run: func(context.Context) error { return nil }}), ErrPoolShutdown) +} + +// Regression: ErrTimeout was a plain error, so a timed-out submission didn't +// match context.DeadlineExceeded although a cancelled one matched +// context.Canceled. +func TestErrTimeoutWrapsDeadlineExceeded(t *testing.T) { + assert.ErrorIs(t, ErrTimeout, context.DeadlineExceeded) + + p := newTestPool(t, WithLogger(discardLogger())) + ctx, cancel := context.WithTimeout(context.Background(), 0) + defer cancel() + err := p.Submit(ctx, func(context.Context) error { return nil }) + + assert.Equal(t, ErrTimeout, err, "the sentinel itself is still returned") + assert.ErrorIs(t, err, ErrTimeout) + assert.ErrorIs(t, err, context.DeadlineExceeded) + var timeout interface{ Timeout() bool } + require.ErrorAs(t, err, &timeout) + assert.True(t, timeout.Timeout(), "callers that look for a Timeout() method see it too") + assert.NotErrorIs(t, err, context.Canceled) +} diff --git a/docs/RETRY_AND_OBSERVABILITY.md b/docs/RETRY_AND_OBSERVABILITY.md new file mode 100644 index 0000000..b93df81 --- /dev/null +++ b/docs/RETRY_AND_OBSERVABILITY.md @@ -0,0 +1,832 @@ +# Retries and Observability + +This guide covers task identity, structured logging, metrics (Prometheus, +OpenTelemetry or your own backend), the `OnTaskDone` hook, and the retry engine. Each feature comes with its use case +and a code sample. + +- [Design goals](#design-goals) +- [Task identity: `SubmitTask`](#task-identity-submittask) +- [Structured logging](#structured-logging) +- [Metrics](#metrics) +- [In-process metrics](#in-process-metrics) +- [The `OnTaskDone` hook](#the-ontaskdone-hook) +- [Retries](#retries) +- [Status reference](#status-reference) +- [Grafana dashboard](#grafana-dashboard) +- [Performance](#performance) + +--- + +## Design goals + +The pool is meant to be lightweight, so every feature here follows a few rules: + +- **Everything runs inline on the worker.** Retries don't re-queue jobs and + don't start goroutines or timers in the background. +- **You only pay for what you enable.** With retries, the hook and debug + logging all turned off, the execution path costs what it did before. +- **The hot path doesn't allocate.** Successful and failed jobs run with zero + heap allocations, and so does the retry logic itself. There are two + exceptions: the `*RetryError` returned when retrying gives up, and each + backoff wait longer than zero, which creates a timer (3 allocations, 248 + bytes) through `time.After`. That wait then lasts milliseconds, so the + allocation is negligible next to it. A test enforces the zero-allocation + paths. +- **Observability can't blow up memory.** Metric labels only use bounded + values (pool name, task kind, status, rejection reason). Unique IDs only + appear in logs and in the hook. + +--- + +## Task identity: `SubmitTask` + +`Submit(ctx, job)` still works. `SubmitTask` lets you attach identity to a job: + +```go +err := pool.SubmitTask(ctx, adaptivepool.Task{ + ID: "order-8812", // unique per task: appears in logs and TaskResult only + Kind: "send_email", // task type: used as a metric label + Run: sendEmail, +}) +``` + +| Field | Use it for | Where it shows up | +|---|---|---| +| `ID` | Finding one specific task: order ID, request ID, message ID | Logs (`task_id`), `TaskResult.ID` | +| `Kind` | Grouping tasks of the same type | Metric label `kind`, logs, `TaskResult.Kind` | +| `Context` | The context the job runs with, if different from the submit context | Passed to `Run`; drives retry cancellation | + +> **Keep `Kind` bounded.** Every distinct kind creates new series in your +> metrics backend. +> Use a fixed set like `"send_email"` or `"resize_image"`, never a user ID or +> URL. Tasks without a kind are reported as `kind="default"`. + +### Submit context vs execution context + +The `ctx` passed to `Submit`/`SubmitTask` bounds **how long to wait for queue +space** under backpressure. By default it is also **the context the job runs +with**. Those are often different lifetimes: + +| You want | Use | +|---|---| +| The job to stop when the caller gives up (request-scoped work) | `Submit(ctx, job)`: one context for both | +| A bounded wait for a slot, without that deadline cancelling the job | `Task.Context` | +| The job to outlive the request that submitted it | `Task.Context: context.WithoutCancel(r.Context())` | + +```go +func handler(w http.ResponseWriter, r *http.Request) { + // Wait at most 50ms for a slot; respond 503 if the pool is saturated + submitCtx, cancel := context.WithTimeout(r.Context(), 50*time.Millisecond) + defer cancel() + + err := pool.SubmitTask(submitCtx, adaptivepool.Task{ + Kind: "send_email", + Context: context.WithoutCancel(r.Context()), // keeps trace IDs, not cancellation + Run: sendEmail, + }) + if errors.Is(err, adaptivepool.ErrTimeout) { + http.Error(w, "busy, retry later", http.StatusServiceUnavailable) + return + } + w.WriteHeader(http.StatusAccepted) +} +``` + +Without `Task.Context`, `defer cancel()` here would cancel the job as soon as +the handler returns, and the job would finish as `canceled`. + +`WithoutCancel` keeps the values (trace and request IDs) but drops the +deadline. To bound the job itself, apply the timeout inside `Run`, where the +`cancel` can be deferred: + +```go +Run: func(ctx context.Context) error { + ctx, cancel := context.WithTimeout(ctx, 30*time.Second) + defer cancel() + return sendEmail(ctx) +}, +``` + +A `ctx` that is already done is rejected up front when it is also the job's +context (`Task.Context` is nil), since the job would be cancelled before it +ran. With `Task.Context` set, `ctx` only bounds the wait, so the task is still +queued when there is room. + +To never wait, use `TrySubmit`. It returns `ErrQueueFull` when the queue has +no space, which suits best-effort work such as telemetry: + +```go +err := pool.TrySubmit(ctx, adaptivepool.Task{Kind: "track_event", Run: track}) +if errors.Is(err, adaptivepool.ErrQueueFull) { + droppedEvents.Add(1) +} +``` + +Its `ctx` is only the job's context (when `Task.Context` is nil), since there +is no wait to bound; a done one is rejected up front. + +### Submit errors + +A nil error means the task was queued; how it ends is reported later through +logs, metrics and `OnTaskDone`. Otherwise `Submit`, `SubmitTask` and +`TrySubmit` return: + +| Error | When | Rejection reason | +|---|---|---| +| `ErrNilJob` | `Run` is nil | not counted | +| `ErrPoolShutdown` | `Shutdown` has started, before or while waiting for space | `shutdown` | +| `ErrTimeout` | The submit context's deadline passed: while waiting for space, or before the call when it is also the job's context | `timeout` | +| `context.Canceled` | The submit context was cancelled: while waiting for space, or before the call when it is also the job's context | `canceled` | +| `ErrQueueFull` | `TrySubmit` only: the queue was full | `queue_full` | + +`ErrTimeout` wraps `context.DeadlineExceeded`, so `errors.Is` matches either one, +and `err == adaptivepool.ErrTimeout` still works. `Submit` and `SubmitTask` wait +for space while the queue is full, so give them a context with a deadline to +bound the wait. + +--- + +## Structured logging + +The pool logs through `log/slog`. By default it uses `slog.Default()`, which +keeps the previous behaviour of writing wherever the standard logger goes. + +```go +logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)) + +pool, _ := adaptivepool.New( + adaptivepool.WithName("orders"), // adds pool="orders" to every record + adaptivepool.WithLogger(logger), +) +``` + +| Event | Level | Message | +|---|---|---| +| Task finished with an error or panic | `ERROR` | `task failed` | +| A retry is about to wait | `DEBUG` | `retrying task` | +| `OnTaskDone` hook panicked | `ERROR` | `OnTaskDone hook panicked` | +| Scale-up | `INFO` | `scaled up` | +| Shutdown progress | `INFO`, or `WARN` when forced | `initiating pool shutdown`, ... | + +`task failed` records include `pool`, `worker`, `task_id`, `kind`, `status`, +`attempts`, `duration` and `err`, plus `stack` for panics: + +```json +{"level":"ERROR","msg":"task failed","pool":"orders","worker":4,"task_id":"send_email-42", + "kind":"send_email","status":"retries_exhausted","attempts":2,"duration":54238958, + "err":"retries exhausted after 2 attempt(s): upstream unavailable"} +``` + +**Use cases** + +- **Turn on per-retry visibility while debugging:** set the handler level to + `slog.LevelDebug`. At the default level the retry log is skipped before any + attributes are built, so it costs nothing. +- **Correlate with traces:** records are logged with the job's context, so a + handler that pulls trace or request IDs from the context will tag pool logs + automatically. +- **Silence the pool:** `adaptivepool.WithLogger(slog.New(slog.DiscardHandler))`. +- **Find failures in Grafana:** ship the logs to Loki and filter, for example + `{app="orders"} | json | status="retries_exhausted"`. + +Successful tasks are deliberately **not** logged. At high throughput, a log +line per task costs far more than a counter. Use metrics for rates and +latencies, and logs for the details of failures. + +--- + +## Metrics + +The pool doesn't depend on any metrics backend. It reports events (job +submitted, rejected, completed, workers added) to a **`Recorder`**, and you +pick how they're exported: + +| You use | Recorder | Import | +|---|---|---| +| Prometheus | `promrecorder.New(registerer)` | `github.com/iyashjayesh/go-adaptive-pool/promrecorder` | +| OpenTelemetry (and any vendor it exports to: Datadog, New Relic, Grafana Cloud, ...) | `otelrecorder.New(meterProvider)` | `github.com/iyashjayesh/go-adaptive-pool/otelrecorder` | +| Something else (StatsD, CloudWatch, expvar, ...) | your own `Recorder` | - | +| Nothing | none: the default | - | + +Without a recorder no metrics backend runs at all. The pool's own counters +behind [`Metrics()`](#in-process-metrics) are always kept. + +`WithName` is passed to the recorder, so every metric carries the pool name. +A recorder serves one pool at a time; create one per pool. + +### Prometheus + +```bash +go get github.com/iyashjayesh/go-adaptive-pool/promrecorder +``` + +```go +reg := prometheus.NewRegistry() // or prometheus.DefaultRegisterer +pool, err := adaptivepool.New( + adaptivepool.WithName("orders"), + adaptivepool.WithRecorder(promrecorder.New(reg)), +) + +http.Handle("/metrics", promhttp.HandlerFor(reg, promhttp.HandlerOpts{})) +``` + +- Collectors are registered when the pool is created and unregistered on + `Shutdown`. Pools sharing a registry need distinct names; a duplicate + makes `New` return an error. +- Gauges are evaluated when Prometheus scrapes, so they cost nothing between + scrapes. + +| Metric | Type | Labels | Answers | +|---|---|---|---| +| `adaptivepool_active_workers` | gauge | `pool` | How many workers are running? | +| `adaptivepool_busy_workers` | gauge | `pool` | How many are executing a task right now? | +| `adaptivepool_max_workers` | gauge | `pool` | What is the ceiling? (`busy ≈ max` means saturated) | +| `adaptivepool_queue_depth` | gauge | `pool` | How many tasks are waiting? | +| `adaptivepool_queue_capacity` | gauge | `pool` | How large is the queue? | +| `adaptivepool_jobs_submitted_total` | counter | `pool`, `kind` | Incoming rate by task type | +| `adaptivepool_jobs_rejected_total` | counter | `pool`, `kind`, `reason` | Overload: `timeout`, `canceled`, `queue_full` or `shutdown` | +| `adaptivepool_jobs_completed_total` | counter | `pool`, `kind`, `status` | Throughput, and why tasks failed | +| `adaptivepool_jobs_dropped_total` | counter | `pool`, `kind` | Queued tasks a forced shutdown discarded without running | +| `adaptivepool_job_duration_seconds` | histogram | `pool`, `kind` | How long tasks take, including retries | +| `adaptivepool_job_queue_wait_seconds` | histogram | `pool`, `kind` | How long tasks wait before starting | +| `adaptivepool_jobs_retried_total` | counter | `pool`, `kind` | Tasks that needed at least one retry | +| `adaptivepool_retry_attempts_total` | counter | `pool`, `kind` | Total retries | +| `adaptivepool_scale_up_events_total` | counter | `pool` | How often the pool grew | + +Names follow the Prometheus naming conventions (`promlint` reports no +problems). Once a kind has been seen, its retry counters are exported at +zero rather than appearing on the first retry. + +**Useful queries** + +```promql +# Throughput by task type +sum by (kind) (rate(adaptivepool_jobs_completed_total[1m])) + +# Failure reasons +sum by (kind, status) (rate(adaptivepool_jobs_completed_total{status!="success"}[5m])) + +# p95 execution time and queue wait +histogram_quantile(0.95, sum by (le, kind) (rate(adaptivepool_job_duration_seconds_bucket[5m]))) +histogram_quantile(0.95, sum by (le, kind) (rate(adaptivepool_job_queue_wait_seconds_bucket[5m]))) + +# Saturation (alert when this stays near 1) +adaptivepool_busy_workers / adaptivepool_max_workers +``` + +### OpenTelemetry + +```bash +go get github.com/iyashjayesh/go-adaptive-pool/otelrecorder +``` + +```go +pool, err := adaptivepool.New( + adaptivepool.WithName("orders"), + adaptivepool.WithRecorder(otelrecorder.New(meterProvider)), // nil uses otel.GetMeterProvider() +) +``` + +Names, units and attributes follow the OpenTelemetry semantic conventions, +modelled on the database connection pool metrics (`db.client.connection.*`). +Every metric carries `adaptivepool.pool.name`. + +| Metric | Instrument | Unit | Attributes | +|---|---|---|---| +| `adaptivepool.worker.count` | UpDownCounter | `{worker}` | `adaptivepool.worker.state` = `idle` or `busy` | +| `adaptivepool.worker.limit` | UpDownCounter | `{worker}` | | +| `adaptivepool.worker.min` | UpDownCounter | `{worker}` | | +| `adaptivepool.queue.usage` | UpDownCounter | `{job}` | | +| `adaptivepool.queue.limit` | UpDownCounter | `{job}` | | +| `adaptivepool.job.submissions` | Counter | `{submission}` | `adaptivepool.job.kind` | +| `adaptivepool.job.rejections` | Counter | `{rejection}` | `adaptivepool.job.kind`, `adaptivepool.rejection.reason` | +| `adaptivepool.job.dropped` | Counter | `{job}` | `adaptivepool.job.kind` | +| `adaptivepool.job.duration` | Histogram | `s` | `adaptivepool.job.kind`, `adaptivepool.job.status` | +| `adaptivepool.job.wait_time` | Histogram | `s` | `adaptivepool.job.kind` | +| `adaptivepool.job.retries` | Counter | `{retry}` | `adaptivepool.job.kind` | +| `adaptivepool.worker.scale_ups` | Counter | `{scale_up}` | | + +- Completed jobs are counted by the `job.duration` histogram (its count, by + status), as `http.server.request.duration` counts requests. There is no + separate completions counter. +- There is no equivalent of Prometheus's `jobs_retried_total`; use + `job.retries`. +- Duration histograms use the bucket boundaries the conventions recommend for + seconds (5ms to 10s). +- Recording costs about 200ns per completed job, mostly inside the + OpenTelemetry SDK, versus about 30ns for the Prometheus recorder. Neither + allocates. + +### Writing your own recorder + +Implement five methods. They run on submitting and worker goroutines, so they +must be safe for concurrent use and fast: + +```go +type statsdRecorder struct{ c *statsd.Client } + +func (r statsdRecorder) JobSubmitted(kind string) { + r.c.Incr("pool.submitted", []string{"kind:" + kind}, 1) +} +func (r statsdRecorder) JobRejected(kind string, reason adaptivepool.RejectReason) { + r.c.Incr("pool.rejected", []string{"kind:" + kind, "reason:" + string(reason)}, 1) +} +func (r statsdRecorder) JobCompleted(kind string, status adaptivepool.Status, attempts int, wait, d time.Duration) { + r.c.Timing("pool.duration", d, []string{"kind:" + kind, "status:" + string(status)}, 1) +} +func (r statsdRecorder) JobDropped(kind string) { + r.c.Incr("pool.dropped", []string{"kind:" + kind}, 1) +} +func (r statsdRecorder) ScaledUp(added int) { + r.c.Count("pool.scale_up", int64(added), nil, 1) +} + +pool, err := adaptivepool.New(adaptivepool.WithRecorder(statsdRecorder{client})) +``` + +Kinds arrive normalized: an empty kind is reported as `"default"`. A panic in +a method is recovered and logged once (later ones are ignored without logging), +so a faulty recorder can't take down a worker or a caller. + +To export gauges (queue depth, workers) or register with a backend, also +implement `Attacher`. `New` calls `Attach` with the pool's `PoolInfo` (name, +worker limits, queue size) and its live `Metrics()`, which you can read +whenever your backend collects; an error from `Attach` fails `New`. +`Shutdown` calls `Detach` once every worker has exited; the pool reports no +events after that, so the recorder can be attached to a new pool. + +### Exposing metrics over HTTP without a backend + +`pool.Metrics()` needs no recorder. To serve it as JSON, or through the +standard library's `/debug/vars`: + +```go +http.HandleFunc("/pool", func(w http.ResponseWriter, _ *http.Request) { + m := pool.Metrics() + _ = json.NewEncoder(w).Encode(map[string]any{ + "queue_depth": m.QueueDepth(), + "active_workers": m.ActiveWorkers(), + "busy_workers": m.BusyWorkers(), + "jobs_processed": m.JobsProcessed(), + "jobs_failed": m.JobsFailed(), + "avg_latency": m.AvgJobLatency().String(), + }) +}) +``` + +These are pool-wide totals and averages. For per-kind breakdowns or +histograms, use a recorder. + +--- + +## In-process metrics + +`pool.Metrics()` is always available, with or without a recorder, so +`WithMetricsEnabled` is deprecated and does nothing: exporting is opt-in through +`WithRecorder`. It's handy for health endpoints, tests and logs: + +```go +m := pool.Metrics() +m.QueueDepth() // queued tasks +m.ActiveWorkers() // running workers +m.BusyWorkers() // workers executing a task +m.JobsProcessed() // finished tasks +m.JobsFailed() // finished with any non-success status +m.JobsRejected() // rejected at submission +m.JobsDropped() // queued tasks dropped by a forced shutdown +m.JobsRetried() // needed at least one retry +m.RetryAttempts() // total retries +m.AvgJobLatency() // mean execution time, including retries +m.AvgQueueWait() // mean time spent queued +``` + +--- + +## The `OnTaskDone` hook + +`Submit` returns as soon as a task is queued, so your code otherwise has no way +to learn how a task ended. `WithOnTaskDone` is called **exactly once per +executed task**, whatever the outcome, and once per queued task a forced +shutdown drops (status `shutdown`, `Attempts` 0): + +```go +pool, _ := adaptivepool.New( + adaptivepool.WithOnTaskDone(func(r adaptivepool.TaskResult) { + if r.Err != nil { + deadLetters.Publish(r.ID, r.Kind, r.Status, r.Err) // hand off, don't block + } + }), +) +``` + +`TaskResult` contains `ID`, `Kind`, `QueueWait`, `Duration`, `Attempts`, +`Status` and `Err`. + +**Use cases** + +- Sending failed tasks to a dead-letter queue, or marking a record as failed. +- Notifying whoever submitted the task, for example by closing a per-task + channel or completing a future. +- Ending a tracing span or recording custom business metrics. + +**Rules** + +- The hook runs synchronously on the worker goroutine, and that worker can't + take another task until the hook returns. Keep it fast and hand off anything + slow. +- A panic inside the hook is recovered and logged. It never kills the worker. +- When the hook isn't set, it costs a single nil check. + +To inspect the error: + +```go +var re *adaptivepool.RetryError +if errors.As(r.Err, &re) { + log.Printf("gave up after %d attempts: %v", re.Attempts, re.Reason) +} +var pe *adaptivepool.PanicError +if errors.As(r.Err, &pe) { + log.Printf("panic: %v\n%s", pe.Value, pe.Stack) +} +``` + +--- + +## Retries + +Retries are enabled per pool with a reusable policy value: + +```go +pool, err := adaptivepool.New( + adaptivepool.WithRetry(adaptivepool.RetryPolicy{ + MaxAttempts: 5, + Backoff: adaptivepool.ExponentialBackoff{Base: 100 * time.Millisecond}, + MaxDelay: 2 * time.Second, + MaxElapsedTime: 10 * time.Second, + Jitter: true, + }), +) +``` + +**How it works** + +- A failed job is retried **on the same worker**: it waits, then runs again. + Nothing is re-queued and no goroutines or timers are left behind. +- A retrying job keeps its worker busy, so retries consume pool capacity. + Bound them with `MaxAttempts`, `MaxDelay` and `MaxElapsedTime`. +- **Every error is retried by default.** The exceptions are errors wrapped with + `Permanent`, a done job context, and panics (which are never retried). +- Only retry jobs that are **idempotent**: an attempt may have partly + succeeded before it failed. +- An invalid policy makes `New` return an error wrapping `ErrInvalidConfig`. + +### MaxAttempts (required) + +This is the total number of runs, including the first. It must be at least 1: +infinite retries aren't supported, because a permanently failing job would +hold a worker forever. + +```go +adaptivepool.RetryPolicy{MaxAttempts: 3} // first try + 2 retries +``` + +Use case: you want a predictable upper bound on how much work and worker time +a failing job can consume. + +### Backoff strategies + +`Backoff` decides how long to wait before each retry. `retry` starts at 1. + +| Strategy | Formula | Example (`100ms` base) | Use when | +|---|---|---|---| +| `ConstantBackoff{Delay}` | `Delay` | 100ms, 100ms, 100ms | Polling for a short-lived condition, such as a lock or a file appearing | +| `LinearBackoff{Base}` | `Base × retry` | 100ms, 200ms, 300ms | Contention that clears gradually | +| `ExponentialBackoff{Base, Multiplier}` | `Base × Multiplier^(retry-1)` | 100ms, 150ms, 225ms (×1.5) | Overloaded or unavailable downstream services. **This is the default** (`Base: 100ms`, `Multiplier: 1.5`) | + +```go +adaptivepool.ExponentialBackoff{Base: 50 * time.Millisecond, Multiplier: 2} // 50ms, 100ms, 200ms... +``` + +All three are stateless values: one instance is shared by every worker without +locking. Values too large for a `time.Duration` are clamped to the maximum +instead of overflowing. + +**Custom backoff.** Implement `Next(retry int) time.Duration`. It must be safe +for concurrent use. Wrapping is the way to compose strategies: + +```go +// An explicit schedule; the last step repeats +type stepped struct{ steps []time.Duration } + +func (s stepped) Next(retry int) time.Duration { + return s.steps[min(retry, len(s.steps))-1] +} + +adaptivepool.RetryPolicy{ + MaxAttempts: 6, + Backoff: stepped{[]time.Duration{100 * time.Millisecond, 100 * time.Millisecond, 200 * time.Millisecond, 300 * time.Millisecond, 500 * time.Millisecond}}, +} +``` + +### MaxDelay + +`MaxDelay` caps any single wait, including `RetryAfter` hints. Zero means no +cap. + +```go +adaptivepool.RetryPolicy{ + MaxAttempts: 10, + Backoff: adaptivepool.ExponentialBackoff{Base: 100 * time.Millisecond, Multiplier: 2}, + MaxDelay: 5 * time.Second, // 100ms, 200ms, ... 3.2s, 5s, 5s +} +``` + +Use case: you want exponential growth for the first few retries without one +late retry parking a worker for minutes. + +### Jitter (full jitter) + +With `Jitter: true`, each wait is drawn uniformly from `[0, delay)`, where +`delay` is the backoff value after `MaxDelay` is applied. This is the "full +jitter" scheme AWS recommends. + +```go +adaptivepool.RetryPolicy{MaxAttempts: 5, Jitter: true} +``` + +Use case: a downstream outage fails hundreds of jobs at the same moment. +Without jitter they all retry in lockstep and hit the recovering service +together (a thundering herd). Jitter spreads them out. + +`RetryAfter` hints are never jittered. Randomness comes from `math/rand/v2`, +which is lock-free. + +### MaxElapsedTime + +`MaxElapsedTime` is a total time budget for one job, covering all of its +attempts and waits. It works alongside `MaxAttempts`, and whichever limit is +hit first wins. + +```go +adaptivepool.RetryPolicy{ + MaxAttempts: 20, + MaxElapsedTime: 30 * time.Second, +} +``` + +- Retrying stops **as soon as the next wait would exceed the budget**, rather + than sleeping first and then giving up. That frees the worker sooner. +- An attempt that's already running is never interrupted. Use the job's + context if you need a hard deadline per attempt. +- The stop reason is `ErrRetryBudgetExceeded` and the status is + `budget_exceeded`. + +Use case: attempt latency varies a lot (a fast failure in one case, a 10s +timeout in another), so an attempt count alone can't bound the total cost. + +### Context cancellation + +You don't configure this; it always applies: + +- If the job's context (`Task.Context` when set, otherwise the submit + context) is done after a failure, retrying stops immediately and the + reason is `ctx.Err()`. +- A backoff wait ends the moment the context is cancelled. +- Context errors are therefore never retried pointlessly. The status is + `canceled`. + +```go +ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) +pool.Submit(ctx, job) // retries for at most ~5s, and the job sees the same deadline +``` + +### Permanent errors + +Every error is retried unless you mark it as permanent: + +```go +func chargeCard(ctx context.Context) error { + if err := validate(req); err != nil { + return adaptivepool.Permanent(err) // invalid input will never succeed + } + return gateway.Charge(ctx, req) // network errors: retried +} +``` + +- `Permanent` is transparent: `Error()` returns the original message, and + `errors.Is`/`errors.As` still match the original error. +- It works even when wrapped further: + `fmt.Errorf("charge: %w", adaptivepool.Permanent(err))`. +- `Permanent(nil)` returns `nil`. +- The stop reason is `ErrPermanentFailure` and the status is `permanent`. Without + `WithRetry` the status is still `permanent`, but the error is your own + (still wrapped by `Permanent`) rather than a `*RetryError`. + +Use case: bad input, authorisation failures, "not found". Retrying these only +wastes attempts and worker time. + +### RetryAfter (delay override) + +A job can tell the engine exactly how long to wait before the next attempt: + +```go +func callAPI(ctx context.Context) error { + resp, err := client.Do(req.WithContext(ctx)) + if err != nil { + return err + } + defer resp.Body.Close() + if resp.StatusCode == http.StatusTooManyRequests { + wait, _ := strconv.Atoi(resp.Header.Get("Retry-After")) + return adaptivepool.RetryAfter(errRateLimited, time.Duration(wait)*time.Second) + } + return nil +} +``` + +- The hint replaces the backoff value for that one retry and isn't jittered. +- It's still capped by `MaxDelay`, so a hostile or huge hint can't block a + worker indefinitely. +- It doesn't depend on HTTP: use it for any downstream that tells you when to + come back, such as rate limiters, queue visibility timeouts or lease + expiries. + +### Per-error attempt limits + +Allow fewer attempts for specific errors: + +```go +var ( + errRateLimited = errors.New("rate limited") + errTimeout = errors.New("timeout") +) + +adaptivepool.RetryPolicy{ + MaxAttempts: 6, + ErrorLimits: []adaptivepool.ErrorLimit{ + {Err: errTimeout, MaxAttempts: 2}, // timeouts: retry once + {Err: errRateLimited, MaxAttempts: 5}, // rate limits: be patient + }, +} +``` + +- Each failure is matched with `errors.Is` against the limits in order. The + first match counts, and wrapped errors match too. +- The count is how many attempts failed with *that* error. Retrying stops when + it reaches the limit, and `MaxAttempts` still bounds the job overall. +- The counters live on the stack for up to 8 limits, so typical policies add + no allocations. + +Use case: some failures deserve patience (rate limits) and others a quick +second chance (timeouts that usually mean the dependency is down). + +### Why retrying stopped: `RetryError` + +When retrying gives up, the final error is a `*RetryError`: + +```go +type RetryError struct { + Reason error // why retrying stopped + Attempts int // how many times the job ran + Err error // the last attempt's error +} +``` + +`errors.Is` matches **both** the reason and the job's own error: + +```go +errors.Is(err, adaptivepool.ErrRetriesExhausted) // true +errors.Is(err, errUpstream) // also true +``` + +| Reason | Status | Cause | +|---|---|---| +| `ErrRetriesExhausted` | `retries_exhausted` | `MaxAttempts` or an `ErrorLimit` was reached | +| `ErrRetryBudgetExceeded` | `budget_exceeded` | The next wait would exceed `MaxElapsedTime` | +| `ErrPermanentFailure` | `permanent` | The job returned a `Permanent` error | +| `context.Canceled` / `context.DeadlineExceeded` | `canceled` | The job failed after its context was done, with or without retries | +| `ErrPoolShutdown` | `shutdown` | A forced shutdown aborted a backoff wait | + +Only the last attempt's error is kept, rather than the whole history: it's +simpler to handle and doesn't grow with the number of attempts. The `retrying +task` debug logs show the earlier errors when you need them. + +Panics are never wrapped. They surface as `*PanicError` with status `panic`. + +### Shutdown behaviour + +- **Graceful** (`Shutdown` finishes within its context): in-flight retries run + to completion. They're already bounded by your policy. +- **Forced** (`Shutdown`'s context expires): backoff waits, including + zero-length ones, are aborted and the task finishes with status `shutdown`. + A running attempt isn't interrupted. Each worker exits after its current + job without starting another from the queue. Tasks still queued are + dropped: each is reported to `OnTaskDone` with status `shutdown`, + `Attempts` 0 and `ErrPoolShutdown`, and to the recorder's `JobDropped`. + `Shutdown` then returns a `*ShutdownError` with the `Dropped` count, which + wraps the context's error, so `errors.Is(err, context.DeadlineExceeded)` + still matches. The recorder is detached once the last worker has exited. +- **Repeated calls:** the first call does the work. A later call returns the + first call's result (for example `context.DeadlineExceeded` if it timed out), + or its own `ctx` error if its `ctx` ends before the shutdown does. + +### Testing retry timing with `Clock` + +Inject a `Clock` so tests don't actually sleep: + +```go +type fakeClock struct { + mu sync.Mutex + now time.Time + waits []time.Duration +} + +func (c *fakeClock) Now() time.Time { + c.mu.Lock(); defer c.mu.Unlock() + return c.now +} + +func (c *fakeClock) After(d time.Duration) <-chan time.Time { + c.mu.Lock(); defer c.mu.Unlock() + c.now = c.now.Add(d) + c.waits = append(c.waits, d) + ch := make(chan time.Time, 1) + ch <- c.now + return ch +} + +clock := &fakeClock{} +pool, _ := adaptivepool.New(adaptivepool.WithRetry(adaptivepool.RetryPolicy{ + MaxAttempts: 4, + Backoff: adaptivepool.LinearBackoff{Base: time.Second}, + Clock: clock, +})) +// ... submit a failing job, then assert clock.waits == [1s 2s 3s] instantly +``` + +--- + +## Status reference + +Every finished task has exactly one `Status`. The same value appears in the +`status` metric label, the `status` log attribute and `TaskResult.Status`. + +| Status | Meaning | +|---|---| +| `success` | The job returned nil (possibly after retries) | +| `error` | The job returned an error and retries are disabled (its context was still active) | +| `panic` | The job panicked (`*PanicError`, never retried) | +| `retries_exhausted` | All allowed attempts failed | +| `budget_exceeded` | `MaxElapsedTime` would have been exceeded | +| `permanent` | The job returned a `Permanent` error, with or without retries | +| `canceled` | The job failed after its context was done, with or without retries | +| `shutdown` | A forced shutdown aborted retrying, or dropped the task from the queue before it ran | + +--- + +## Grafana dashboard + +[`examples/observability`](../examples/observability) contains a runnable app, +plus a Prometheus and Grafana stack with a provisioned dashboard: + +```bash +make run-observability # app with metrics on :2112 +cd examples/observability && docker compose up # Prometheus :9090, Grafana :3000 +``` + +The dashboard has a pool selector and panels for: +- Workers (active, busy, max) and queue (depth, capacity) +- Throughput by kind, and failures by kind and status +- p95 execution time and p95 queue wait by kind +- Retries, retried jobs, and rejections by reason + +--- + +## Performance + +`executeJob` measured in isolation (`go test -bench BenchmarkExecuteJob -benchmem`, Apple M-series): + +| Path | ns/op | allocs/op | +|---|---|---| +| No recorder | ~50 | 0 | +| Recorder set (dispatch only, no-op recorder) | ~51 | 0 | +| Retry enabled, job succeeds | ~54 | 0 | +| One retry (zero delay), then success | ~65 | 0 | +| One retry with a real wait, then success | the wait itself | 3 (248 B, the `time.After` timer) | +| `OnTaskDone` hook set | ~58 | 0 | +| Job fails, retries disabled | ~56 | 0 | +| Retries exhausted | ~94 | 1 (the returned `*RetryError`) | + +A recorder adds its own cost on top: about 30ns per completed job for +`promrecorder` and about 200ns for `otelrecorder`, both without allocations +(`BenchmarkJobCompleted` in each package). + +`TestExecuteJobAllocations` fails the build if any zero-allocation path starts +allocating. + +**Why the timer allocation is left alone.** It could be removed by keeping one +reusable timer per worker and calling `Reset` before each wait. That would need +the `Clock` interface to expose timers instead of `After`, plus extra plumbing +from each worker into the retry engine. A real backoff wait lasts at least +milliseconds, so 248 bytes per retry costs nothing measurable, and the extra +complexity isn't worth it. diff --git a/errors.go b/errors.go index 719809a..eaf1267 100644 --- a/errors.go +++ b/errors.go @@ -1,17 +1,151 @@ package adaptivepool -import "errors" +import ( + "context" + "errors" + "fmt" + "time" +) var ( - // ErrPoolShutdown is returned when attempting to Submit a job to a shutdown pool + // ErrPoolShutdown is returned by Submit once Shutdown has started, and is the + // RetryError reason when a forced shutdown aborts a backoff wait ErrPoolShutdown = errors.New("pool is shutdown") - // ErrQueueFull is returned when the job queue is at capacity and cannot accept new jobs + // ErrQueueFull is returned by TrySubmit when the queue has no space ErrQueueFull = errors.New("queue is full") - // ErrTimeout is returned when a job submission times out - ErrTimeout = errors.New("submission timeout") + // ErrTimeout is returned when a job submission times out. It wraps + // context.DeadlineExceeded, so errors.Is matches both. + ErrTimeout = fmt.Errorf("submission timeout: %w", context.DeadlineExceeded) + + // ErrNilJob is returned when submitting a nil job + ErrNilJob = errors.New("job is nil") + + // ErrRetriesExhausted is the RetryError reason when a job used all its attempts + ErrRetriesExhausted = errors.New("retries exhausted") + + // ErrRetryBudgetExceeded is the RetryError reason when the next retry would exceed MaxElapsedTime + ErrRetryBudgetExceeded = errors.New("retry time budget exceeded") + + // ErrPermanentFailure is the RetryError reason when a job returned an error wrapped with Permanent + ErrPermanentFailure = errors.New("permanent failure") // ErrInvalidConfig is returned when pool configuration is invalid ErrInvalidConfig = errors.New("invalid pool configuration") ) + +// PanicError is the error recorded when a job panics. Stack holds the +// goroutine stack captured at the time of the panic. +type PanicError struct { + Value any + Stack []byte +} + +func (e *PanicError) Error() string { + return fmt.Sprintf("job panicked: %v", e.Value) +} + +// RetryError is the final error of a job that was retried and gave up. +// errors.Is matches both the stop Reason (e.g. ErrRetriesExhausted or +// context.Canceled) and the job's last error. +type RetryError struct { + // Reason explains why retrying stopped + Reason error + // Attempts is the number of times the job ran + Attempts int + // Err is the error returned by the last attempt + Err error +} + +func (e *RetryError) Error() string { + return fmt.Sprintf("%v after %d attempt(s): %v", e.Reason, e.Attempts, e.Err) +} + +// Unwrap returns the stop reason and the last attempt's error +func (e *RetryError) Unwrap() []error { + return []error{e.Reason, e.Err} +} + +// ShutdownError is returned by Shutdown when its context ended before the +// queue drained. errors.Is matches the context's error. +type ShutdownError struct { + // Dropped is the number of queued jobs that were discarded without running + Dropped int + // Err is the error of Shutdown's context + Err error +} + +func (e *ShutdownError) Error() string { + return fmt.Sprintf("forced shutdown dropped %d queued job(s): %v", e.Dropped, e.Err) +} + +// Unwrap returns the context's error +func (e *ShutdownError) Unwrap() error { + return e.Err +} + +// Permanent marks err as not retryable: the retry engine stops immediately. +// Use it for failures that cannot succeed on retry, such as invalid input. +// Permanent(nil) returns nil. +func Permanent(err error) error { + if err == nil { + return nil + } + return &permanentError{err: err} +} + +type permanentError struct { + err error +} + +func (e *permanentError) Error() string { return e.err.Error() } +func (e *permanentError) Unwrap() error { return e.err } + +// RetryAfter makes the next retry wait d instead of the backoff delay, e.g. +// for a Retry-After header. The wait is capped by MaxDelay and not jittered. +// RetryAfter(nil, d) returns nil. +func RetryAfter(err error, d time.Duration) error { + if err == nil { + return nil + } + return &retryAfterError{err: err, delay: max(d, 0)} +} + +type retryAfterError struct { + err error + delay time.Duration +} + +func (e *retryAfterError) Error() string { return e.err.Error() } +func (e *retryAfterError) Unwrap() error { return e.err } + +// findMarker is errors.As for the package's marker types, without the +// allocation errors.As needs for its target. +func findMarker[T error](err error) (T, bool) { + var zero T + for err != nil { + if t, ok := err.(T); ok { + return t, true + } + switch u := err.(type) { + case interface{ Unwrap() error }: + err = u.Unwrap() + case interface{ Unwrap() []error }: + for _, e := range u.Unwrap() { + if t, ok := findMarker[T](e); ok { + return t, true + } + } + return zero, false + default: + return zero, false + } + } + return zero, false +} + +func hasMarker[T error](err error) bool { + _, ok := findMarker[T](err) + return ok +} diff --git a/example_test.go b/example_test.go new file mode 100644 index 0000000..e569086 --- /dev/null +++ b/example_test.go @@ -0,0 +1,152 @@ +package adaptivepool_test + +import ( + "context" + "errors" + "fmt" + "log/slog" + "time" + + adaptivepool "github.com/iyashjayesh/go-adaptive-pool" +) + +func ExampleWithRetry() { + done := make(chan adaptivepool.TaskResult, 1) + pool, err := adaptivepool.New( + adaptivepool.WithLogger(slog.New(slog.DiscardHandler)), + adaptivepool.WithRetry(adaptivepool.RetryPolicy{ + MaxAttempts: 5, + Backoff: adaptivepool.ExponentialBackoff{Base: time.Millisecond}, + MaxDelay: 10 * time.Millisecond, + Jitter: true, + }), + adaptivepool.WithOnTaskDone(func(r adaptivepool.TaskResult) { done <- r }), + ) + if err != nil { + panic(err) + } + defer func() { _ = pool.Shutdown(context.Background()) }() + + calls := 0 + _ = pool.Submit(context.Background(), func(context.Context) error { + calls++ + if calls < 3 { + return errors.New("temporarily unavailable") + } + return nil + }) + + r := <-done + fmt.Println(r.Status, "after", r.Attempts, "attempts") + // Output: success after 3 attempts +} + +func ExamplePermanent() { + done := make(chan adaptivepool.TaskResult, 1) + pool, err := adaptivepool.New( + adaptivepool.WithLogger(slog.New(slog.DiscardHandler)), + adaptivepool.WithRetry(adaptivepool.RetryPolicy{MaxAttempts: 5}), + adaptivepool.WithOnTaskDone(func(r adaptivepool.TaskResult) { done <- r }), + ) + if err != nil { + panic(err) + } + defer func() { _ = pool.Shutdown(context.Background()) }() + + errInvalid := errors.New("invalid payload") + _ = pool.Submit(context.Background(), func(context.Context) error { + return adaptivepool.Permanent(errInvalid) + }) + + r := <-done + fmt.Println(r.Status, r.Attempts) + fmt.Println(errors.Is(r.Err, adaptivepool.ErrPermanentFailure), errors.Is(r.Err, errInvalid)) + // Output: + // permanent 1 + // true true +} + +func ExampleWithOnTaskDone() { + done := make(chan adaptivepool.TaskResult, 1) + pool, err := adaptivepool.New( + adaptivepool.WithLogger(slog.New(slog.DiscardHandler)), + adaptivepool.WithOnTaskDone(func(r adaptivepool.TaskResult) { done <- r }), + ) + if err != nil { + panic(err) + } + defer func() { _ = pool.Shutdown(context.Background()) }() + + _ = pool.SubmitTask(context.Background(), adaptivepool.Task{ + ID: "order-8812", + Kind: "send_email", + Run: func(context.Context) error { return errors.New("smtp: connection refused") }, + }) + + r := <-done + fmt.Printf("%s %s %s: %v\n", r.Kind, r.ID, r.Status, r.Err) + // Output: send_email order-8812 error: smtp: connection refused +} + +func ExamplePool_SubmitTask() { + done := make(chan error, 1) + pool, err := adaptivepool.New(adaptivepool.WithLogger(slog.New(slog.DiscardHandler))) + if err != nil { + panic(err) + } + defer func() { _ = pool.Shutdown(context.Background()) }() + + // Wait at most 50ms for queue space, but let the job run on its own + // context so the wait deadline doesn't cancel it. + waitCtx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond) + err = pool.SubmitTask(waitCtx, adaptivepool.Task{ + Kind: "send_email", + Context: context.Background(), + Run: func(ctx context.Context) error { + time.Sleep(100 * time.Millisecond) // outlives waitCtx + done <- ctx.Err() + return nil + }, + }) + cancel() + + fmt.Println("submitted:", err) + fmt.Println("job context error:", <-done) + // Output: + // submitted: + // job context error: +} + +func ExamplePool_TrySubmit() { + pool, err := adaptivepool.New( + adaptivepool.WithMinWorkers(1), + adaptivepool.WithMaxWorkers(1), + adaptivepool.WithQueueSize(1), + adaptivepool.WithLogger(slog.New(slog.DiscardHandler)), + ) + if err != nil { + panic(err) + } + defer func() { _ = pool.Shutdown(context.Background()) }() + + started, release := make(chan struct{}, 1), make(chan struct{}) + defer close(release) + block := func(context.Context) error { + select { + case started <- struct{}{}: + default: + } + <-release + return nil + } + + ctx := context.Background() + _ = pool.TrySubmit(ctx, adaptivepool.Task{Run: block}) // runs on the only worker + <-started + _ = pool.TrySubmit(ctx, adaptivepool.Task{Run: block}) // fills the queue + + // Drop best-effort work instead of waiting when the pool is saturated + err = pool.TrySubmit(ctx, adaptivepool.Task{Kind: "track_event", Run: block}) + fmt.Println(errors.Is(err, adaptivepool.ErrQueueFull)) + // Output: true +} diff --git a/examples/README.md b/examples/README.md index 17a908c..9804b02 100644 --- a/examples/README.md +++ b/examples/README.md @@ -18,6 +18,12 @@ The heavy-duty simulation used for the 1M RPS benchmarks. - with-pool: runs with protection enabled. - without-pool: runs the naive version (caution: uses lots of RAM). +### 4. Observability (/observability) +A named pool under bursty load with retries, plus Prometheus and Grafana. +- Shows retries, `Permanent` errors, `RetryAfter` hints and per-error limits. +- Serves Prometheus metrics on :2112 and logs failures as JSON. +- `docker compose up` starts Prometheus and Grafana with a ready-made dashboard. + --- ## Running the examples @@ -27,5 +33,6 @@ You can use the Makefile in the root directory to run these: ```bash make run-http make run-batch +make run-observability make run-comparison ``` \ No newline at end of file diff --git a/examples/batch_processor/main.go b/examples/batch_processor/main.go index 2a4e7bb..4a38225 100644 --- a/examples/batch_processor/main.go +++ b/examples/batch_processor/main.go @@ -103,9 +103,10 @@ func main() { } } - // Submit with short timeout to demonstrate backpressure + // Wait at most 100ms for capacity to demonstrate backpressure. The job + // runs on ctx, so cancelling the wait context below doesn't cancel it. SubmitCtx, SubmitCancel := context.WithTimeout(ctx, 100*time.Millisecond) - if err := pool.Submit(SubmitCtx, job); err != nil { + if err := pool.SubmitTask(SubmitCtx, adaptivepool.Task{Context: ctx, Run: job}); err != nil { failed.Add(1) if err != context.Canceled { log.Printf("Task %d failed to Submit: %v", taskID, err) diff --git a/examples/http_server/main.go b/examples/http_server/main.go index f74283f..8c42003 100644 --- a/examples/http_server/main.go +++ b/examples/http_server/main.go @@ -107,11 +107,18 @@ func handleSubmit(w http.ResponseWriter, r *http.Request) { } } - // Submit with timeout + // Wait at most 5s for capacity. The job gets its own context: this + // handler returns (and cancels ctx) as soon as the job is accepted, and + // the request context ends with it. WithoutCancel keeps request values. ctx, cancel := context.WithTimeout(r.Context(), 5*time.Second) defer cancel() - if err := pool.Submit(ctx, job); err != nil { + err := pool.SubmitTask(ctx, adaptivepool.Task{ + Kind: "http_job", + Context: context.WithoutCancel(r.Context()), + Run: job, + }) + if err != nil { if err == adaptivepool.ErrPoolShutdown { http.Error(w, "Service is shutting down", http.StatusServiceUnavailable) return diff --git a/examples/observability/README.md b/examples/observability/README.md new file mode 100644 index 0000000..1e3c6bc --- /dev/null +++ b/examples/observability/README.md @@ -0,0 +1,56 @@ +# Observability example + +Runs a pool named `orders` under synthetic, bursty load with retries enabled, +and serves its Prometheus metrics on `:2112/metrics`. A Prometheus + Grafana +stack with a pre-built dashboard is included. + +```bash +# 1. Start the app (from the repo root) +make run-observability + +# 2. Start Prometheus and Grafana +cd examples/observability && docker compose up +``` + +Open Grafana at http://localhost:3000 (anonymous access is enabled) and pick +the **Adaptive Pool** dashboard. Prometheus is on http://localhost:9090. + +Metrics are exported with `promrecorder`. If port 2112 is taken by another +process, pick another port and point Prometheus at it: + +```bash +make run-observability ARGS="-metrics-addr=:2113" +# then change the target in prometheus.yml to host.docker.internal:2113 +``` + +## What the load does + +| Kind | Behaviour | Shows up as | +|---|---|---| +| `send_email` | 10% transient `upstream unavailable` errors, limited to 2 attempts via `ErrorLimits` | retries, `retries_exhausted` | +| `resize_image` | 2% `Permanent` invalid payload errors | `permanent` (never retried) | +| `charge_card` | 15% rate limiting with a `RetryAfter` hint of 200ms | retries honouring the hint | + +A second pool, `previews` (4 workers, queue of 8, no retries), receives +interactive and best-effort work, so the rejection panels have data: + +| Kind | Behaviour | Shows up as | +|---|---|---| +| `render_preview` | Request-scoped work with a 250ms deadline; 5% of clients disconnect early | rejected `canceled`, completed `canceled` when the deadline passes in the queue | +| `track_event` | Best-effort telemetry, dropped if no slot frees within 5ms | rejected `timeout` during bursts | + +Use the dashboard's **Pool** selector to compare the two pools. + +Load on `orders` alternates between 50 and 400 tasks/s every 30 seconds, so you can watch +the pool scale up, the queue fill and drain, and queue wait rise during bursts. + +## Logs + +The app writes JSON logs to stdout. Only failures are logged at the default +level, each with `pool`, `task_id`, `kind`, `status`, `attempts`, `duration` +and `err`. Ship them to Loki (for example with Grafana Alloy) to drill into a +failure spike seen on the dashboard: + +```logql +{app="orders"} | json | status != "success" | line_format "{{.task_id}} {{.status}} {{.err}}" +``` diff --git a/examples/observability/docker-compose.yml b/examples/observability/docker-compose.yml new file mode 100644 index 0000000..01b83ad --- /dev/null +++ b/examples/observability/docker-compose.yml @@ -0,0 +1,23 @@ +services: + prometheus: + image: prom/prometheus:v3.1.0 + ports: + - "9090:9090" + volumes: + - ./prometheus.yml:/etc/prometheus/prometheus.yml:ro + extra_hosts: + - "host.docker.internal:host-gateway" + + grafana: + image: grafana/grafana:11.4.0 + ports: + - "3000:3000" + environment: + GF_AUTH_ANONYMOUS_ENABLED: "true" + GF_AUTH_ANONYMOUS_ORG_ROLE: Admin + GF_AUTH_DISABLE_LOGIN_FORM: "true" + volumes: + - ./grafana/provisioning:/etc/grafana/provisioning:ro + - ./grafana/dashboards:/var/lib/grafana/dashboards:ro + depends_on: + - prometheus diff --git a/examples/observability/go.mod b/examples/observability/go.mod new file mode 100644 index 0000000..802680d --- /dev/null +++ b/examples/observability/go.mod @@ -0,0 +1,27 @@ +module github.com/iyashjayesh/go-adaptive-pool/examples/observability + +go 1.25.0 + +require ( + github.com/iyashjayesh/go-adaptive-pool v0.0.0 + github.com/iyashjayesh/go-adaptive-pool/promrecorder v0.0.0 + github.com/prometheus/client_golang v1.23.2 +) + +require ( + github.com/beorn7/perks v1.0.1 // indirect + github.com/cespare/xxhash/v2 v2.3.0 // indirect + github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect + github.com/prometheus/client_model v0.6.2 // indirect + github.com/prometheus/common v0.66.1 // indirect + github.com/prometheus/procfs v0.16.1 // indirect + go.yaml.in/yaml/v2 v2.4.2 // indirect + golang.org/x/sys v0.47.0 // indirect + google.golang.org/protobuf v1.36.8 // indirect +) + +// An example, never imported by anyone: it always builds against this checkout. +replace ( + github.com/iyashjayesh/go-adaptive-pool => ../../ + github.com/iyashjayesh/go-adaptive-pool/promrecorder => ../../promrecorder +) diff --git a/examples/observability/go.sum b/examples/observability/go.sum new file mode 100644 index 0000000..6ef9948 --- /dev/null +++ b/examples/observability/go.sum @@ -0,0 +1,41 @@ +github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= +github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= +github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= +github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= +github.com/klauspost/compress v1.18.0 h1:c/Cqfb0r+Yi+JtIEq73FWXVkRonBlf0CRNYc8Zttxdo= +github.com/klauspost/compress v1.18.0/go.mod h1:2Pp+KzxcywXVXMr50+X0Q/Lsb43OQHYWRCY2AiWywWQ= +github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= +github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= +github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= +github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= +github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc= +github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= +github.com/prometheus/client_golang v1.23.2 h1:Je96obch5RDVy3FDMndoUsjAhG5Edi49h0RJWRi/o0o= +github.com/prometheus/client_golang v1.23.2/go.mod h1:Tb1a6LWHB3/SPIzCoaDXI4I8UHKeFTEQ1YCr+0Gyqmg= +github.com/prometheus/client_model v0.6.2 h1:oBsgwpGs7iVziMvrGhE53c/GrLUsZdHnqNwqPLxwZyk= +github.com/prometheus/client_model v0.6.2/go.mod h1:y3m2F6Gdpfy6Ut/GBsUqTWZqCUvMVzSfMLjcu6wAwpE= +github.com/prometheus/common v0.66.1 h1:h5E0h5/Y8niHc5DlaLlWLArTQI7tMrsfQjHV+d9ZoGs= +github.com/prometheus/common v0.66.1/go.mod h1:gcaUsgf3KfRSwHY4dIMXLPV0K/Wg1oZ8+SbZk/HH/dA= +github.com/prometheus/procfs v0.16.1 h1:hZ15bTNuirocR6u0JZ6BAHHmwS1p8B4P6MRqxtzMyRg= +github.com/prometheus/procfs v0.16.1/go.mod h1:teAbpZRB1iIAJYREa1LsoWUXykVXA1KlTmWl8x/U+Is= +github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ= +github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog= +github.com/stretchr/testify v1.12.1 h1:EuwCh5fleGS7H32xRwO3wRGT7DxrDhLAT6FF8MpWDWE= +github.com/stretchr/testify v1.12.1/go.mod h1:MDEgiDPPsNp5cuIrHPPCyornHKgEVbtFUmoNlxoYthg= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= +go.yaml.in/yaml/v2 v2.4.2 h1:DzmwEr2rDGHl7lsFgAHxmNz/1NlQ7xLIrlN2h5d1eGI= +go.yaml.in/yaml/v2 v2.4.2/go.mod h1:081UH+NErpNdqlCXm3TtEran0rJZGxAYx9hb/ELlsPU= +go.yaml.in/yaml/v3 v3.0.5 h1:N6y/pJk8buWs9NY5ERU2HSMfm+IuD/OtfdAnq6kESPw= +go.yaml.in/yaml/v3 v3.0.5/go.mod h1:HVTZu1O7/Vkt2N+BFy8Zza+lnLsABggaTM2ZpNIGuKg= +golang.org/x/sys v0.47.0 h1:o7XGOvZQCADBQQ4Y7VNq2dRWQR7JmOUW8Kxx4ZsNgWs= +golang.org/x/sys v0.47.0/go.mod h1:4GL1E5IUh+htKOUEOaiffhrAeqysfVGipDYzABqnCmw= +google.golang.org/protobuf v1.36.8 h1:xHScyCOEuuwZEc6UtSOvPbAT4zRh0xcNRYekJwfqyMc= +google.golang.org/protobuf v1.36.8/go.mod h1:fuxRtAxBytpl4zzqUh6/eyUujkJdNiuEkXntxiD/uRU= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= +gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= diff --git a/examples/observability/grafana/dashboards/adaptivepool.json b/examples/observability/grafana/dashboards/adaptivepool.json new file mode 100644 index 0000000..b2fb609 --- /dev/null +++ b/examples/observability/grafana/dashboards/adaptivepool.json @@ -0,0 +1,841 @@ +{ + "uid": "adaptivepool", + "title": "Adaptive Pool", + "schemaVersion": 39, + "version": 1, + "refresh": "5s", + "time": { + "from": "now-15m", + "to": "now" + }, + "tags": [ + "adaptivepool" + ], + "templating": { + "list": [ + { + "name": "pool", + "label": "Pool", + "type": "query", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "query": { + "query": "label_values(adaptivepool_active_workers, pool)", + "refId": "pool" + }, + "definition": "label_values(adaptivepool_active_workers, pool)", + "includeAll": true, + "multi": true, + "allValue": ".*", + "refresh": 2, + "current": { + "text": "All", + "value": "$__all" + } + } + ] + }, + "panels": [ + { + "id": 1, + "type": "row", + "title": "Overview", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 0, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 2, + "type": "stat", + "title": "Active workers", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 0, + "y": 1, + "w": 4, + "h": 4 + }, + "fieldConfig": { + "defaults": { + "unit": "short" + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "(sum(adaptivepool_active_workers{pool=~\"$pool\"})) or vector(0)", + "legendFormat": "" + } + ], + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ] + }, + "colorMode": "value", + "graphMode": "area" + } + }, + { + "id": 3, + "type": "stat", + "title": "Busy workers", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 4, + "y": 1, + "w": 4, + "h": 4 + }, + "fieldConfig": { + "defaults": { + "unit": "short" + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "(sum(adaptivepool_busy_workers{pool=~\"$pool\"})) or vector(0)", + "legendFormat": "" + } + ], + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ] + }, + "colorMode": "value", + "graphMode": "area" + } + }, + { + "id": 4, + "type": "stat", + "title": "Queue depth", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 8, + "y": 1, + "w": 4, + "h": 4 + }, + "fieldConfig": { + "defaults": { + "unit": "short" + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "(sum(adaptivepool_queue_depth{pool=~\"$pool\"})) or vector(0)", + "legendFormat": "" + } + ], + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ] + }, + "colorMode": "value", + "graphMode": "area" + } + }, + { + "id": 5, + "type": "stat", + "title": "Throughput", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 12, + "y": 1, + "w": 4, + "h": 4 + }, + "fieldConfig": { + "defaults": { + "unit": "reqps" + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "(sum(rate(adaptivepool_jobs_completed_total{pool=~\"$pool\"}[1m]))) or vector(0)", + "legendFormat": "" + } + ], + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ] + }, + "colorMode": "value", + "graphMode": "area" + } + }, + { + "id": 6, + "type": "stat", + "title": "Failure ratio", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 16, + "y": 1, + "w": 4, + "h": 4 + }, + "fieldConfig": { + "defaults": { + "unit": "percentunit" + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "(sum(rate(adaptivepool_jobs_completed_total{pool=~\"$pool\",status!=\"success\"}[5m])) / sum(rate(adaptivepool_jobs_completed_total{pool=~\"$pool\"}[5m]))) or vector(0)", + "legendFormat": "" + } + ], + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ] + }, + "colorMode": "value", + "graphMode": "area" + } + }, + { + "id": 7, + "type": "stat", + "title": "Rejected / s", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 20, + "y": 1, + "w": 4, + "h": 4 + }, + "fieldConfig": { + "defaults": { + "unit": "reqps" + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "(sum(rate(adaptivepool_jobs_rejected_total{pool=~\"$pool\"}[1m]))) or vector(0)", + "legendFormat": "" + } + ], + "options": { + "reduceOptions": { + "calcs": [ + "lastNotNull" + ] + }, + "colorMode": "value", + "graphMode": "area" + } + }, + { + "id": 8, + "type": "row", + "title": "Capacity", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 5, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 9, + "type": "timeseries", + "title": "Workers", + "description": "Busy close to max means the pool is saturated; scale-ups appear as steps in active.", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 0, + "y": 6, + "w": 12, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "short", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "none" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (pool) (adaptivepool_active_workers{pool=~\"$pool\"})", + "legendFormat": "active {{pool}}" + }, + { + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (pool) (adaptivepool_busy_workers{pool=~\"$pool\"})", + "legendFormat": "busy {{pool}}" + }, + { + "refId": "C", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (pool) (adaptivepool_max_workers{pool=~\"$pool\"})", + "legendFormat": "max {{pool}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + }, + { + "id": 10, + "type": "timeseries", + "title": "Queue", + "description": "A queue near capacity means Submit is applying backpressure.", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 12, + "y": 6, + "w": 12, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "short", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "none" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (pool) (adaptivepool_queue_depth{pool=~\"$pool\"})", + "legendFormat": "depth {{pool}}" + }, + { + "refId": "B", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (pool) (adaptivepool_queue_capacity{pool=~\"$pool\"})", + "legendFormat": "capacity {{pool}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + }, + { + "id": 11, + "type": "row", + "title": "Tasks", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 14, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 12, + "type": "timeseries", + "title": "Completed / s by kind", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 0, + "y": 15, + "w": 12, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "normal" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (kind) (rate(adaptivepool_jobs_completed_total{pool=~\"$pool\"}[1m]))", + "legendFormat": "{{kind}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + }, + { + "id": 13, + "type": "timeseries", + "title": "Failures / s by status", + "description": "Why tasks failed: error, panic, retries_exhausted, budget_exceeded, permanent, canceled, shutdown.", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 12, + "y": 15, + "w": 12, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "normal" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (kind, status) (rate(adaptivepool_jobs_completed_total{pool=~\"$pool\",status!=\"success\"}[1m]))", + "legendFormat": "{{kind}} {{status}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + }, + { + "id": 14, + "type": "timeseries", + "title": "Execution time p95 by kind", + "description": "Includes retries and backoff waits.", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 0, + "y": 23, + "w": 12, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "s", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "none" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "histogram_quantile(0.95, sum by (le, kind) (rate(adaptivepool_job_duration_seconds_bucket{pool=~\"$pool\"}[1m])))", + "legendFormat": "{{kind}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + }, + { + "id": 15, + "type": "timeseries", + "title": "Queue wait p95 by kind", + "description": "Time between Submit and execution start. Growing wait means too few workers.", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 12, + "y": 23, + "w": 12, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "s", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "none" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "histogram_quantile(0.95, sum by (le, kind) (rate(adaptivepool_job_queue_wait_seconds_bucket{pool=~\"$pool\"}[1m])))", + "legendFormat": "{{kind}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + }, + { + "id": 16, + "type": "row", + "title": "Retries and rejections", + "collapsed": false, + "gridPos": { + "x": 0, + "y": 31, + "w": 24, + "h": 1 + }, + "panels": [] + }, + { + "id": 17, + "type": "timeseries", + "title": "Retries / s by kind", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 0, + "y": 32, + "w": 8, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "none" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (kind) (rate(adaptivepool_retry_attempts_total{pool=~\"$pool\"}[1m]))", + "legendFormat": "{{kind}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + }, + { + "id": 18, + "type": "timeseries", + "title": "Retried jobs / s by kind", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 8, + "y": 32, + "w": 8, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "none" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (kind) (rate(adaptivepool_jobs_retried_total{pool=~\"$pool\"}[1m]))", + "legendFormat": "{{kind}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + }, + { + "id": 19, + "type": "timeseries", + "title": "Rejections / s by reason", + "description": "", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "gridPos": { + "x": 16, + "y": 32, + "w": 8, + "h": 8 + }, + "fieldConfig": { + "defaults": { + "unit": "reqps", + "custom": { + "fillOpacity": 10, + "stacking": { + "mode": "none" + } + } + }, + "overrides": [] + }, + "targets": [ + { + "refId": "A", + "datasource": { + "type": "prometheus", + "uid": "prometheus" + }, + "expr": "sum by (kind, reason) (rate(adaptivepool_jobs_rejected_total{pool=~\"$pool\"}[1m]))", + "legendFormat": "{{kind}} {{reason}}" + } + ], + "options": { + "legend": { + "displayMode": "table", + "placement": "right", + "calcs": [ + "lastNotNull", + "max" + ] + }, + "tooltip": { + "mode": "multi" + } + } + } + ] +} \ No newline at end of file diff --git a/examples/observability/grafana/provisioning/dashboards/dashboards.yml b/examples/observability/grafana/provisioning/dashboards/dashboards.yml new file mode 100644 index 0000000..9a449a6 --- /dev/null +++ b/examples/observability/grafana/provisioning/dashboards/dashboards.yml @@ -0,0 +1,7 @@ +apiVersion: 1 +providers: + - name: adaptivepool + folder: "" + type: file + options: + path: /var/lib/grafana/dashboards diff --git a/examples/observability/grafana/provisioning/datasources/prometheus.yml b/examples/observability/grafana/provisioning/datasources/prometheus.yml new file mode 100644 index 0000000..2387b2f --- /dev/null +++ b/examples/observability/grafana/provisioning/datasources/prometheus.yml @@ -0,0 +1,8 @@ +apiVersion: 1 +datasources: + - name: Prometheus + uid: prometheus + type: prometheus + access: proxy + url: http://prometheus:9090 + isDefault: true diff --git a/examples/observability/main.go b/examples/observability/main.go new file mode 100644 index 0000000..f523103 --- /dev/null +++ b/examples/observability/main.go @@ -0,0 +1,272 @@ +// Package main runs an adaptive pool under synthetic load and exposes its +// Prometheus metrics, for use with the bundled Prometheus + Grafana stack. +package main + +import ( + "context" + "errors" + "flag" + "fmt" + "log/slog" + "math/rand/v2" + "net/http" + "os" + "os/signal" + "sync" + "sync/atomic" + "syscall" + "time" + + adaptivepool "github.com/iyashjayesh/go-adaptive-pool" + "github.com/iyashjayesh/go-adaptive-pool/promrecorder" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promhttp" +) + +var ( + errUpstream = errors.New("upstream unavailable") + errRateLimited = errors.New("rate limited") + errBadPayload = errors.New("invalid payload") +) + +// kind describes one type of synthetic task +type kind struct { + name string + latency time.Duration + run func(ctx context.Context, latency time.Duration) error +} + +func main() { + metricsAddr := flag.String("metrics-addr", ":2112", "address to serve Prometheus metrics on; keep prometheus.yml's target in sync") + flag.Parse() + + logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo})) + + var deadLetters atomic.Int64 + pool, err := adaptivepool.New( + adaptivepool.WithName("orders"), + adaptivepool.WithMinWorkers(4), + adaptivepool.WithMaxWorkers(32), + adaptivepool.WithQueueSize(500), + adaptivepool.WithScaleDownIdleDuration(10*time.Second), + adaptivepool.WithScaleCooldown(time.Second), // react quickly to the 30s bursts + adaptivepool.WithLogger(logger), + adaptivepool.WithRecorder(promrecorder.New(prometheus.DefaultRegisterer)), + adaptivepool.WithRetry(adaptivepool.RetryPolicy{ + MaxAttempts: 4, + Backoff: adaptivepool.ExponentialBackoff{Base: 50 * time.Millisecond, Multiplier: 2}, + MaxDelay: time.Second, + MaxElapsedTime: 3 * time.Second, + Jitter: true, + ErrorLimits: []adaptivepool.ErrorLimit{{Err: errUpstream, MaxAttempts: 2}}, + }), + adaptivepool.WithOnTaskDone(func(r adaptivepool.TaskResult) { + if r.Err != nil { + deadLetters.Add(1) // a real service would publish r to a dead-letter queue + } + }), + ) + if err != nil { + logger.Error("creating pool", slog.Any("err", err)) + os.Exit(1) + } + + // A small pool for interactive work. It has no retries: a request has a + // deadline, so failing fast beats queueing work nobody will wait for. + previews, err := adaptivepool.New( + adaptivepool.WithName("previews"), + adaptivepool.WithMinWorkers(2), + adaptivepool.WithMaxWorkers(4), + adaptivepool.WithQueueSize(8), // ~80ms of work: queued requests still meet their deadline + adaptivepool.WithScaleCooldown(time.Second), + adaptivepool.WithLogger(logger), + adaptivepool.WithRecorder(promrecorder.New(prometheus.DefaultRegisterer)), + ) + if err != nil { + logger.Error("creating pool", slog.Any("err", err)) + os.Exit(1) + } + + http.Handle("/metrics", promhttp.Handler()) + server := &http.Server{Addr: *metricsAddr, ReadHeaderTimeout: 3 * time.Second} + go func() { + logger.Info("serving metrics", slog.String("addr", *metricsAddr)) + if err := server.ListenAndServe(); err != nil && !errors.Is(err, http.ErrServerClosed) { + logger.Error("metrics server", slog.Any("err", err)) + } + }() + + ctx, stop := signal.NotifyContext(context.Background(), os.Interrupt, syscall.SIGTERM) + defer stop() + + // Producers stop before the pools shut down + var producers sync.WaitGroup + producers.Go(func() { generateLoad(ctx, pool) }) + producers.Go(func() { serveRequests(ctx, previews) }) + producers.Go(func() { trackEvents(ctx, previews) }) + producers.Wait() + + logger.Info("shutting down", slog.Int64("dead_letters", deadLetters.Load())) + shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + _ = pool.Shutdown(shutdownCtx) + _ = previews.Shutdown(shutdownCtx) + _ = server.Shutdown(shutdownCtx) +} + +// generateLoad submits tasks in waves so scaling, queueing and retries are +// all visible on the dashboard. +func generateLoad(ctx context.Context, pool adaptivepool.Pool) { + kinds := []kind{ + {"send_email", 20 * time.Millisecond, flaky(0.10, errUpstream)}, + {"resize_image", 80 * time.Millisecond, flaky(0.02, errBadPayload)}, + {"charge_card", 40 * time.Millisecond, rateLimited(0.15)}, + } + + var seq int + for { + rate := 50 + if burst() { + rate = 400 + } + tick := time.Second / time.Duration(rate) + + select { + case <-ctx.Done(): + return + case <-time.After(tick): + } + + k := kinds[rand.IntN(len(kinds))] + seq++ + // The submit context is also the task's execution context, so it must + // outlive the task. Background lets queued tasks drain on shutdown. + _ = pool.SubmitTask(context.Background(), adaptivepool.Task{ + ID: fmt.Sprintf("%s-%d", k.name, seq), + Kind: k.name, + Run: func(ctx context.Context) error { + return k.run(ctx, k.latency) + }, + }) + } +} + +// serveRequests simulates interactive requests, such as rendering a preview +// for an HTTP response, that must finish within the request's deadline. +// +// Here the submit context should also be the job context: if the request +// times out or the client goes away, both waiting for a queue slot and the +// work itself should stop. When the pool is saturated, Submit returns +// ErrTimeout (rejected, reason="timeout") or context.Canceled +// (reason="canceled") and a real handler would respond with 503. +func serveRequests(ctx context.Context, pool adaptivepool.Pool) { + var requests sync.WaitGroup + defer requests.Wait() + + for id := 1; ; id++ { + rate := 40 + if burst() { + rate = 150 // more than 4 workers can serve + } + select { + case <-ctx.Done(): + return + case <-time.After(time.Second / time.Duration(rate)): + } + requests.Go(func() { handleRequest(ctx, pool, id) }) + } +} + +func handleRequest(ctx context.Context, pool adaptivepool.Pool, id int) { + reqCtx, cancel := context.WithTimeout(ctx, 250*time.Millisecond) + defer cancel() + if rand.Float64() < 0.05 { + time.AfterFunc(rand.N(100*time.Millisecond), cancel) // client disconnects + } + + done := make(chan struct{}) + err := pool.SubmitTask(reqCtx, adaptivepool.Task{ + ID: fmt.Sprintf("preview-%d", id), + Kind: "render_preview", + Run: func(ctx context.Context) error { + defer close(done) + return work(ctx, 40*time.Millisecond) + }, + }) + if err != nil { + return // rejected: respond 503 Service Unavailable + } + select { + case <-done: + case <-reqCtx.Done(): + } +} + +// trackEvents submits best-effort telemetry: if no worker slot frees up +// within 5ms the event is dropped (rejected, reason="timeout"). +// +// Task.Context gives the job its own context, so the 5ms deadline only +// bounds the wait for a queue slot and doesn't cancel accepted events. +func trackEvents(ctx context.Context, pool adaptivepool.Pool) { + for id := 1; ; id++ { + select { + case <-ctx.Done(): + return + case <-time.After(20 * time.Millisecond): + } + submitCtx, cancel := context.WithTimeout(ctx, 5*time.Millisecond) + _ = pool.SubmitTask(submitCtx, adaptivepool.Task{ + ID: fmt.Sprintf("event-%d", id), + Kind: "track_event", + Context: context.Background(), + Run: func(ctx context.Context) error { + return work(ctx, 5*time.Millisecond) + }, + }) + cancel() + } +} + +// burst reports whether load is in a burst phase; phases alternate every 30s +func burst() bool { + return time.Now().Unix()/30%2 == 0 +} + +// work simulates a task taking roughly latency +func work(ctx context.Context, latency time.Duration) error { + select { + case <-time.After(latency/2 + rand.N(latency)): + return nil + case <-ctx.Done(): + return ctx.Err() + } +} + +// flaky fails with err at the given rate. Payload errors are permanent. +func flaky(rate float64, err error) func(context.Context, time.Duration) error { + return func(ctx context.Context, latency time.Duration) error { + if werr := work(ctx, latency); werr != nil { + return werr + } + if rand.Float64() < rate { + if errors.Is(err, errBadPayload) { + return adaptivepool.Permanent(err) + } + return err + } + return nil + } +} + +// rateLimited simulates a downstream API that returns a Retry-After hint +func rateLimited(rate float64) func(context.Context, time.Duration) error { + return func(ctx context.Context, latency time.Duration) error { + if err := work(ctx, latency); err != nil { + return err + } + if rand.Float64() < rate { + return adaptivepool.RetryAfter(errRateLimited, 200*time.Millisecond) + } + return nil + } +} diff --git a/examples/observability/prometheus.yml b/examples/observability/prometheus.yml new file mode 100644 index 0000000..dfa271a --- /dev/null +++ b/examples/observability/prometheus.yml @@ -0,0 +1,7 @@ +global: + scrape_interval: 5s + +scrape_configs: + - job_name: adaptivepool-example + static_configs: + - targets: ["host.docker.internal:2112"] diff --git a/execute.go b/execute.go new file mode 100644 index 0000000..02f96c5 --- /dev/null +++ b/execute.go @@ -0,0 +1,103 @@ +package adaptivepool + +import ( + "context" + "log/slog" + "runtime/debug" + "time" +) + +// executeJob runs a job on the calling worker and records its outcome +func (p *pool) executeJob(workerID int, job jobWrapper) { + p.state.busyWorkers.Add(1) + defer p.state.busyWorkers.Add(-1) + + start := time.Now() + attempts, err := 1, error(nil) + if p.retrier != nil { + attempts, err = p.retrier.execute(&job) + } else { + err = runJob(job.ctx, job.job) + } + duration := time.Since(start) + status := statusOf(err) + if status == StatusError && job.ctx.Err() != nil { + // Match the retry engine: a failure after the context is done is canceled + status = StatusCanceled + } + + queueWait := start.Sub(p.epoch) - time.Duration(job.submittedAt) + + p.metrics.recordJobDone(job.kind, status, attempts, queueWait, duration) + if err != nil { + p.logFailure(workerID, job, status, attempts, duration, err) + } + if p.config.onTaskDone != nil { + p.notifyTaskDone(TaskResult{ + ID: job.taskID, + Kind: job.kind, + QueueWait: queueWait, + Duration: duration, + Attempts: attempts, + Status: status, + Err: err, + }) + } +} + +// dropJob reports a queued job that a forced shutdown discarded before it ran +func (p *pool) dropJob(job jobWrapper) { + p.metrics.recordJobDropped(job.kind) + if p.config.onTaskDone != nil { + p.notifyTaskDone(TaskResult{ + ID: job.taskID, + Kind: job.kind, + QueueWait: time.Since(p.epoch) - time.Duration(job.submittedAt), + Status: StatusShutdown, + Err: ErrPoolShutdown, + }) + } +} + +// notifyTaskDone invokes the OnTaskDone hook, shielding the worker from panics +func (p *pool) notifyTaskDone(res TaskResult) { + defer func() { + if r := recover(); r != nil { + p.logger.Error("OnTaskDone hook panicked", + slog.String("task_id", res.ID), + slog.Any("panic", r), + slog.String("stack", string(debug.Stack())), + ) + } + }() + p.config.onTaskDone(res) +} + +// runJob executes the job, converting a panic into a *PanicError +func runJob(ctx context.Context, job Job) (err error) { + defer func() { + if r := recover(); r != nil { + err = &PanicError{Value: r, Stack: debug.Stack()} + } + }() + return job(ctx) +} + +func (p *pool) logFailure(workerID int, job jobWrapper, status Status, attempts int, duration time.Duration, err error) { + if !p.logger.Enabled(job.ctx, slog.LevelError) { + return + } + attrs := []slog.Attr{ + slog.Int("worker", workerID), + slog.String("task_id", job.taskID), + slog.String("kind", job.kind), + slog.String("status", string(status)), + slog.Int("attempts", attempts), + slog.Duration("duration", duration), + slog.Any("err", err), + } + if pe, ok := err.(*PanicError); ok { + attrs = append(attrs, slog.String("stack", string(pe.Stack))) + } + p.logger.LogAttrs(job.ctx, slog.LevelError, "task failed", attrs...) +} diff --git a/execute_bench_test.go b/execute_bench_test.go new file mode 100644 index 0000000..a56b415 --- /dev/null +++ b/execute_bench_test.go @@ -0,0 +1,106 @@ +package adaptivepool + +import ( + "context" + "errors" + "testing" + "time" +) + +// benchPool returns the concrete pool so executeJob can be measured in +// isolation from queueing and scheduling. +func benchPool(tb testing.TB, opts ...Option) *pool { + tb.Helper() + opts = append([]Option{WithLogger(discardLogger())}, opts...) + p, err := New(opts...) + if err != nil { + tb.Fatal(err) + } + tb.Cleanup(func() { + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + _ = p.Shutdown(ctx) + }) + return p.(*pool) +} + +var errBench = errors.New("bench") + +// noopRecorder measures the cost of dispatching events to a recorder. +type noopRecorder struct{} + +func (noopRecorder) JobSubmitted(string) {} +func (noopRecorder) JobRejected(string, RejectReason) {} +func (noopRecorder) JobCompleted(string, Status, int, time.Duration, time.Duration) {} +func (noopRecorder) JobDropped(string) {} +func (noopRecorder) ScaledUp(int) {} + +func executeCases() []struct { + name string + opts []Option + job Job +} { + ok := func(context.Context) error { return nil } + failOnce := func() Job { + failed := false + return func(context.Context) error { + if failed = !failed; failed { + return errBench + } + return nil + } + } + noWait := WithRetry(RetryPolicy{MaxAttempts: 3, Backoff: ConstantBackoff{}}) + permanent := Permanent(errBench) + return []struct { + name string + opts []Option + job Job + }{ + {"no-recorder", nil, ok}, + {"recorder", []Option{WithRecorder(noopRecorder{})}, ok}, + {"retry-success", []Option{noWait}, ok}, + {"retry-one-failure", []Option{noWait}, failOnce()}, + {"hook", []Option{WithOnTaskDone(func(TaskResult) {})}, ok}, + {"error", nil, func(context.Context) error { return errBench }}, + {"permanent", nil, func(context.Context) error { return permanent }}, + {"retry-exhausted", []Option{noWait}, func(context.Context) error { return errBench }}, + } +} + +func BenchmarkExecuteJob(b *testing.B) { + for _, c := range executeCases() { + b.Run(c.name, func(b *testing.B) { + p := benchPool(b, c.opts...) + w := jobWrapper{job: c.job, ctx: context.Background(), kind: "bench"} + b.ReportAllocs() + for b.Loop() { + p.executeJob(0, w) + } + }) + } +} + +// TestExecuteJobAllocations guards the hot path: apart from the final +// *RetryError when retrying gives up, executing a job must not allocate. +// Retry cases use zero-length waits; a real wait adds the timer allocated +// by Clock.After, which is outside what this test covers. +func TestExecuteJobAllocations(t *testing.T) { + if raceEnabled { + t.Skip("the race detector adds allocations") + } + for _, c := range executeCases() { + t.Run(c.name, func(t *testing.T) { + p := benchPool(t, c.opts...) + w := jobWrapper{job: c.job, ctx: context.Background(), kind: "bench"} + want := 0.0 + if c.name == "retry-exhausted" { + want = 1 + } + allocs := testing.AllocsPerRun(1000, func() { p.executeJob(0, w) }) + if allocs != want { + t.Fatalf("got %v allocs per job, want %v", allocs, want) + } + }) + } +} diff --git a/go.mod b/go.mod index 6182a75..3e91541 100644 --- a/go.mod +++ b/go.mod @@ -3,22 +3,8 @@ module github.com/iyashjayesh/go-adaptive-pool go 1.25.0 require ( - github.com/prometheus/client_golang v1.23.2 - github.com/stretchr/testify v1.11.1 + github.com/stretchr/testify v1.12.1 go.uber.org/goleak v1.3.0 ) -require ( - github.com/beorn7/perks v1.0.1 // indirect - github.com/cespare/xxhash/v2 v2.3.0 // indirect - github.com/davecgh/go-spew v1.1.1 // indirect - github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect - github.com/pmezard/go-difflib v1.0.0 // indirect - github.com/prometheus/client_model v0.6.2 // indirect - github.com/prometheus/common v0.66.1 // indirect - github.com/prometheus/procfs v0.16.1 // indirect - go.yaml.in/yaml/v2 v2.4.2 // indirect - golang.org/x/sys v0.35.0 // indirect - google.golang.org/protobuf v1.36.8 // indirect - gopkg.in/yaml.v3 v3.0.1 // indirect -) +require go.yaml.in/yaml/v3 v3.0.5 // indirect diff --git a/go.sum b/go.sum index 8ce748b..8c1274c 100644 --- a/go.sum +++ b/go.sum @@ -1,31 +1,6 @@ -github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= -github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= -github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= -github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= -github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= -github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= -github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= -github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= -github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= -github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= -github.com/prometheus/client_golang v1.23.2 h1:Je96obch5RDVy3FDMndoUsjAhG5Edi49h0RJWRi/o0o= -github.com/prometheus/client_golang v1.23.2/go.mod h1:Tb1a6LWHB3/SPIzCoaDXI4I8UHKeFTEQ1YCr+0Gyqmg= -github.com/prometheus/client_model v0.6.2 h1:oBsgwpGs7iVziMvrGhE53c/GrLUsZdHnqNwqPLxwZyk= -github.com/prometheus/client_model v0.6.2/go.mod h1:y3m2F6Gdpfy6Ut/GBsUqTWZqCUvMVzSfMLjcu6wAwpE= -github.com/prometheus/common v0.66.1 h1:h5E0h5/Y8niHc5DlaLlWLArTQI7tMrsfQjHV+d9ZoGs= -github.com/prometheus/common v0.66.1/go.mod h1:gcaUsgf3KfRSwHY4dIMXLPV0K/Wg1oZ8+SbZk/HH/dA= -github.com/prometheus/procfs v0.16.1 h1:hZ15bTNuirocR6u0JZ6BAHHmwS1p8B4P6MRqxtzMyRg= -github.com/prometheus/procfs v0.16.1/go.mod h1:teAbpZRB1iIAJYREa1LsoWUXykVXA1KlTmWl8x/U+Is= -github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= -github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= +github.com/stretchr/testify v1.12.1 h1:EuwCh5fleGS7H32xRwO3wRGT7DxrDhLAT6FF8MpWDWE= +github.com/stretchr/testify v1.12.1/go.mod h1:MDEgiDPPsNp5cuIrHPPCyornHKgEVbtFUmoNlxoYthg= go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= -go.yaml.in/yaml/v2 v2.4.2 h1:DzmwEr2rDGHl7lsFgAHxmNz/1NlQ7xLIrlN2h5d1eGI= -go.yaml.in/yaml/v2 v2.4.2/go.mod h1:081UH+NErpNdqlCXm3TtEran0rJZGxAYx9hb/ELlsPU= -golang.org/x/sys v0.35.0 h1:vz1N37gP5bs89s7He8XuIYXpyY0+QlsKmzipCbUtyxI= -golang.org/x/sys v0.35.0/go.mod h1:BJP2sWEmIv4KK5OTEluFJCKSidICx8ciO85XgH3Ak8k= -google.golang.org/protobuf v1.36.8 h1:xHScyCOEuuwZEc6UtSOvPbAT4zRh0xcNRYekJwfqyMc= -google.golang.org/protobuf v1.36.8/go.mod h1:fuxRtAxBytpl4zzqUh6/eyUujkJdNiuEkXntxiD/uRU= -gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= -gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= -gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= +go.yaml.in/yaml/v3 v3.0.5 h1:N6y/pJk8buWs9NY5ERU2HSMfm+IuD/OtfdAnq6kESPw= +go.yaml.in/yaml/v3 v3.0.5/go.mod h1:HVTZu1O7/Vkt2N+BFy8Zza+lnLsABggaTM2ZpNIGuKg= diff --git a/helpers_test.go b/helpers_test.go new file mode 100644 index 0000000..305829f --- /dev/null +++ b/helpers_test.go @@ -0,0 +1,131 @@ +package adaptivepool + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "strings" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +// newTestPool creates a pool that is shut down when the test ends. +func newTestPool(t *testing.T, opts ...Option) Pool { + t.Helper() + p, err := New(opts...) + require.NoError(t, err) + t.Cleanup(func() { + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + _ = p.Shutdown(ctx) + }) + return p +} + +func discardLogger() *slog.Logger { + return slog.New(slog.DiscardHandler) +} + +// logRecorder captures JSON log records written by the pool. +type logRecorder struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (r *logRecorder) Write(b []byte) (int, error) { + r.mu.Lock() + defer r.mu.Unlock() + return r.buf.Write(b) +} + +func (r *logRecorder) logger() *slog.Logger { + return slog.New(slog.NewJSONHandler(r, &slog.HandlerOptions{Level: slog.LevelDebug})) +} + +// records returns all captured records with the given message. +func (r *logRecorder) records(msg string) []map[string]any { + r.mu.Lock() + defer r.mu.Unlock() + var out []map[string]any + for _, line := range strings.Split(strings.TrimSpace(r.buf.String()), "\n") { + var rec map[string]any + if json.Unmarshal([]byte(line), &rec) == nil && rec["msg"] == msg { + out = append(out, rec) + } + } + return out +} + +// fakeRecorder captures recorder events in memory. +type fakeRecorder struct { + mu sync.Mutex + submitted []string + rejected []string // kind/reason + completed []completedEvent + dropped []string + scaledUp []int + + attachErr error + info *PoolInfo + stats Metrics + detached bool +} + +type completedEvent struct { + kind string + status Status + attempts int +} + +func (r *fakeRecorder) JobSubmitted(kind string) { + r.mu.Lock() + defer r.mu.Unlock() + r.submitted = append(r.submitted, kind) +} + +func (r *fakeRecorder) JobRejected(kind string, reason RejectReason) { + r.mu.Lock() + defer r.mu.Unlock() + r.rejected = append(r.rejected, kind+"/"+string(reason)) +} + +func (r *fakeRecorder) JobCompleted(kind string, status Status, attempts int, _, _ time.Duration) { + r.mu.Lock() + defer r.mu.Unlock() + r.completed = append(r.completed, completedEvent{kind, status, attempts}) +} + +func (r *fakeRecorder) JobDropped(kind string) { + r.mu.Lock() + defer r.mu.Unlock() + r.dropped = append(r.dropped, kind) +} + +func (r *fakeRecorder) ScaledUp(added int) { + r.mu.Lock() + defer r.mu.Unlock() + r.scaledUp = append(r.scaledUp, added) +} + +func (r *fakeRecorder) Attach(info PoolInfo, stats Metrics) error { + r.mu.Lock() + defer r.mu.Unlock() + r.info, r.stats = &info, stats + return r.attachErr +} + +func (r *fakeRecorder) Detach() { + r.mu.Lock() + defer r.mu.Unlock() + r.detached = true +} + +func (r *fakeRecorder) completedEvents() []completedEvent { + r.mu.Lock() + defer r.mu.Unlock() + return append([]completedEvent(nil), r.completed...) +} diff --git a/hook_test.go b/hook_test.go new file mode 100644 index 0000000..ee07267 --- /dev/null +++ b/hook_test.go @@ -0,0 +1,90 @@ +package adaptivepool + +import ( + "context" + "errors" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestOnTaskDone(t *testing.T) { + results := make(chan TaskResult, 3) + p := newTestPool(t, + WithMinWorkers(1), WithMaxWorkers(1), + WithLogger(discardLogger()), + WithOnTaskDone(func(r TaskResult) { results <- r }), + ) + + errBoom := errors.New("boom") + ctx := context.Background() + require.NoError(t, p.SubmitTask(ctx, Task{ID: "ok", Kind: "k", Run: func(context.Context) error { return nil }})) + require.NoError(t, p.SubmitTask(ctx, Task{ID: "fail", Kind: "k", Run: func(context.Context) error { return errBoom }})) + require.NoError(t, p.SubmitTask(ctx, Task{ID: "panic", Kind: "k", Run: func(context.Context) error { panic("bad") }})) + + got := map[string]TaskResult{} + for range 3 { + select { + case r := <-results: + got[r.ID] = r + case <-time.After(2 * time.Second): + t.Fatal("hook not called") + } + } + + assert.Equal(t, StatusSuccess, got["ok"].Status) + assert.NoError(t, got["ok"].Err) + assert.Equal(t, 1, got["ok"].Attempts) + assert.Equal(t, "k", got["ok"].Kind) + + assert.Equal(t, StatusError, got["fail"].Status) + assert.ErrorIs(t, got["fail"].Err, errBoom) + + assert.Equal(t, StatusPanic, got["panic"].Status) + var pe *PanicError + require.ErrorAs(t, got["panic"].Err, &pe) + assert.Equal(t, "bad", pe.Value) +} + +func TestOnTaskDonePanicDoesNotKillWorker(t *testing.T) { + var rec logRecorder + p := newTestPool(t, + WithMinWorkers(1), WithMaxWorkers(1), + WithLogger(rec.logger()), + WithOnTaskDone(func(TaskResult) { panic("hook bug") }), + ) + + for range 2 { + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { return nil })) + } + require.Eventually(t, func() bool { return len(rec.records("OnTaskDone hook panicked")) == 2 }, 2*time.Second, 10*time.Millisecond) + assert.Equal(t, 1, p.Metrics().ActiveWorkers()) +} + +func TestStatusCanceledWithoutRetries(t *testing.T) { + results := make(chan TaskResult, 2) + p := newTestPool(t, + WithMinWorkers(1), WithMaxWorkers(1), + WithLogger(discardLogger()), + WithOnTaskDone(func(r TaskResult) { results <- r }), + ) + + ctx, cancel := context.WithCancel(context.Background()) + require.NoError(t, p.SubmitTask(ctx, Task{ID: "canceled", Run: func(ctx context.Context) error { + cancel() + return ctx.Err() + }})) + require.NoError(t, p.SubmitTask(context.Background(), Task{ID: "error", Run: func(context.Context) error { + return context.Canceled // an inner operation's error while the job context is live + }})) + + got := map[string]Status{} + for range 2 { + r := <-results + got[r.ID] = r.Status + } + assert.Equal(t, StatusCanceled, got["canceled"]) + assert.Equal(t, StatusError, got["error"]) +} diff --git a/internal_types.go b/internal_types.go index 6385774..d206914 100644 --- a/internal_types.go +++ b/internal_types.go @@ -13,9 +13,10 @@ type Job func(ctx context.Context) error // jobWrapper wraps a job with metadata for tracking type jobWrapper struct { job Job - SubmittedAt time.Time - id uint64 ctx context.Context + taskID string + kind string + submittedAt int64 // nanoseconds since pool.epoch } // shutdownState represents the shutdown state of the pool @@ -33,34 +34,49 @@ type poolState struct { jobQueue chan jobWrapper // Worker management - workerWg sync.WaitGroup - workerCount atomic.Int32 - workerShutdown chan struct{} - - // Shutdown coordination - shutdownOnce sync.Once - shutdownState atomic.Int32 - shutdownDone chan struct{} + workerWg sync.WaitGroup + workerCount atomic.Int32 + busyWorkers atomic.Int32 + + // Shutdown coordination. Submit holds submitMu for reading while it + // checks the state and sends; Shutdown takes it for writing to close the + // queue, so no send can race the close. closing wakes Submits blocked on a + // full queue so they release the lock. + shutdownStarted atomic.Bool // set by the first Shutdown call, which runs it + shutdownErr error // its result, written before shutdownDone is closed + shutdownState atomic.Int32 + shutdownDone chan struct{} + closing chan struct{} // closed when Shutdown starts + forceStop chan struct{} // closed when Shutdown's context expires + submitMu sync.RWMutex // Scaling coordination scalingMu sync.Mutex lastScaleUp time.Time - - // Job ID generation - nextJobID atomic.Uint64 } // newPoolState Creates a new pool state func newPoolState(queueSize int) *poolState { ps := &poolState{ - jobQueue: make(chan jobWrapper, queueSize), - workerShutdown: make(chan struct{}), - shutdownDone: make(chan struct{}), + jobQueue: make(chan jobWrapper, queueSize), + shutdownDone: make(chan struct{}), + closing: make(chan struct{}), + forceStop: make(chan struct{}), } ps.shutdownState.Store(int32(shutdownStateRunning)) return ps } +// closed reports whether c is closed, without blocking +func closed(c <-chan struct{}) bool { + select { + case <-c: + return true + default: + return false + } +} + // isShutdown returns true if the pool is shutdown or draining func (ps *poolState) isShutdown() bool { state := shutdownState(ps.shutdownState.Load()) @@ -105,8 +121,3 @@ func (ps *poolState) getQueueUtilization() float64 { } return float64(ps.getQueueDepth()) / float64(capacity) } - -// nextID generates the next job ID -func (ps *poolState) nextID() uint64 { - return ps.nextJobID.Add(1) -} diff --git a/logging_test.go b/logging_test.go new file mode 100644 index 0000000..4313641 --- /dev/null +++ b/logging_test.go @@ -0,0 +1,59 @@ +package adaptivepool + +import ( + "context" + "errors" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestLogsTaskFailure(t *testing.T) { + var rec logRecorder + p := newTestPool(t, WithName("emails"), WithLogger(rec.logger())) + + err := p.SubmitTask(context.Background(), Task{ + ID: "order-42", + Kind: "send_email", + Run: func(context.Context) error { return errors.New("smtp down") }, + }) + require.NoError(t, err) + + require.Eventually(t, func() bool { return len(rec.records("task failed")) == 1 }, 2*time.Second, 10*time.Millisecond) + r := rec.records("task failed")[0] + assert.Equal(t, "ERROR", r["level"]) + assert.Equal(t, "emails", r["pool"]) + assert.Equal(t, "order-42", r["task_id"]) + assert.Equal(t, "send_email", r["kind"]) + assert.Equal(t, "error", r["status"]) + assert.Equal(t, "smtp down", r["err"]) +} + +func TestLogsTaskPanicWithStack(t *testing.T) { + var rec logRecorder + p := newTestPool(t, WithLogger(rec.logger())) + + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { panic("boom") })) + + require.Eventually(t, func() bool { return len(rec.records("task failed")) == 1 }, 2*time.Second, 10*time.Millisecond) + r := rec.records("task failed")[0] + assert.Equal(t, "panic", r["status"]) + assert.Equal(t, "job panicked: boom", r["err"]) + assert.Contains(t, r["stack"], "runJob") +} + +func TestLogsShutdownWithPoolName(t *testing.T) { + var rec logRecorder + p, err := New(WithName("emails"), WithLogger(rec.logger())) + require.NoError(t, err) + + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + require.NoError(t, p.Shutdown(ctx)) + + records := rec.records("initiating pool shutdown") + require.Len(t, records, 1) + assert.Equal(t, "emails", records[0]["pool"]) +} diff --git a/metrics.go b/metrics.go index cc65cc2..0490695 100644 --- a/metrics.go +++ b/metrics.go @@ -1,10 +1,10 @@ package adaptivepool import ( + "log/slog" + "runtime/debug" "sync/atomic" "time" - - "github.com/prometheus/client_golang/prometheus" ) // Metrics provides observability into pool behavior @@ -15,77 +15,58 @@ type Metrics interface { // ActiveWorkers returns the current number of active workers ActiveWorkers() int + // BusyWorkers returns the number of workers currently executing a job + BusyWorkers() int + // JobsProcessed returns the total number of jobs processed JobsProcessed() int64 + // JobsFailed returns the number of processed jobs that ended with an error or panic + JobsFailed() int64 + // JobsRejected returns the total number of jobs rejected JobsRejected() int64 - // AvgJobLatency returns the average job latency + // JobsDropped returns the number of queued jobs a forced shutdown discarded without running + JobsDropped() int64 + + // JobsRetried returns the number of processed jobs that needed at least one retry + JobsRetried() int64 + + // RetryAttempts returns the total number of retries across all jobs + RetryAttempts() int64 + + // AvgJobLatency returns the average job execution time AvgJobLatency() time.Duration + + // AvgQueueWait returns the average time jobs spent queued before execution + AvgQueueWait() time.Duration } -// metrics implements the Metrics interface with Prometheus integration +// metrics implements Metrics with always-on atomic counters and forwards +// events to an optional recorder type metrics struct { - enabled bool - - // Internal counters (always tracked) - jobsProcessed atomic.Int64 - jobsRejected atomic.Int64 - totalLatency atomic.Int64 // in nanoseconds + jobsProcessed atomic.Int64 + jobsFailed atomic.Int64 + jobsRejected atomic.Int64 + jobsDropped atomic.Int64 + jobsRetried atomic.Int64 + retryAttempts atomic.Int64 + totalLatency atomic.Int64 // in nanoseconds + totalQueueWait atomic.Int64 // in nanoseconds // Reference to pool state for current values state *poolState - // Prometheus metrics (optional) - promQueueDepth prometheus.Gauge - promActiveWorkers prometheus.Gauge - promJobsProcessed prometheus.Counter - promJobsRejected prometheus.Counter - promJobLatency prometheus.Histogram -} - -// newMetrics Creates a new metrics collector -func newMetrics(state *poolState, enabled bool, namespace string) *metrics { - m := &metrics{ - enabled: enabled, - state: state, - } + rec Recorder // nil when no recorder is configured + detached atomic.Bool // set when the recorder is detached; later events are dropped - if enabled { - m.promQueueDepth = prometheus.NewGauge(prometheus.GaugeOpts{ - Namespace: namespace, - Name: "queue_depth", - Help: "Current number of jobs in the queue", - }) - - m.promActiveWorkers = prometheus.NewGauge(prometheus.GaugeOpts{ - Namespace: namespace, - Name: "active_workers", - Help: "Current number of active workers", - }) - - m.promJobsProcessed = prometheus.NewCounter(prometheus.CounterOpts{ - Namespace: namespace, - Name: "jobs_processed_total", - Help: "Total number of jobs processed", - }) - - m.promJobsRejected = prometheus.NewCounter(prometheus.CounterOpts{ - Namespace: namespace, - Name: "jobs_rejected_total", - Help: "Total number of jobs rejected", - }) - - m.promJobLatency = prometheus.NewHistogram(prometheus.HistogramOpts{ - Namespace: namespace, - Name: "job_latency_seconds", - Help: "Job execution latency in seconds", - Buckets: prometheus.DefBuckets, - }) - } + logger *slog.Logger + panicReported atomic.Bool // only the first recorder panic is logged +} - return m +func newMetrics(state *poolState, rec Recorder, logger *slog.Logger) *metrics { + return &metrics{state: state, rec: rec, logger: logger} } // QueueDepth returns the current queue depth @@ -98,50 +79,156 @@ func (m *metrics) ActiveWorkers() int { return m.state.getWorkerCount() } +// BusyWorkers returns the number of workers currently executing a job +func (m *metrics) BusyWorkers() int { + return int(m.state.busyWorkers.Load()) +} + // JobsProcessed returns the total number of jobs processed func (m *metrics) JobsProcessed() int64 { return m.jobsProcessed.Load() } +// JobsFailed returns the number of processed jobs that did not succeed +func (m *metrics) JobsFailed() int64 { + return m.jobsFailed.Load() +} + // JobsRejected returns the total number of jobs rejected func (m *metrics) JobsRejected() int64 { return m.jobsRejected.Load() } -// AvgJobLatency returns the average job latency +// JobsRetried returns the number of jobs that needed at least one retry +func (m *metrics) JobsRetried() int64 { + return m.jobsRetried.Load() +} + +// RetryAttempts returns the total number of retries across all jobs +func (m *metrics) RetryAttempts() int64 { + return m.retryAttempts.Load() +} + +// JobsDropped returns the number of queued jobs dropped by a forced shutdown +func (m *metrics) JobsDropped() int64 { + return m.jobsDropped.Load() +} + +// AvgJobLatency returns the average job execution time func (m *metrics) AvgJobLatency() time.Duration { - processed := m.jobsProcessed.Load() - if processed == 0 { + return average(m.totalLatency.Load(), m.jobsProcessed.Load()) +} + +// AvgQueueWait returns the average time jobs spent queued +func (m *metrics) AvgQueueWait() time.Duration { + return average(m.totalQueueWait.Load(), m.jobsProcessed.Load()) +} + +func average(totalNs, n int64) time.Duration { + if n == 0 { return 0 } - totalNs := m.totalLatency.Load() - return time.Duration(totalNs / processed) + return time.Duration(totalNs / n) } -// recordJobProcessed records a processed job with its latency -func (m *metrics) recordJobProcessed(latency time.Duration) { - m.jobsProcessed.Add(1) - m.totalLatency.Add(int64(latency)) +// recoverRecorder is deferred around every recorder call: a recorder that +// panics must not kill a worker or the caller, or leave Shutdown hanging. +// Only the first panic is logged, so a recorder that always panics doesn't +// flood the log. +func (m *metrics) recoverRecorder(method string) { + if r := recover(); r != nil && m.panicReported.CompareAndSwap(false, true) { + m.logger.Error("recorder panicked; later panics are ignored without logging", + slog.String("method", method), + slog.Any("panic", r), + slog.String("stack", string(debug.Stack())), + ) + } +} - if m.enabled { - m.promJobsProcessed.Inc() - m.promJobLatency.Observe(latency.Seconds()) +// detach stops reporting to the recorder and detaches it +func (m *metrics) detach() { + m.detached.Store(true) + if a, ok := m.rec.(Attacher); ok { + m.detachRecorder(a) } } +func (m *metrics) detachRecorder(a Attacher) { + defer m.recoverRecorder("Detach") + a.Detach() +} + +// recordJobSubmitted records a job accepted into the queue +func (m *metrics) recordJobSubmitted(kind string) { + if m.rec != nil && !m.detached.Load() { + m.reportSubmitted(kind) + } +} + +func (m *metrics) reportSubmitted(kind string) { + defer m.recoverRecorder("JobSubmitted") + m.rec.JobSubmitted(normalizeKind(kind)) +} + // recordJobRejected records a rejected job -func (m *metrics) recordJobRejected() { +func (m *metrics) recordJobRejected(kind string, reason RejectReason) { m.jobsRejected.Add(1) + if m.rec != nil && !m.detached.Load() { + m.reportRejected(kind, reason) + } +} + +func (m *metrics) reportRejected(kind string, reason RejectReason) { + defer m.recoverRecorder("JobRejected") + m.rec.JobRejected(normalizeKind(kind), reason) +} - if m.enabled { - m.promJobsRejected.Inc() +// recordJobDone records a finished job. Retry counters are derived from the +// attempt count here rather than per retry, keeping the retry loop free of +// metric updates. +func (m *metrics) recordJobDone(kind string, status Status, attempts int, queueWait, duration time.Duration) { + m.jobsProcessed.Add(1) + m.totalLatency.Add(int64(duration)) + m.totalQueueWait.Add(int64(queueWait)) + if status != StatusSuccess { + m.jobsFailed.Add(1) + } + if retries := attempts - 1; retries > 0 { + m.jobsRetried.Add(1) + m.retryAttempts.Add(int64(retries)) + } + if m.rec != nil && !m.detached.Load() { + m.reportCompleted(kind, status, attempts, queueWait, duration) } } -// updateGauges updates the gauge metrics -func (m *metrics) updateGauges() { - if m.enabled { - m.promQueueDepth.Set(float64(m.QueueDepth())) - m.promActiveWorkers.Set(float64(m.ActiveWorkers())) +func (m *metrics) reportCompleted(kind string, status Status, attempts int, queueWait, duration time.Duration) { + defer m.recoverRecorder("JobCompleted") + m.rec.JobCompleted(normalizeKind(kind), status, attempts, queueWait, duration) +} + +// recordJobDropped records a queued job discarded by a forced shutdown. It +// isn't counted as processed, so it doesn't skew the latency averages. +func (m *metrics) recordJobDropped(kind string) { + m.jobsDropped.Add(1) + if m.rec != nil && !m.detached.Load() { + m.reportDropped(kind) } } + +func (m *metrics) reportDropped(kind string) { + defer m.recoverRecorder("JobDropped") + m.rec.JobDropped(normalizeKind(kind)) +} + +// recordScaleUp records a scale-up event +func (m *metrics) recordScaleUp(added int) { + if m.rec != nil && !m.detached.Load() { + m.reportScaleUp(added) + } +} + +func (m *metrics) reportScaleUp(added int) { + defer m.recoverRecorder("ScaledUp") + m.rec.ScaledUp(added) +} diff --git a/metrics_test.go b/metrics_test.go new file mode 100644 index 0000000..dc05bba --- /dev/null +++ b/metrics_test.go @@ -0,0 +1,36 @@ +package adaptivepool + +import ( + "context" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestBusyWorkers(t *testing.T) { + p := newTestPool(t, WithMinWorkers(2), WithMaxWorkers(2)) + + release := make(chan struct{}) + for range 2 { + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { + <-release + return nil + })) + } + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 2 }, 2*time.Second, 10*time.Millisecond) + close(release) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 0 }, 2*time.Second, 10*time.Millisecond) + assert.Positive(t, p.Metrics().AvgQueueWait()+p.Metrics().AvgJobLatency()) +} + +// WithMetricsEnabled is kept as a deprecated no-op so existing callers keep +// compiling; in-process metrics are always on. +func TestWithMetricsEnabledIsANoOp(t *testing.T) { + for _, enabled := range []bool{true, false} { + p := newTestPool(t, WithLogger(discardLogger()), WithMetricsEnabled(enabled)) + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { return nil })) + require.Eventually(t, func() bool { return p.Metrics().JobsProcessed() == 1 }, 2*time.Second, time.Millisecond) + } +} diff --git a/options.go b/options.go index 67e0e21..35f7ea1 100644 --- a/options.go +++ b/options.go @@ -1,6 +1,7 @@ package adaptivepool import ( + "log/slog" "runtime" "time" ) @@ -12,8 +13,12 @@ type Config struct { queueSize int scaleUpThreshold float64 scaleDownIdleDuration time.Duration - metricsEnabled bool scaleCooldown time.Duration + name string + logger *slog.Logger + recorder Recorder + onTaskDone func(TaskResult) + retry *RetryPolicy } // Option is a functional option for configuring the pool @@ -59,12 +64,13 @@ func WithScaleDownIdleDuration(d time.Duration) Option { } } -// WithMetricsEnabled enables or disables metrics collection -// Default: true -func WithMetricsEnabled(enabled bool) Option { - return func(c *Config) { - c.metricsEnabled = enabled - } +// WithMetricsEnabled has no effect. +// +// Deprecated: the pool always keeps in-process metrics, available through +// Metrics(). To export them, use WithRecorder, e.g. +// WithRecorder(promrecorder.New(reg)). +func WithMetricsEnabled(bool) Option { + return func(*Config) {} } // WithScaleCooldown sets the minimum duration between scaling operations @@ -75,6 +81,36 @@ func WithScaleCooldown(d time.Duration) Option { } } +// WithName names the pool. The name is attached to every log record and +// passed to recorders in PoolInfo, so multiple pools in one process can be +// told apart. +// Default: "" (unnamed) +func WithName(name string) Option { + return func(c *Config) { + c.name = name + } +} + +// WithOnTaskDone sets a hook called exactly once per executed task, whatever +// the outcome, and once per queued task dropped by a forced shutdown. It lets application code react to results (dead-letter queues, +// status updates, tracing) since Submit returns before the task runs. +// +// The hook runs synchronously on the worker goroutine, so keep it fast and +// hand off heavy work. A panic in the hook is recovered and logged. +func WithOnTaskDone(fn func(TaskResult)) Option { + return func(c *Config) { + c.onTaskDone = fn + } +} + +// WithLogger sets the structured logger used by the pool. +// Default: slog.Default() +func WithLogger(l *slog.Logger) Option { + return func(c *Config) { + c.logger = l + } +} + // defaultConfig returns the default configuration func defaultConfig() *Config { return &Config{ @@ -83,7 +119,6 @@ func defaultConfig() *Config { queueSize: 1000, scaleUpThreshold: 0.7, scaleDownIdleDuration: 30 * time.Second, - metricsEnabled: true, scaleCooldown: 5 * time.Second, } } @@ -108,5 +143,8 @@ func (c *Config) validate() error { if c.scaleCooldown < 0 { return ErrInvalidConfig } + if c.retry != nil { + return c.retry.validate() + } return nil } diff --git a/otelrecorder/go.mod b/otelrecorder/go.mod new file mode 100644 index 0000000..e93cb89 --- /dev/null +++ b/otelrecorder/go.mod @@ -0,0 +1,28 @@ +module github.com/iyashjayesh/go-adaptive-pool/otelrecorder + +go 1.25.0 + +require ( + github.com/iyashjayesh/go-adaptive-pool v0.0.0 + github.com/stretchr/testify v1.12.1 + go.opentelemetry.io/otel v1.46.0 + go.opentelemetry.io/otel/metric v1.46.0 + go.opentelemetry.io/otel/sdk/metric v1.46.0 + go.uber.org/goleak v1.3.0 +) + +require ( + github.com/cespare/xxhash/v2 v2.3.0 // indirect + github.com/go-logr/logr v1.4.4 // indirect + github.com/go-logr/stdr v1.2.2 // indirect + github.com/google/uuid v1.6.0 // indirect + go.opentelemetry.io/auto/sdk v1.2.1 // indirect + go.opentelemetry.io/otel/sdk v1.46.0 // indirect + go.opentelemetry.io/otel/trace v1.46.0 // indirect + go.yaml.in/yaml/v3 v3.0.5 // indirect + golang.org/x/sys v0.47.0 // indirect +) + +// The core has no release with the Recorder API yet. Remove this before +// tagging, once go.mod requires a published core version (see CONTRIBUTING.md). +replace github.com/iyashjayesh/go-adaptive-pool => ../ diff --git a/otelrecorder/go.sum b/otelrecorder/go.sum new file mode 100644 index 0000000..c24af50 --- /dev/null +++ b/otelrecorder/go.sum @@ -0,0 +1,33 @@ +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= +github.com/go-logr/logr v1.2.2/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +github.com/go-logr/logr v1.4.4 h1:tG4xh9yMsRCAiodLVTxyrkzSZ9+o0L1Kg/+cPVcbP/8= +github.com/go-logr/logr v1.4.4/go.mod h1:9T104GzyrTigFIr8wt5mBrctHMim0Nb2HLGrmQ40KvY= +github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= +github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= +github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= +github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= +github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= +github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= +github.com/stretchr/testify v1.12.1 h1:EuwCh5fleGS7H32xRwO3wRGT7DxrDhLAT6FF8MpWDWE= +github.com/stretchr/testify v1.12.1/go.mod h1:MDEgiDPPsNp5cuIrHPPCyornHKgEVbtFUmoNlxoYthg= +go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= +go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= +go.opentelemetry.io/otel v1.46.0 h1:FHt5/CDyVxi/8IM1CH7VE/rRgq3kLHa2mSTVMO8AWyc= +go.opentelemetry.io/otel v1.46.0/go.mod h1:Gj3SEScelsNC45tp4nSxRYlS+f5iez7W8XPMCt905kE= +go.opentelemetry.io/otel/metric v1.46.0 h1:yBnkXvgV7AXFILZc5K6IZe/CBFF3OS7BJ8ov6/lj0K8= +go.opentelemetry.io/otel/metric v1.46.0/go.mod h1:iPmdWqifKUdzziPkvvzIJXITl56fQx2mGM/DHLB3/2o= +go.opentelemetry.io/otel/metric/x v0.68.0 h1:TA/cBT23D3MnxYPwHL7YFOdYGdx0A0v+s7Mzotpd1dU= +go.opentelemetry.io/otel/metric/x v0.68.0/go.mod h1:agudOmvWhwUTjgibWDzxD2PoWYnpw5Ht5jISYOD2Hd4= +go.opentelemetry.io/otel/sdk v1.46.0 h1:h5CNQQjEbuQXY/JfZtgt3i7HVFV3aHPO2OAwO2eTYPI= +go.opentelemetry.io/otel/sdk v1.46.0/go.mod h1:GAERFXFt5SYCEB+YiKUbMBeza6UaDH7GmGOZEfh2gSM= +go.opentelemetry.io/otel/sdk/metric v1.46.0 h1:0piZ26EG4RBfebb2jhDH6ERCYHoVWduc3kLgPCwSnSE= +go.opentelemetry.io/otel/sdk/metric v1.46.0/go.mod h1:I1PbKrdVc8Qu8HYVDNtqVIwLwjNrhsV/uFuxfwg8mO4= +go.opentelemetry.io/otel/trace v1.46.0 h1:OULy7ccdJnZtJ0UDYFOIGaCmiWzJ8Vi2G/Rsu60qs1c= +go.opentelemetry.io/otel/trace v1.46.0/go.mod h1:J7GAXweO77XSFkB/rmAqk9D6ihszhFjLU+d9WuUxDLI= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= +go.yaml.in/yaml/v3 v3.0.5 h1:N6y/pJk8buWs9NY5ERU2HSMfm+IuD/OtfdAnq6kESPw= +go.yaml.in/yaml/v3 v3.0.5/go.mod h1:HVTZu1O7/Vkt2N+BFy8Zza+lnLsABggaTM2ZpNIGuKg= +golang.org/x/sys v0.47.0 h1:o7XGOvZQCADBQQ4Y7VNq2dRWQR7JmOUW8Kxx4ZsNgWs= +golang.org/x/sys v0.47.0/go.mod h1:4GL1E5IUh+htKOUEOaiffhrAeqysfVGipDYzABqnCmw= diff --git a/otelrecorder/otelrecorder.go b/otelrecorder/otelrecorder.go new file mode 100644 index 0000000..a970296 --- /dev/null +++ b/otelrecorder/otelrecorder.go @@ -0,0 +1,292 @@ +// Package otelrecorder exports adaptive pool metrics through OpenTelemetry, +// so they can reach any backend with an OpenTelemetry exporter or the +// OpenTelemetry Collector. +// +// pool, err := adaptivepool.New( +// adaptivepool.WithName("orders"), +// adaptivepool.WithRecorder(otelrecorder.New(meterProvider)), +// ) +// +// Metric names, units and attributes follow the OpenTelemetry semantic +// conventions, modelled on the database connection pool metrics +// (db.client.connection.*): +// +// adaptivepool.worker.count UpDownCounter {worker} adaptivepool.worker.state = idle | busy +// adaptivepool.worker.limit UpDownCounter {worker} +// adaptivepool.worker.min UpDownCounter {worker} +// adaptivepool.queue.usage UpDownCounter {job} +// adaptivepool.queue.limit UpDownCounter {job} +// adaptivepool.job.submissions Counter {submission} adaptivepool.job.kind +// adaptivepool.job.rejections Counter {rejection} adaptivepool.job.kind, adaptivepool.rejection.reason +// adaptivepool.job.duration Histogram s adaptivepool.job.kind, adaptivepool.job.status +// adaptivepool.job.wait_time Histogram s adaptivepool.job.kind +// adaptivepool.job.retries Counter {retry} adaptivepool.job.kind +// adaptivepool.worker.scale_ups Counter {scale_up} +// +// Every metric carries adaptivepool.pool.name. Completed jobs are counted by +// the job.duration histogram, broken down by status. +package otelrecorder + +import ( + "context" + "errors" + "sync" + "sync/atomic" + "time" + + adaptivepool "github.com/iyashjayesh/go-adaptive-pool" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/metric" +) + +const instrumentationName = "github.com/iyashjayesh/go-adaptive-pool/otelrecorder" + +// Attribute keys +const ( + PoolNameKey = attribute.Key("adaptivepool.pool.name") + JobKindKey = attribute.Key("adaptivepool.job.kind") + JobStatusKey = attribute.Key("adaptivepool.job.status") + RejectionReasonKey = attribute.Key("adaptivepool.rejection.reason") + WorkerStateKey = attribute.Key("adaptivepool.worker.state") +) + +// durationBuckets are the explicit bucket boundaries, in seconds, +// recommended by the semantic conventions for duration histograms. +var durationBuckets = []float64{0.005, 0.01, 0.025, 0.05, 0.075, 0.1, 0.25, 0.5, 0.75, 1, 2.5, 5, 7.5, 10} + +// ErrAlreadyAttached is returned when a Recorder is used by a second pool +// while the first is still running. +var ErrAlreadyAttached = errors.New("otelrecorder: recorder already attached to a pool") + +// Recorder exports pool events as OpenTelemetry metrics. Use one Recorder +// per pool. +type Recorder struct { + provider metric.MeterProvider + attached atomic.Bool + + // state holds the instruments of the attached pool, nil when detached. + // Each event loads it once, so Attach and Detach never race with recording. + state atomic.Pointer[state] +} + +type state struct { + poolAttr attribute.KeyValue + submissions metric.Int64Counter + rejections metric.Int64Counter + dropped metric.Int64Counter + duration metric.Float64Histogram + waitTime metric.Float64Histogram + retries metric.Int64Counter + scaleUps metric.Int64Counter + scaleUpOpts []metric.AddOption + registration metric.Registration + + // kinds caches each kind's precomputed measurement options + // (*kindOptions), so recording does not allocate attribute sets. + kinds sync.Map +} + +type kindOptions struct { + add []metric.AddOption // pool, kind + record []metric.RecordOption // pool, kind + byStatus sync.Map // adaptivepool.Status -> []metric.RecordOption + byReason sync.Map // adaptivepool.RejectReason -> []metric.AddOption +} + +var ( + _ adaptivepool.Recorder = (*Recorder)(nil) + _ adaptivepool.Attacher = (*Recorder)(nil) +) + +// New returns a Recorder that creates its instruments from provider. A nil +// provider uses the global one (otel.GetMeterProvider). +func New(provider metric.MeterProvider) *Recorder { + if provider == nil { + provider = otel.GetMeterProvider() + } + return &Recorder{provider: provider} +} + +// Attach creates the instruments and registers the callback that reports +// worker and queue gauges. It is called by adaptivepool.New. +func (r *Recorder) Attach(info adaptivepool.PoolInfo, stats adaptivepool.Metrics) error { + if !r.attached.CompareAndSwap(false, true) { + return ErrAlreadyAttached + } + s, err := r.register(info, stats) + if err != nil { + r.attached.Store(false) + return err + } + r.state.Store(s) + return nil +} + +func (r *Recorder) register(info adaptivepool.PoolInfo, stats adaptivepool.Metrics) (*state, error) { + meter := r.provider.Meter(instrumentationName) + s := &state{poolAttr: PoolNameKey.String(info.Name)} + s.scaleUpOpts = []metric.AddOption{metric.WithAttributeSet(attribute.NewSet(s.poolAttr))} + + var err error + if s.submissions, err = meter.Int64Counter("adaptivepool.job.submissions", + metric.WithUnit("{submission}"), metric.WithDescription("Jobs accepted into the queue")); err != nil { + return nil, err + } + if s.rejections, err = meter.Int64Counter("adaptivepool.job.rejections", + metric.WithUnit("{rejection}"), metric.WithDescription("Jobs rejected at submission")); err != nil { + return nil, err + } + if s.dropped, err = meter.Int64Counter("adaptivepool.job.dropped", + metric.WithUnit("{job}"), metric.WithDescription("Queued jobs a forced shutdown discarded without running")); err != nil { + return nil, err + } + if s.duration, err = meter.Float64Histogram("adaptivepool.job.duration", + metric.WithUnit("s"), metric.WithDescription("Job execution time, including retries"), + metric.WithExplicitBucketBoundaries(durationBuckets...)); err != nil { + return nil, err + } + if s.waitTime, err = meter.Float64Histogram("adaptivepool.job.wait_time", + metric.WithUnit("s"), metric.WithDescription("Time jobs spent queued before execution"), + metric.WithExplicitBucketBoundaries(durationBuckets...)); err != nil { + return nil, err + } + if s.retries, err = meter.Int64Counter("adaptivepool.job.retries", + metric.WithUnit("{retry}"), metric.WithDescription("Retries performed across all jobs")); err != nil { + return nil, err + } + if s.scaleUps, err = meter.Int64Counter("adaptivepool.worker.scale_ups", + metric.WithUnit("{scale_up}"), metric.WithDescription("Number of scale-up events")); err != nil { + return nil, err + } + + workers, err := meter.Int64ObservableUpDownCounter("adaptivepool.worker.count", + metric.WithUnit("{worker}"), metric.WithDescription("Workers by state")) + if err != nil { + return nil, err + } + workerLimit, err := meter.Int64ObservableUpDownCounter("adaptivepool.worker.limit", + metric.WithUnit("{worker}"), metric.WithDescription("Maximum number of workers")) + if err != nil { + return nil, err + } + workerMin, err := meter.Int64ObservableUpDownCounter("adaptivepool.worker.min", + metric.WithUnit("{worker}"), metric.WithDescription("Minimum number of workers")) + if err != nil { + return nil, err + } + queueUsage, err := meter.Int64ObservableUpDownCounter("adaptivepool.queue.usage", + metric.WithUnit("{job}"), metric.WithDescription("Jobs waiting in the queue")) + if err != nil { + return nil, err + } + queueLimit, err := meter.Int64ObservableUpDownCounter("adaptivepool.queue.limit", + metric.WithUnit("{job}"), metric.WithDescription("Capacity of the queue")) + if err != nil { + return nil, err + } + + pool := metric.WithAttributeSet(attribute.NewSet(s.poolAttr)) + idle := metric.WithAttributeSet(attribute.NewSet(s.poolAttr, WorkerStateKey.String("idle"))) + busy := metric.WithAttributeSet(attribute.NewSet(s.poolAttr, WorkerStateKey.String("busy"))) + s.registration, err = meter.RegisterCallback(func(_ context.Context, o metric.Observer) error { + active, inUse := stats.ActiveWorkers(), stats.BusyWorkers() + o.ObserveInt64(workers, int64(max(active-inUse, 0)), idle) + o.ObserveInt64(workers, int64(inUse), busy) + o.ObserveInt64(workerLimit, int64(info.MaxWorkers), pool) + o.ObserveInt64(workerMin, int64(info.MinWorkers), pool) + o.ObserveInt64(queueUsage, int64(stats.QueueDepth()), pool) + o.ObserveInt64(queueLimit, int64(info.QueueSize), pool) + return nil + }, workers, workerLimit, workerMin, queueUsage, queueLimit) + if err != nil { + return nil, err + } + return s, nil +} + +// Detach unregisters the gauge callback and drops later events. It is called +// when the pool shuts down, after which the Recorder may be attached to a new +// pool. +func (r *Recorder) Detach() { + s := r.state.Swap(nil) + if s == nil { + return + } + _ = s.registration.Unregister() + r.attached.Store(false) +} + +// options returns the cached measurement options for kind +func (s *state) options(kind string) *kindOptions { + if o, ok := s.kinds.Load(kind); ok { + return o.(*kindOptions) + } + opt := metric.WithAttributeSet(attribute.NewSet(s.poolAttr, JobKindKey.String(kind))) + o, _ := s.kinds.LoadOrStore(kind, &kindOptions{ + add: []metric.AddOption{opt}, + record: []metric.RecordOption{opt}, + }) + return o.(*kindOptions) +} + +func (s *state) statusOptions(o *kindOptions, kind string, status adaptivepool.Status) []metric.RecordOption { + if v, ok := o.byStatus.Load(status); ok { + return v.([]metric.RecordOption) + } + set := attribute.NewSet(s.poolAttr, JobKindKey.String(kind), JobStatusKey.String(string(status))) + v, _ := o.byStatus.LoadOrStore(status, []metric.RecordOption{metric.WithAttributeSet(set)}) + return v.([]metric.RecordOption) +} + +func (s *state) reasonOptions(o *kindOptions, kind string, reason adaptivepool.RejectReason) []metric.AddOption { + if v, ok := o.byReason.Load(reason); ok { + return v.([]metric.AddOption) + } + set := attribute.NewSet(s.poolAttr, JobKindKey.String(kind), RejectionReasonKey.String(string(reason))) + v, _ := o.byReason.LoadOrStore(reason, []metric.AddOption{metric.WithAttributeSet(set)}) + return v.([]metric.AddOption) +} + +// JobSubmitted implements adaptivepool.Recorder +func (r *Recorder) JobSubmitted(kind string) { + if s := r.state.Load(); s != nil { + s.submissions.Add(context.Background(), 1, s.options(kind).add...) + } +} + +// JobRejected implements adaptivepool.Recorder +func (r *Recorder) JobRejected(kind string, reason adaptivepool.RejectReason) { + if s := r.state.Load(); s != nil { + s.rejections.Add(context.Background(), 1, s.reasonOptions(s.options(kind), kind, reason)...) + } +} + +// JobCompleted implements adaptivepool.Recorder +func (r *Recorder) JobCompleted(kind string, status adaptivepool.Status, attempts int, queueWait, duration time.Duration) { + s := r.state.Load() + if s == nil { + return + } + ctx := context.Background() + o := s.options(kind) + s.duration.Record(ctx, duration.Seconds(), s.statusOptions(o, kind, status)...) + s.waitTime.Record(ctx, queueWait.Seconds(), o.record...) + if retries := attempts - 1; retries > 0 { + s.retries.Add(ctx, int64(retries), o.add...) + } +} + +// JobDropped implements adaptivepool.Recorder +func (r *Recorder) JobDropped(kind string) { + if s := r.state.Load(); s != nil { + s.dropped.Add(context.Background(), 1, s.options(kind).add...) + } +} + +// ScaledUp implements adaptivepool.Recorder +func (r *Recorder) ScaledUp(int) { + if s := r.state.Load(); s != nil { + s.scaleUps.Add(context.Background(), 1, s.scaleUpOpts...) + } +} diff --git a/otelrecorder/otelrecorder_test.go b/otelrecorder/otelrecorder_test.go new file mode 100644 index 0000000..9052940 --- /dev/null +++ b/otelrecorder/otelrecorder_test.go @@ -0,0 +1,312 @@ +package otelrecorder + +import ( + "context" + "errors" + "log/slog" + "sync" + "testing" + "time" + + adaptivepool "github.com/iyashjayesh/go-adaptive-pool" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/attribute" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + "go.uber.org/goleak" +) + +func TestMain(m *testing.M) { + goleak.VerifyTestMain(m) +} + +// collector reads metrics from an in-memory reader +type collector struct { + t *testing.T + reader *sdkmetric.ManualReader +} + +func newCollector(t *testing.T) (*collector, *sdkmetric.MeterProvider) { + reader := sdkmetric.NewManualReader() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + t.Cleanup(func() { _ = mp.Shutdown(context.Background()) }) + return &collector{t: t, reader: reader}, mp +} + +func (c *collector) metric(name string) (metricdata.Metrics, bool) { + var rm metricdata.ResourceMetrics + require.NoError(c.t, c.reader.Collect(context.Background(), &rm)) + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name == name { + return m, true + } + } + } + return metricdata.Metrics{}, false +} + +// sum returns the int64 sum data point value matching attrs +func (c *collector) sum(name string, attrs ...attribute.KeyValue) int64 { + m, ok := c.metric(name) + require.True(c.t, ok, "metric %s not found", name) + want := attribute.NewSet(attrs...) + for _, dp := range m.Data.(metricdata.Sum[int64]).DataPoints { + if dp.Attributes.Equals(&want) { + return dp.Value + } + } + c.t.Fatalf("no %s data point with %v", name, attrs) + return 0 +} + +// histogramCount returns the observation count of the data point matching attrs +func (c *collector) histogramCount(name string, attrs ...attribute.KeyValue) uint64 { + m, ok := c.metric(name) + require.True(c.t, ok, "metric %s not found", name) + want := attribute.NewSet(attrs...) + for _, dp := range m.Data.(metricdata.Histogram[float64]).DataPoints { + if dp.Attributes.Equals(&want) { + return dp.Count + } + } + c.t.Fatalf("no %s data point with %v", name, attrs) + return 0 +} + +func newPool(t *testing.T, opts ...adaptivepool.Option) adaptivepool.Pool { + t.Helper() + opts = append([]adaptivepool.Option{adaptivepool.WithLogger(slog.New(slog.DiscardHandler))}, opts...) + p, err := adaptivepool.New(opts...) + require.NoError(t, err) + t.Cleanup(func() { + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + _ = p.Shutdown(ctx) + }) + return p +} + +func TestInstrumentsFollowSemanticConventions(t *testing.T) { + c, mp := newCollector(t) + p := newPool(t, adaptivepool.WithName("orders"), adaptivepool.WithRecorder(New(mp))) + require.NoError(t, p.SubmitTask(context.Background(), adaptivepool.Task{Kind: "email", Run: func(context.Context) error { return nil }})) + require.Eventually(t, func() bool { return p.Metrics().JobsProcessed() == 1 }, 2*time.Second, time.Millisecond) + + units := map[string]string{ + "adaptivepool.worker.count": "{worker}", + "adaptivepool.worker.limit": "{worker}", + "adaptivepool.worker.min": "{worker}", + "adaptivepool.queue.usage": "{job}", + "adaptivepool.queue.limit": "{job}", + "adaptivepool.job.submissions": "{submission}", + "adaptivepool.job.duration": "s", + "adaptivepool.job.wait_time": "s", + } + for name, unit := range units { + m, ok := c.metric(name) + if assert.True(t, ok, name) { + assert.Equal(t, unit, m.Unit, name) + } + } +} + +func TestGauges(t *testing.T) { + c, mp := newCollector(t) + p := newPool(t, adaptivepool.WithName("orders"), + adaptivepool.WithMinWorkers(2), adaptivepool.WithMaxWorkers(4), adaptivepool.WithQueueSize(10), + adaptivepool.WithRecorder(New(mp))) + + release := make(chan struct{}) + defer close(release) + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { <-release; return nil })) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, 2*time.Second, time.Millisecond) + + pool := PoolNameKey.String("orders") + assert.Equal(t, int64(1), c.sum("adaptivepool.worker.count", pool, WorkerStateKey.String("busy"))) + assert.Equal(t, int64(1), c.sum("adaptivepool.worker.count", pool, WorkerStateKey.String("idle"))) + assert.Equal(t, int64(4), c.sum("adaptivepool.worker.limit", pool)) + assert.Equal(t, int64(2), c.sum("adaptivepool.worker.min", pool)) + assert.Equal(t, int64(0), c.sum("adaptivepool.queue.usage", pool)) + assert.Equal(t, int64(10), c.sum("adaptivepool.queue.limit", pool)) +} + +func TestJobOutcomes(t *testing.T) { + c, mp := newCollector(t) + results := make(chan adaptivepool.TaskResult, 3) + p := newPool(t, adaptivepool.WithName("orders"), adaptivepool.WithRecorder(New(mp)), + adaptivepool.WithMinWorkers(1), adaptivepool.WithMaxWorkers(1), + adaptivepool.WithRetry(adaptivepool.RetryPolicy{MaxAttempts: 3, Backoff: adaptivepool.ConstantBackoff{}}), + adaptivepool.WithOnTaskDone(func(r adaptivepool.TaskResult) { results <- r })) + + ctx := context.Background() + ok := func(context.Context) error { return nil } + require.NoError(t, p.SubmitTask(ctx, adaptivepool.Task{Kind: "email", Run: ok})) + require.NoError(t, p.SubmitTask(ctx, adaptivepool.Task{Kind: "email", Run: func(context.Context) error { return errors.New("down") }})) + require.NoError(t, p.Submit(ctx, ok)) + for range 3 { + <-results + } + + pool := PoolNameKey.String("orders") + email, def := JobKindKey.String("email"), JobKindKey.String("default") + assert.Equal(t, int64(2), c.sum("adaptivepool.job.submissions", pool, email)) + assert.Equal(t, int64(1), c.sum("adaptivepool.job.submissions", pool, def)) + assert.Equal(t, uint64(1), c.histogramCount("adaptivepool.job.duration", pool, email, JobStatusKey.String("success"))) + assert.Equal(t, uint64(1), c.histogramCount("adaptivepool.job.duration", pool, email, JobStatusKey.String("retries_exhausted"))) + assert.Equal(t, uint64(2), c.histogramCount("adaptivepool.job.wait_time", pool, email)) + assert.Equal(t, int64(2), c.sum("adaptivepool.job.retries", pool, email)) +} + +func TestDroppedJobs(t *testing.T) { + c, mp := newCollector(t) + rec := New(mp) + require.NoError(t, rec.Attach(adaptivepool.PoolInfo{Name: "orders"}, stubStats{})) + defer rec.Detach() + + rec.JobDropped("email") + rec.JobDropped("email") + assert.Equal(t, int64(2), c.sum("adaptivepool.job.dropped", PoolNameKey.String("orders"), JobKindKey.String("email"))) +} + +func TestRejections(t *testing.T) { + c, mp := newCollector(t) + p := newPool(t, adaptivepool.WithName("orders"), adaptivepool.WithMinWorkers(1), adaptivepool.WithMaxWorkers(1), + adaptivepool.WithQueueSize(1), adaptivepool.WithRecorder(New(mp))) + + release := make(chan struct{}) + defer close(release) + task := adaptivepool.Task{Kind: "email", Run: func(context.Context) error { <-release; return nil }} + ctx := context.Background() + require.NoError(t, p.TrySubmit(ctx, task)) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + require.NoError(t, p.TrySubmit(ctx, task)) // fills the queue + + assert.ErrorIs(t, p.TrySubmit(ctx, task), adaptivepool.ErrQueueFull) + assert.Equal(t, int64(1), c.sum("adaptivepool.job.rejections", + PoolNameKey.String("orders"), JobKindKey.String("email"), RejectionReasonKey.String("queue_full"))) +} + +func TestRecorderServesOnePoolAtATime(t *testing.T) { + _, mp := newCollector(t) + rec := New(mp) + first, err := adaptivepool.New(adaptivepool.WithRecorder(rec), adaptivepool.WithLogger(slog.New(slog.DiscardHandler))) + require.NoError(t, err) + + _, err = adaptivepool.New(adaptivepool.WithRecorder(rec)) + require.ErrorIs(t, err, ErrAlreadyAttached) + + require.NoError(t, first.Shutdown(context.Background())) + newPool(t, adaptivepool.WithRecorder(rec)) +} + +func TestDetachStopsGauges(t *testing.T) { + c, mp := newCollector(t) + p, err := adaptivepool.New(adaptivepool.WithName("orders"), adaptivepool.WithRecorder(New(mp)), + adaptivepool.WithLogger(slog.New(slog.DiscardHandler))) + require.NoError(t, err) + _, ok := c.metric("adaptivepool.worker.count") + require.True(t, ok) + + require.NoError(t, p.Shutdown(context.Background())) + _, ok = c.metric("adaptivepool.worker.count") + assert.False(t, ok, "the gauge callback must be unregistered on shutdown") +} + +func attachedRecorder(tb testing.TB) *Recorder { + tb.Helper() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(sdkmetric.NewManualReader())) + rec := New(mp) + p, err := adaptivepool.New(adaptivepool.WithRecorder(rec), adaptivepool.WithLogger(slog.New(slog.DiscardHandler))) + if err != nil { + tb.Fatal(err) + } + tb.Cleanup(func() { + _ = p.Shutdown(context.Background()) + _ = mp.Shutdown(context.Background()) + }) + return rec +} + +func TestRecordingDoesNotAllocate(t *testing.T) { + if raceEnabled { + t.Skip("the race detector adds allocations") + } + rec := attachedRecorder(t) + record := func() { + rec.JobSubmitted("email") + rec.JobCompleted("email", adaptivepool.StatusSuccess, 2, time.Millisecond, time.Millisecond) + } + record() // populate the option caches + assert.Zero(t, testing.AllocsPerRun(1000, record)) +} + +func BenchmarkJobCompleted(b *testing.B) { + rec := attachedRecorder(b) + b.ReportAllocs() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + rec.JobCompleted("email", adaptivepool.StatusSuccess, 1, time.Millisecond, time.Millisecond) + } + }) +} + +type stubStats struct{} + +func (stubStats) QueueDepth() int { return 0 } +func (stubStats) ActiveWorkers() int { return 0 } +func (stubStats) BusyWorkers() int { return 0 } +func (stubStats) JobsProcessed() int64 { return 0 } +func (stubStats) JobsFailed() int64 { return 0 } +func (stubStats) JobsRejected() int64 { return 0 } +func (stubStats) JobsDropped() int64 { return 0 } +func (stubStats) JobsRetried() int64 { return 0 } +func (stubStats) RetryAttempts() int64 { return 0 } +func (stubStats) AvgJobLatency() time.Duration { return 0 } +func (stubStats) AvgQueueWait() time.Duration { return 0 } + +// Regression: Attach rewrote the recorder's instruments without +// synchronization while events from a previous pool could still read them +// (run with -race). +func TestAttachDetachWhileRecording(t *testing.T) { + _, mp := newCollector(t) + rec := New(mp) + stop := make(chan struct{}) + var wg sync.WaitGroup + for range 4 { + wg.Go(func() { + for { + select { + case <-stop: + return + default: + } + rec.JobSubmitted("k") + rec.JobRejected("k", adaptivepool.RejectTimeout) + rec.JobCompleted("k", adaptivepool.StatusSuccess, 2, time.Millisecond, time.Millisecond) + rec.ScaledUp(1) + } + }) + } + for range 100 { + require.NoError(t, rec.Attach(adaptivepool.PoolInfo{Name: "p", MaxWorkers: 1, QueueSize: 1}, stubStats{})) + rec.Detach() + } + close(stop) + wg.Wait() +} + +func TestEventsAfterDetachAreDropped(t *testing.T) { + _, mp := newCollector(t) + rec := New(mp) + require.NoError(t, rec.Attach(adaptivepool.PoolInfo{}, stubStats{})) + rec.Detach() + rec.Detach() // idempotent + + rec.JobSubmitted("k") + rec.JobRejected("k", adaptivepool.RejectTimeout) + rec.JobCompleted("k", adaptivepool.StatusSuccess, 1, 0, 0) + rec.ScaledUp(1) + assert.Nil(t, rec.state.Load()) +} diff --git a/otelrecorder/race_off_test.go b/otelrecorder/race_off_test.go new file mode 100644 index 0000000..6e06bf7 --- /dev/null +++ b/otelrecorder/race_off_test.go @@ -0,0 +1,5 @@ +//go:build !race + +package otelrecorder + +const raceEnabled = false diff --git a/otelrecorder/race_on_test.go b/otelrecorder/race_on_test.go new file mode 100644 index 0000000..ed2efd1 --- /dev/null +++ b/otelrecorder/race_on_test.go @@ -0,0 +1,5 @@ +//go:build race + +package otelrecorder + +const raceEnabled = true diff --git a/pool.go b/pool.go index 032c091..6b219f4 100644 --- a/pool.go +++ b/pool.go @@ -3,20 +3,41 @@ package adaptivepool import ( "context" "fmt" - "log" + "log/slog" "sync" "time" ) // Pool represents a worker pool that can execute jobs concurrently type Pool interface { - // Submit Submits a job to the pool for execution - // Returns ErrPoolShutdown if the pool is shutdown - // Blocks until the job is enqueued or context is cancelled + // Submit submits a job to the pool for execution. If the queue is full + // it blocks until there is space, ctx is done or the pool shuts down. + // ctx is also the context the job runs with; use SubmitTask with + // Task.Context to give the job a different one. + // + // It returns ErrNilJob for a nil job, ErrPoolShutdown once Shutdown has + // started, ErrTimeout if ctx's deadline passes while waiting, and + // context.Canceled if ctx is cancelled while waiting. A ctx that is + // already done is rejected the same way, without queueing, unless + // Task.Context is set. Submit(ctx context.Context, job Job) error + // SubmitTask is like Submit but carries a task ID and kind for logs and + // metrics, and an optional execution context separate from ctx. It + // returns the same errors as Submit. + SubmitTask(ctx context.Context, task Task) error + + // TrySubmit is like SubmitTask but never waits: if the queue is full it + // returns ErrQueueFull. ctx is only the job's context, used when + // task.Context is nil. + TrySubmit(ctx context.Context, task Task) error + // Shutdown gracefully shuts down the pool // Waits for in-flight jobs to complete within the context timeout + // If ctx ends first, jobs still queued are dropped without running, each + // reported with StatusShutdown, and it returns a *ShutdownError. + // It may be called more than once: later calls return the first call's + // result, or ctx's error if ctx ends before the shutdown does Shutdown(ctx context.Context) error // Metrics returns the pool metrics @@ -28,6 +49,9 @@ type pool struct { config *Config state *poolState metrics *metrics + logger *slog.Logger + retrier *retrier // nil when retries are disabled + epoch time.Time // monotonic reference for queue wait timing // Dispatcher coordination dispatcherWg sync.WaitGroup @@ -51,8 +75,14 @@ func New(options ...Option) (Pool, error) { // creating pool state state := newPoolState(config.queueSize) - // creating metrics - metrics := newMetrics(state, config.metricsEnabled, "adaptivepool") + logger := newLogger(config) + metrics := newMetrics(state, config.recorder, logger) + if a, ok := config.recorder.(Attacher); ok { + info := PoolInfo{Name: config.name, MinWorkers: config.minWorkers, MaxWorkers: config.maxWorkers, QueueSize: config.queueSize} + if err := a.Attach(info, metrics); err != nil { + return nil, fmt.Errorf("attaching metrics recorder: %w", err) + } + } // creating dispatcher context dispatcherCtx, dispatcherCancel := context.WithCancel(context.Background()) @@ -61,10 +91,16 @@ func New(options ...Option) (Pool, error) { config: config, state: state, metrics: metrics, + logger: logger, + epoch: time.Now(), dispatcherCtx: dispatcherCtx, dispatcherCancel: dispatcherCancel, } + if config.retry != nil { + p.retrier = newRetrier(*config.retry, p.logger, state.forceStop) + } + // Start the dispatcher p.dispatcherWg.Add(1) go p.runDispatcher() @@ -77,6 +113,18 @@ func New(options ...Option) (Pool, error) { return p, nil } +// newLogger resolves the configured logger and binds the pool name to it +func newLogger(c *Config) *slog.Logger { + l := c.logger + if l == nil { + l = slog.Default() + } + if c.name != "" { + l = l.With(slog.String("pool", c.name)) + } + return l +} + // Metrics returns the pool metrics func (p *pool) Metrics() Metrics { return p.metrics @@ -96,9 +144,6 @@ func (p *pool) runDispatcher() { scaleTicker := time.NewTicker(1 * time.Second) defer scaleTicker.Stop() - metricsTicker := time.NewTicker(5 * time.Second) - defer metricsTicker.Stop() - for { select { case <-p.dispatcherCtx.Done(): @@ -108,10 +153,6 @@ func (p *pool) runDispatcher() { case <-scaleTicker.C: // Check if we need to scale p.checkScaling() - - case <-metricsTicker.C: - // Update gauge metrics - p.metrics.updateGauges() } } } @@ -126,8 +167,8 @@ func (p *pool) runWorker(id int) { for { select { - case <-p.state.workerShutdown: - // Shutdown signal received + case <-p.state.forceStop: + // Forced shutdown: stop without draining the queue return case job, ok := <-p.state.jobQueue: @@ -135,6 +176,11 @@ func (p *pool) runWorker(id int) { // Queue closed, shutdown return } + // select picks at random when forceStop and the queue are both ready + if closed(p.state.forceStop) { + p.dropJob(job) + return + } // Reset idle timer if !idleTimer.Stop() { @@ -161,26 +207,6 @@ func (p *pool) runWorker(id int) { } } -// executeJob executes a job with panic recovery and metrics -func (p *pool) executeJob(workerID int, job jobWrapper) { - start := time.Now() - - defer func() { - if r := recover(); r != nil { - log.Printf("worker %d: panic executing job %d: %v", workerID, job.id, r) - } - - // Record metrics - latency := time.Since(start) - p.metrics.recordJobProcessed(latency) - }() - - // Execute the job - if err := job.job(job.ctx); err != nil { - log.Printf("worker %d: job %d failed: %v", workerID, job.id, err) - } -} - // checkScaling checks if we need to scale workers up or down func (p *pool) checkScaling() { utilization := p.state.getQueueUtilization() @@ -216,5 +242,6 @@ func (p *pool) scaleUp() { } p.state.lastScaleUp = time.Now() - log.Printf("scaled up: added %d workers (total: %d)", toAdd, p.state.getWorkerCount()) + p.metrics.recordScaleUp(toAdd) + p.logger.Info("scaled up", slog.Int("added", toAdd), slog.Int("workers", p.state.getWorkerCount())) } diff --git a/promrecorder/go.mod b/promrecorder/go.mod new file mode 100644 index 0000000..460aa94 --- /dev/null +++ b/promrecorder/go.mod @@ -0,0 +1,29 @@ +module github.com/iyashjayesh/go-adaptive-pool/promrecorder + +go 1.25.0 + +require ( + github.com/iyashjayesh/go-adaptive-pool v0.0.0 + github.com/prometheus/client_golang v1.23.2 + github.com/stretchr/testify v1.12.1 + go.uber.org/goleak v1.3.0 +) + +require ( + github.com/beorn7/perks v1.0.1 // indirect + github.com/cespare/xxhash/v2 v2.3.0 // indirect + github.com/kr/text v0.2.0 // indirect + github.com/kylelemons/godebug v1.1.0 // indirect + github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect + github.com/prometheus/client_model v0.6.2 // indirect + github.com/prometheus/common v0.66.1 // indirect + github.com/prometheus/procfs v0.16.1 // indirect + go.yaml.in/yaml/v2 v2.4.2 // indirect + go.yaml.in/yaml/v3 v3.0.5 // indirect + golang.org/x/sys v0.47.0 // indirect + google.golang.org/protobuf v1.36.8 // indirect +) + +// The core has no release with the Recorder API yet. Remove this before +// tagging, once go.mod requires a published core version (see CONTRIBUTING.md). +replace github.com/iyashjayesh/go-adaptive-pool => ../ diff --git a/promrecorder/go.sum b/promrecorder/go.sum new file mode 100644 index 0000000..00c739a --- /dev/null +++ b/promrecorder/go.sum @@ -0,0 +1,40 @@ +github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= +github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= +github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= +github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= +github.com/creack/pty v1.1.9/go.mod h1:oKZEueFk5CKHvIhNR5MUki03XCEU+Q6VDXinZuGJ33E= +github.com/google/go-cmp v0.7.0 h1:wk8382ETsv4JYUZwIsn6YpYiWiBsYLSJiTsyBybVuN8= +github.com/google/go-cmp v0.7.0/go.mod h1:pXiqmnSA92OHEEa9HXL2W4E7lf9JzCmGVUdgjX3N/iU= +github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= +github.com/kr/pretty v0.3.1/go.mod h1:hoEshYVHaxMs3cyo3Yncou5ZscifuDolrwPKZanG3xk= +github.com/kr/text v0.2.0 h1:5Nx0Ya0ZqY2ygV366QzturHI13Jq95ApcVaJBhpS+AY= +github.com/kr/text v0.2.0/go.mod h1:eLer722TekiGuMkidMxC/pM04lWEeraHUUmBw8l2grE= +github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0SNc= +github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= +github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= +github.com/prometheus/client_golang v1.23.2 h1:Je96obch5RDVy3FDMndoUsjAhG5Edi49h0RJWRi/o0o= +github.com/prometheus/client_golang v1.23.2/go.mod h1:Tb1a6LWHB3/SPIzCoaDXI4I8UHKeFTEQ1YCr+0Gyqmg= +github.com/prometheus/client_model v0.6.2 h1:oBsgwpGs7iVziMvrGhE53c/GrLUsZdHnqNwqPLxwZyk= +github.com/prometheus/client_model v0.6.2/go.mod h1:y3m2F6Gdpfy6Ut/GBsUqTWZqCUvMVzSfMLjcu6wAwpE= +github.com/prometheus/common v0.66.1 h1:h5E0h5/Y8niHc5DlaLlWLArTQI7tMrsfQjHV+d9ZoGs= +github.com/prometheus/common v0.66.1/go.mod h1:gcaUsgf3KfRSwHY4dIMXLPV0K/Wg1oZ8+SbZk/HH/dA= +github.com/prometheus/procfs v0.16.1 h1:hZ15bTNuirocR6u0JZ6BAHHmwS1p8B4P6MRqxtzMyRg= +github.com/prometheus/procfs v0.16.1/go.mod h1:teAbpZRB1iIAJYREa1LsoWUXykVXA1KlTmWl8x/U+Is= +github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ= +github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog= +github.com/stretchr/testify v1.12.1 h1:EuwCh5fleGS7H32xRwO3wRGT7DxrDhLAT6FF8MpWDWE= +github.com/stretchr/testify v1.12.1/go.mod h1:MDEgiDPPsNp5cuIrHPPCyornHKgEVbtFUmoNlxoYthg= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= +go.yaml.in/yaml/v2 v2.4.2 h1:DzmwEr2rDGHl7lsFgAHxmNz/1NlQ7xLIrlN2h5d1eGI= +go.yaml.in/yaml/v2 v2.4.2/go.mod h1:081UH+NErpNdqlCXm3TtEran0rJZGxAYx9hb/ELlsPU= +go.yaml.in/yaml/v3 v3.0.5 h1:N6y/pJk8buWs9NY5ERU2HSMfm+IuD/OtfdAnq6kESPw= +go.yaml.in/yaml/v3 v3.0.5/go.mod h1:HVTZu1O7/Vkt2N+BFy8Zza+lnLsABggaTM2ZpNIGuKg= +golang.org/x/sys v0.47.0 h1:o7XGOvZQCADBQQ4Y7VNq2dRWQR7JmOUW8Kxx4ZsNgWs= +golang.org/x/sys v0.47.0/go.mod h1:4GL1E5IUh+htKOUEOaiffhrAeqysfVGipDYzABqnCmw= +google.golang.org/protobuf v1.36.8 h1:xHScyCOEuuwZEc6UtSOvPbAT4zRh0xcNRYekJwfqyMc= +google.golang.org/protobuf v1.36.8/go.mod h1:fuxRtAxBytpl4zzqUh6/eyUujkJdNiuEkXntxiD/uRU= +gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= +gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= +gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= diff --git a/promrecorder/promrecorder.go b/promrecorder/promrecorder.go new file mode 100644 index 0000000..75655db --- /dev/null +++ b/promrecorder/promrecorder.go @@ -0,0 +1,257 @@ +// Package promrecorder exports adaptive pool metrics to Prometheus. +// +// reg := prometheus.NewRegistry() +// pool, err := adaptivepool.New( +// adaptivepool.WithName("orders"), +// adaptivepool.WithRecorder(promrecorder.New(reg)), +// ) +// http.Handle("/metrics", promhttp.HandlerFor(reg, promhttp.HandlerOpts{})) +// +// Metrics are named adaptivepool_* and carry a "pool" label when the pool is +// named. Collectors are registered when the pool is created and unregistered +// when it shuts down; give each pool sharing a registry a distinct name. +package promrecorder + +import ( + "errors" + "sync" + "sync/atomic" + "time" + + adaptivepool "github.com/iyashjayesh/go-adaptive-pool" + "github.com/prometheus/client_golang/prometheus" +) + +const namespace = "adaptivepool" + +// ErrAlreadyAttached is returned when a Recorder is used by a second pool +// while the first is still running. +var ErrAlreadyAttached = errors.New("promrecorder: recorder already attached to a pool") + +// Recorder exports pool events as Prometheus metrics. Gauges are GaugeFuncs +// read at scrape time, so they cost nothing between scrapes. Use one +// Recorder per pool. +type Recorder struct { + reg prometheus.Registerer + attached atomic.Bool + + // state holds the collectors of the attached pool, nil when detached. + // Each event loads it once, so Attach and Detach never race with recording. + state atomic.Pointer[state] +} + +type state struct { + collectors []prometheus.Collector + + jobsSubmitted *prometheus.CounterVec // kind + jobsRejected *prometheus.CounterVec // kind, reason + jobsCompleted *prometheus.CounterVec // kind, status + jobsDropped *prometheus.CounterVec // kind + jobDuration *prometheus.HistogramVec // kind + queueWait *prometheus.HistogramVec // kind + jobsRetried *prometheus.CounterVec // kind + retries *prometheus.CounterVec // kind + scaleUps prometheus.Counter + + // kinds caches each kind's resolved series (*kindSeries). Resolving a + // labelled series takes a lock inside client_golang; caching it makes + // the per-job path a lock-free map read. + kinds sync.Map +} + +type kindSeries struct { + submitted prometheus.Counter + dropped prometheus.Counter + duration prometheus.Observer + queueWait prometheus.Observer + jobsRetried prometheus.Counter + retries prometheus.Counter + completed sync.Map // adaptivepool.Status -> prometheus.Counter + rejected sync.Map // adaptivepool.RejectReason -> prometheus.Counter +} + +var ( + _ adaptivepool.Recorder = (*Recorder)(nil) + _ adaptivepool.Attacher = (*Recorder)(nil) +) + +// New returns a Recorder that registers its metrics with reg, e.g. +// prometheus.DefaultRegisterer or a dedicated registry. +func New(reg prometheus.Registerer) *Recorder { + return &Recorder{reg: reg} +} + +// Attach creates the collectors, labelled with the pool name, and registers +// them, rolling back on failure. It is called by adaptivepool.New. +func (r *Recorder) Attach(info adaptivepool.PoolInfo, stats adaptivepool.Metrics) error { + if !r.attached.CompareAndSwap(false, true) { + return ErrAlreadyAttached + } + s, err := r.register(info, stats) + if err != nil { + r.attached.Store(false) + return err + } + r.state.Store(s) + return nil +} + +func (r *Recorder) register(info adaptivepool.PoolInfo, stats adaptivepool.Metrics) (*state, error) { + var constLabels prometheus.Labels + if info.Name != "" { + constLabels = prometheus.Labels{"pool": info.Name} + } + gauge := func(name, help string, fn func() float64) prometheus.Collector { + return prometheus.NewGaugeFunc(prometheus.GaugeOpts{ + Namespace: namespace, Name: name, Help: help, ConstLabels: constLabels, + }, fn) + } + counterVec := func(name, help string, labels ...string) *prometheus.CounterVec { + return prometheus.NewCounterVec(prometheus.CounterOpts{ + Namespace: namespace, Name: name, Help: help, ConstLabels: constLabels, + }, labels) + } + histogramVec := func(name, help string, buckets []float64) *prometheus.HistogramVec { + return prometheus.NewHistogramVec(prometheus.HistogramOpts{ + Namespace: namespace, Name: name, Help: help, ConstLabels: constLabels, Buckets: buckets, + }, []string{"kind"}) + } + + s := &state{} + s.jobsSubmitted = counterVec("jobs_submitted_total", "Jobs accepted into the queue", "kind") + s.jobsRejected = counterVec("jobs_rejected_total", "Jobs rejected at submission", "kind", "reason") + s.jobsCompleted = counterVec("jobs_completed_total", "Jobs that finished executing, by final status", "kind", "status") + s.jobsDropped = counterVec("jobs_dropped_total", "Queued jobs a forced shutdown discarded without running", "kind") + s.jobDuration = histogramVec("job_duration_seconds", "Job execution time in seconds", prometheus.DefBuckets) + s.queueWait = histogramVec("job_queue_wait_seconds", "Time jobs spent queued before execution in seconds", + prometheus.ExponentialBuckets(0.0005, 4, 10)) + s.jobsRetried = counterVec("jobs_retried_total", "Jobs that needed at least one retry", "kind") + s.retries = counterVec("retry_attempts_total", "Retries performed across all jobs", "kind") + s.scaleUps = prometheus.NewCounter(prometheus.CounterOpts{ + Namespace: namespace, Name: "scale_up_events_total", Help: "Number of scale-up events", ConstLabels: constLabels, + }) + + s.collectors = []prometheus.Collector{ + s.jobsSubmitted, + s.jobsRejected, + s.jobsCompleted, + s.jobsDropped, + s.jobDuration, + s.queueWait, + s.jobsRetried, + s.retries, + s.scaleUps, + gauge("queue_depth", "Current number of jobs in the queue", + func() float64 { return float64(stats.QueueDepth()) }), + gauge("queue_capacity", "Capacity of the job queue", + func() float64 { return float64(info.QueueSize) }), + gauge("active_workers", "Current number of active workers", + func() float64 { return float64(stats.ActiveWorkers()) }), + gauge("busy_workers", "Number of workers currently executing a job", + func() float64 { return float64(stats.BusyWorkers()) }), + gauge("max_workers", "Configured maximum number of workers", + func() float64 { return float64(info.MaxWorkers) }), + } + + for i, c := range s.collectors { + if err := r.reg.Register(c); err != nil { + for _, done := range s.collectors[:i] { + r.reg.Unregister(done) + } + return nil, err + } + } + return s, nil +} + +// Detach unregisters all collectors and drops later events. It is called +// when the pool shuts down, after which the Recorder may be attached to a +// new pool. +func (r *Recorder) Detach() { + s := r.state.Swap(nil) + if s == nil { + return + } + for _, c := range s.collectors { + r.reg.Unregister(c) + } + r.attached.Store(false) +} + +// series returns the cached series for kind, resolving them on first use +func (s *state) series(kind string) *kindSeries { + if k, ok := s.kinds.Load(kind); ok { + return k.(*kindSeries) + } + k, _ := s.kinds.LoadOrStore(kind, &kindSeries{ + submitted: s.jobsSubmitted.WithLabelValues(kind), + dropped: s.jobsDropped.WithLabelValues(kind), + duration: s.jobDuration.WithLabelValues(kind), + queueWait: s.queueWait.WithLabelValues(kind), + jobsRetried: s.jobsRetried.WithLabelValues(kind), + retries: s.retries.WithLabelValues(kind), + }) + return k.(*kindSeries) +} + +// completedCounter returns the cached completion counter for kind and status +func (s *state) completedCounter(k *kindSeries, kind string, status adaptivepool.Status) prometheus.Counter { + if c, ok := k.completed.Load(status); ok { + return c.(prometheus.Counter) + } + c, _ := k.completed.LoadOrStore(status, s.jobsCompleted.WithLabelValues(kind, string(status))) + return c.(prometheus.Counter) +} + +// rejectedCounter returns the cached rejection counter for kind and reason +func (s *state) rejectedCounter(k *kindSeries, kind string, reason adaptivepool.RejectReason) prometheus.Counter { + if c, ok := k.rejected.Load(reason); ok { + return c.(prometheus.Counter) + } + c, _ := k.rejected.LoadOrStore(reason, s.jobsRejected.WithLabelValues(kind, string(reason))) + return c.(prometheus.Counter) +} + +// JobSubmitted implements adaptivepool.Recorder +func (r *Recorder) JobSubmitted(kind string) { + if s := r.state.Load(); s != nil { + s.series(kind).submitted.Inc() + } +} + +// JobRejected implements adaptivepool.Recorder +func (r *Recorder) JobRejected(kind string, reason adaptivepool.RejectReason) { + if s := r.state.Load(); s != nil { + s.rejectedCounter(s.series(kind), kind, reason).Inc() + } +} + +// JobCompleted implements adaptivepool.Recorder +func (r *Recorder) JobCompleted(kind string, status adaptivepool.Status, attempts int, queueWait, duration time.Duration) { + s := r.state.Load() + if s == nil { + return + } + k := s.series(kind) + s.completedCounter(k, kind, status).Inc() + k.duration.Observe(duration.Seconds()) + k.queueWait.Observe(queueWait.Seconds()) + if retries := attempts - 1; retries > 0 { + k.jobsRetried.Inc() + k.retries.Add(float64(retries)) + } +} + +// JobDropped implements adaptivepool.Recorder +func (r *Recorder) JobDropped(kind string) { + if s := r.state.Load(); s != nil { + s.series(kind).dropped.Inc() + } +} + +// ScaledUp implements adaptivepool.Recorder +func (r *Recorder) ScaledUp(int) { + if s := r.state.Load(); s != nil { + s.scaleUps.Inc() + } +} diff --git a/promrecorder/promrecorder_test.go b/promrecorder/promrecorder_test.go new file mode 100644 index 0000000..db8d05b --- /dev/null +++ b/promrecorder/promrecorder_test.go @@ -0,0 +1,309 @@ +package promrecorder + +import ( + "context" + "errors" + "log/slog" + "strings" + "sync" + "testing" + "time" + + adaptivepool "github.com/iyashjayesh/go-adaptive-pool" + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/testutil" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.uber.org/goleak" +) + +func TestMain(m *testing.M) { + goleak.VerifyTestMain(m) +} + +func newPool(t *testing.T, opts ...adaptivepool.Option) adaptivepool.Pool { + t.Helper() + opts = append([]adaptivepool.Option{adaptivepool.WithLogger(slog.New(slog.DiscardHandler))}, opts...) + p, err := adaptivepool.New(opts...) + require.NoError(t, err) + t.Cleanup(func() { + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + _ = p.Shutdown(ctx) + }) + return p +} + +func TestRegistrationAndUnregistration(t *testing.T) { + reg := prometheus.NewRegistry() + p, err := adaptivepool.New( + adaptivepool.WithName("emails"), + adaptivepool.WithMinWorkers(2), adaptivepool.WithMaxWorkers(4), adaptivepool.WithQueueSize(10), + adaptivepool.WithLogger(slog.New(slog.DiscardHandler)), + adaptivepool.WithRecorder(New(reg)), + ) + require.NoError(t, err) + + expected := ` +# HELP adaptivepool_active_workers Current number of active workers +# TYPE adaptivepool_active_workers gauge +adaptivepool_active_workers{pool="emails"} 2 +# HELP adaptivepool_max_workers Configured maximum number of workers +# TYPE adaptivepool_max_workers gauge +adaptivepool_max_workers{pool="emails"} 4 +# HELP adaptivepool_queue_capacity Capacity of the job queue +# TYPE adaptivepool_queue_capacity gauge +adaptivepool_queue_capacity{pool="emails"} 10 +` + require.NoError(t, testutil.GatherAndCompare(reg, strings.NewReader(expected), + "adaptivepool_active_workers", "adaptivepool_max_workers", "adaptivepool_queue_capacity")) + + ctx, cancel := context.WithTimeout(context.Background(), 5*time.Second) + defer cancel() + require.NoError(t, p.Shutdown(ctx)) + + families, err := reg.Gather() + require.NoError(t, err) + assert.Empty(t, families, "metrics should be unregistered on shutdown") +} + +func TestDuplicatePoolNameFailsNew(t *testing.T) { + reg := prometheus.NewRegistry() + newPool(t, adaptivepool.WithName("a"), adaptivepool.WithRecorder(New(reg))) + + _, err := adaptivepool.New(adaptivepool.WithName("a"), adaptivepool.WithRecorder(New(reg))) + require.Error(t, err) + + // A distinct name can share the registry + newPool(t, adaptivepool.WithName("b"), adaptivepool.WithRecorder(New(reg))) +} + +func TestRecorderServesOnePoolAtATime(t *testing.T) { + rec := New(prometheus.NewRegistry()) + first, err := adaptivepool.New(adaptivepool.WithRecorder(rec), adaptivepool.WithLogger(slog.New(slog.DiscardHandler))) + require.NoError(t, err) + + _, err = adaptivepool.New(adaptivepool.WithRecorder(rec)) + require.ErrorIs(t, err, ErrAlreadyAttached) + + // Once the first pool shuts down, the recorder can be reused + require.NoError(t, first.Shutdown(context.Background())) + newPool(t, adaptivepool.WithRecorder(rec)) +} + +func TestJobOutcomesByKind(t *testing.T) { + reg := prometheus.NewRegistry() + p := newPool(t, adaptivepool.WithRecorder(New(reg))) + + ctx := context.Background() + ok := func(context.Context) error { return nil } + require.NoError(t, p.SubmitTask(ctx, adaptivepool.Task{Kind: "email", Run: ok})) + require.NoError(t, p.SubmitTask(ctx, adaptivepool.Task{Kind: "email", Run: func(context.Context) error { return errors.New("x") }})) + require.NoError(t, p.SubmitTask(ctx, adaptivepool.Task{Kind: "resize", Run: func(context.Context) error { panic("x") }})) + require.NoError(t, p.Submit(ctx, ok)) + + require.Eventually(t, func() bool { return p.Metrics().JobsProcessed() == 4 }, 2*time.Second, 10*time.Millisecond) + + expected := ` +# HELP adaptivepool_jobs_completed_total Jobs that finished executing, by final status +# TYPE adaptivepool_jobs_completed_total counter +adaptivepool_jobs_completed_total{kind="default",status="success"} 1 +adaptivepool_jobs_completed_total{kind="email",status="error"} 1 +adaptivepool_jobs_completed_total{kind="email",status="success"} 1 +adaptivepool_jobs_completed_total{kind="resize",status="panic"} 1 +# HELP adaptivepool_jobs_submitted_total Jobs accepted into the queue +# TYPE adaptivepool_jobs_submitted_total counter +adaptivepool_jobs_submitted_total{kind="default"} 1 +adaptivepool_jobs_submitted_total{kind="email"} 2 +adaptivepool_jobs_submitted_total{kind="resize"} 1 +` + require.NoError(t, testutil.GatherAndCompare(reg, strings.NewReader(expected), + "adaptivepool_jobs_completed_total", "adaptivepool_jobs_submitted_total")) + assert.Equal(t, 3, testutil.CollectAndCount(reg, "adaptivepool_job_duration_seconds")) +} + +func TestRejectionReasons(t *testing.T) { + rec := New(prometheus.NewRegistry()) + p := newPool(t, adaptivepool.WithMinWorkers(1), adaptivepool.WithMaxWorkers(1), adaptivepool.WithQueueSize(1), + adaptivepool.WithRecorder(rec)) + + release := make(chan struct{}) + defer close(release) + task := adaptivepool.Task{Kind: "email", Run: func(context.Context) error { <-release; return nil }} + ctx := context.Background() + require.NoError(t, p.TrySubmit(ctx, task)) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + require.NoError(t, p.TrySubmit(ctx, task)) // fills the queue + + for range 2 { + assert.ErrorIs(t, p.TrySubmit(ctx, task), adaptivepool.ErrQueueFull) + } + sms := task + sms.Kind = "sms" + assert.ErrorIs(t, p.TrySubmit(ctx, sms), adaptivepool.ErrQueueFull) + + s := rec.state.Load() + queueFull := string(adaptivepool.RejectQueueFull) + assert.InDelta(t, 2, testutil.ToFloat64(s.jobsRejected.WithLabelValues("email", queueFull)), 0) + assert.InDelta(t, 1, testutil.ToFloat64(s.jobsRejected.WithLabelValues("sms", queueFull)), 0) + assert.Equal(t, 2, testutil.CollectAndCount(s.jobsSubmitted), "every kind seen exposes its series, at zero until used") +} + +func TestRetryMetrics(t *testing.T) { + reg := prometheus.NewRegistry() + results := make(chan adaptivepool.TaskResult, 2) + p := newPool(t, + adaptivepool.WithMinWorkers(1), adaptivepool.WithMaxWorkers(1), + adaptivepool.WithRecorder(New(reg)), + adaptivepool.WithRetry(adaptivepool.RetryPolicy{MaxAttempts: 3, Backoff: adaptivepool.ConstantBackoff{}}), + adaptivepool.WithOnTaskDone(func(r adaptivepool.TaskResult) { results <- r }), + ) + + errTransient := errors.New("transient") + failedOnce := false + ctx := context.Background() + require.NoError(t, p.SubmitTask(ctx, adaptivepool.Task{Kind: "sync", Run: func(context.Context) error { + if !failedOnce { + failedOnce = true + return errTransient + } + return nil + }})) + require.NoError(t, p.SubmitTask(ctx, adaptivepool.Task{Kind: "sync", Run: func(context.Context) error { return errTransient }})) + <-results + <-results + + expected := ` +# HELP adaptivepool_jobs_completed_total Jobs that finished executing, by final status +# TYPE adaptivepool_jobs_completed_total counter +adaptivepool_jobs_completed_total{kind="sync",status="retries_exhausted"} 1 +adaptivepool_jobs_completed_total{kind="sync",status="success"} 1 +# HELP adaptivepool_jobs_retried_total Jobs that needed at least one retry +# TYPE adaptivepool_jobs_retried_total counter +adaptivepool_jobs_retried_total{kind="sync"} 2 +# HELP adaptivepool_retry_attempts_total Retries performed across all jobs +# TYPE adaptivepool_retry_attempts_total counter +adaptivepool_retry_attempts_total{kind="sync"} 3 +` + require.NoError(t, testutil.GatherAndCompare(reg, strings.NewReader(expected), + "adaptivepool_jobs_completed_total", "adaptivepool_jobs_retried_total", "adaptivepool_retry_attempts_total")) +} + +func attachedRecorder(tb testing.TB) *Recorder { + tb.Helper() + rec := New(prometheus.NewRegistry()) + p, err := adaptivepool.New(adaptivepool.WithRecorder(rec), adaptivepool.WithLogger(slog.New(slog.DiscardHandler))) + if err != nil { + tb.Fatal(err) + } + tb.Cleanup(func() { _ = p.Shutdown(context.Background()) }) + return rec +} + +func TestJobCompletedDoesNotAllocate(t *testing.T) { + if raceEnabled { + t.Skip("the race detector adds allocations") + } + rec := attachedRecorder(t) + rec.JobCompleted("email", adaptivepool.StatusSuccess, 2, time.Millisecond, time.Millisecond) // create series + allocs := testing.AllocsPerRun(1000, func() { + rec.JobCompleted("email", adaptivepool.StatusSuccess, 2, time.Millisecond, time.Millisecond) + }) + assert.Zero(t, allocs) +} + +func BenchmarkJobCompleted(b *testing.B) { + rec := attachedRecorder(b) + b.ReportAllocs() + b.RunParallel(func(pb *testing.PB) { + for pb.Next() { + rec.JobCompleted("email", adaptivepool.StatusSuccess, 1, time.Millisecond, time.Millisecond) + } + }) +} + +// A reused recorder must not keep series from the previous pool's vectors +func TestReusedRecorderReportsToNewPool(t *testing.T) { + reg := prometheus.NewRegistry() + rec := New(reg) + run := func() { + p, err := adaptivepool.New(adaptivepool.WithRecorder(rec), adaptivepool.WithLogger(slog.New(slog.DiscardHandler))) + require.NoError(t, err) + require.NoError(t, p.SubmitTask(context.Background(), adaptivepool.Task{Kind: "email", Run: func(context.Context) error { return nil }})) + require.Eventually(t, func() bool { return p.Metrics().JobsProcessed() == 1 }, 2*time.Second, time.Millisecond) + assert.InDelta(t, 1, testutil.ToFloat64(rec.state.Load().jobsSubmitted.WithLabelValues("email")), 0) + assert.Equal(t, 1, testutil.CollectAndCount(reg, "adaptivepool_jobs_submitted_total")) + require.NoError(t, p.Shutdown(context.Background())) + } + run() + run() // counts start from zero against the new pool's collectors +} + +// stubStats satisfies adaptivepool.Metrics without a pool +type stubStats struct{} + +func (stubStats) QueueDepth() int { return 0 } +func (stubStats) ActiveWorkers() int { return 0 } +func (stubStats) BusyWorkers() int { return 0 } +func (stubStats) JobsProcessed() int64 { return 0 } +func (stubStats) JobsFailed() int64 { return 0 } +func (stubStats) JobsRejected() int64 { return 0 } +func (stubStats) JobsDropped() int64 { return 0 } +func (stubStats) JobsRetried() int64 { return 0 } +func (stubStats) RetryAttempts() int64 { return 0 } +func (stubStats) AvgJobLatency() time.Duration { return 0 } +func (stubStats) AvgQueueWait() time.Duration { return 0 } + +// Regression: Attach rewrote the recorder's collectors without +// synchronization while events from a previous pool could still read them +// (run with -race). +func TestAttachDetachWhileRecording(t *testing.T) { + rec := New(prometheus.NewRegistry()) + stop := make(chan struct{}) + var wg sync.WaitGroup + for range 4 { + wg.Go(func() { + for { + select { + case <-stop: + return + default: + } + rec.JobSubmitted("k") + rec.JobRejected("k", adaptivepool.RejectTimeout) + rec.JobCompleted("k", adaptivepool.StatusSuccess, 2, time.Millisecond, time.Millisecond) + rec.ScaledUp(1) + } + }) + } + for range 100 { + require.NoError(t, rec.Attach(adaptivepool.PoolInfo{Name: "p", MaxWorkers: 1, QueueSize: 1}, stubStats{})) + rec.Detach() + } + close(stop) + wg.Wait() +} + +func TestDroppedJobs(t *testing.T) { + rec := New(prometheus.NewRegistry()) + require.NoError(t, rec.Attach(adaptivepool.PoolInfo{Name: "p"}, stubStats{})) + defer rec.Detach() + + rec.JobDropped("email") + rec.JobDropped("email") + assert.Equal(t, 2.0, testutil.ToFloat64(rec.state.Load().jobsDropped.WithLabelValues("email"))) +} + +func TestEventsAfterDetachAreDropped(t *testing.T) { + rec := New(prometheus.NewRegistry()) + require.NoError(t, rec.Attach(adaptivepool.PoolInfo{}, stubStats{})) + rec.Detach() + rec.Detach() // idempotent + + rec.JobSubmitted("k") + rec.JobRejected("k", adaptivepool.RejectTimeout) + rec.JobCompleted("k", adaptivepool.StatusSuccess, 1, 0, 0) + rec.JobDropped("k") + rec.ScaledUp(1) + assert.Nil(t, rec.state.Load()) +} diff --git a/promrecorder/race_off_test.go b/promrecorder/race_off_test.go new file mode 100644 index 0000000..00ed18b --- /dev/null +++ b/promrecorder/race_off_test.go @@ -0,0 +1,5 @@ +//go:build !race + +package promrecorder + +const raceEnabled = false diff --git a/promrecorder/race_on_test.go b/promrecorder/race_on_test.go new file mode 100644 index 0000000..9fb2d7a --- /dev/null +++ b/promrecorder/race_on_test.go @@ -0,0 +1,5 @@ +//go:build race + +package promrecorder + +const raceEnabled = true diff --git a/race_off_test.go b/race_off_test.go new file mode 100644 index 0000000..00626c3 --- /dev/null +++ b/race_off_test.go @@ -0,0 +1,5 @@ +//go:build !race + +package adaptivepool + +const raceEnabled = false diff --git a/race_on_test.go b/race_on_test.go new file mode 100644 index 0000000..25b6296 --- /dev/null +++ b/race_on_test.go @@ -0,0 +1,5 @@ +//go:build race + +package adaptivepool + +const raceEnabled = true diff --git a/recorder.go b/recorder.go new file mode 100644 index 0000000..5984a72 --- /dev/null +++ b/recorder.go @@ -0,0 +1,77 @@ +package adaptivepool + +import "time" + +const defaultKind = "default" + +// RejectReason explains why a submission was rejected +type RejectReason string + +const ( + // RejectShutdown means the pool was shutting down + RejectShutdown RejectReason = "shutdown" + // RejectTimeout means the submit context's deadline passed while waiting for queue space + RejectTimeout RejectReason = "timeout" + // RejectCanceled means the submit context was canceled while waiting for queue space + RejectCanceled RejectReason = "canceled" + // RejectQueueFull means TrySubmit found the queue full + RejectQueueFull RejectReason = "queue_full" +) + +// PoolInfo describes the pool a recorder is attached to +type PoolInfo struct { + Name string + MinWorkers int + MaxWorkers int + QueueSize int +} + +// Recorder receives pool events, decoupling the pool from any metrics +// backend. See the promrecorder and otelrecorder packages for Prometheus +// and OpenTelemetry implementations. +// +// Kinds are normalized before being passed in: an empty kind is reported as +// "default". Methods run on submitting and worker goroutines, so +// implementations must be safe for concurrent use and fast. A panic in a +// method is recovered and logged once, so a faulty recorder can't crash the +// pool. +type Recorder interface { + // JobSubmitted is called when a job is accepted into the queue + JobSubmitted(kind string) + // JobRejected is called when a submission is rejected + JobRejected(kind string, reason RejectReason) + // JobCompleted is called once per executed job with its final status, + // number of attempts, time spent queued and execution time + JobCompleted(kind string, status Status, attempts int, queueWait, duration time.Duration) + // JobDropped is called once per queued job that a forced shutdown + // discarded without running it + JobDropped(kind string) + // ScaledUp is called when the pool adds workers + ScaledUp(added int) +} + +// Attacher is implemented by recorders that export gauges or need +// registration. New calls Attach before starting the pool, and an error +// fails New. Shutdown calls Detach once every worker has exited, after which +// the pool reports no more events. stats can be read at any time to report +// current values such as queue depth. +type Attacher interface { + Attach(info PoolInfo, stats Metrics) error + Detach() +} + +// WithRecorder sends pool events to r, e.g. a Prometheus or OpenTelemetry +// recorder. The pool's own counters behind Metrics() are always kept. +// Default: none +func WithRecorder(r Recorder) Option { + return func(c *Config) { + c.recorder = r + } +} + +func normalizeKind(kind string) string { + if kind == "" { + return defaultKind + } + return kind +} diff --git a/recorder_test.go b/recorder_test.go new file mode 100644 index 0000000..4906b66 --- /dev/null +++ b/recorder_test.go @@ -0,0 +1,170 @@ +package adaptivepool + +import ( + "context" + "errors" + "sync/atomic" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestRecorderReceivesEvents(t *testing.T) { + rec := &fakeRecorder{} + p := newTestPool(t, WithMinWorkers(1), WithMaxWorkers(1), WithLogger(discardLogger()), WithRecorder(rec)) + + ctx := context.Background() + require.NoError(t, p.SubmitTask(ctx, Task{Kind: "email", Run: func(context.Context) error { return nil }})) + require.NoError(t, p.Submit(ctx, func(context.Context) error { return errors.New("x") })) + require.Eventually(t, func() bool { return len(rec.completedEvents()) == 2 }, 2*time.Second, time.Millisecond) + + rec.mu.Lock() + defer rec.mu.Unlock() + assert.Equal(t, []string{"email", "default"}, rec.submitted, "empty kinds are normalized") + assert.ElementsMatch(t, []completedEvent{ + {kind: "email", status: StatusSuccess, attempts: 1}, + {kind: "default", status: StatusError, attempts: 1}, + }, rec.completed) +} + +func TestRecorderReceivesRejections(t *testing.T) { + rec := &fakeRecorder{} + p, err := New(WithMinWorkers(1), WithMaxWorkers(1), WithQueueSize(1), WithLogger(discardLogger()), WithRecorder(rec)) + require.NoError(t, err) + + release := make(chan struct{}) + task := Task{Kind: "email", Run: func(context.Context) error { <-release; return nil }} + ctx := context.Background() + require.NoError(t, p.TrySubmit(ctx, task)) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + require.NoError(t, p.TrySubmit(ctx, task)) // fills the queue + assert.ErrorIs(t, p.TrySubmit(ctx, task), ErrQueueFull) + + // A Submit blocked on the full queue is rejected when Shutdown starts + blocked := make(chan error, 1) + go func() { blocked <- p.SubmitTask(ctx, task) }() + time.Sleep(20 * time.Millisecond) + shutdownDone := make(chan error, 1) + go func() { shutdownDone <- p.Shutdown(ctx) }() + assert.ErrorIs(t, <-blocked, ErrPoolShutdown) + close(release) + require.NoError(t, <-shutdownDone) + + rec.mu.Lock() + defer rec.mu.Unlock() + assert.Equal(t, []string{"email/queue_full", "email/shutdown"}, rec.rejected) +} + +// Detach is final: a pool that has shut down no longer reports, so late +// Submit calls can't reach a recorder that has been attached to another pool. +func TestNoEventsAfterDetach(t *testing.T) { + rec := &fakeRecorder{} + p, err := New(WithLogger(discardLogger()), WithRecorder(rec)) + require.NoError(t, err) + require.NoError(t, p.Shutdown(context.Background())) + + assert.ErrorIs(t, p.SubmitTask(context.Background(), Task{Kind: "email", Run: func(context.Context) error { return nil }}), ErrPoolShutdown) + assert.Equal(t, int64(1), p.Metrics().JobsRejected(), "in-process counters keep counting") + rec.mu.Lock() + defer rec.mu.Unlock() + assert.Empty(t, rec.rejected) +} + +func TestAttacherLifecycle(t *testing.T) { + rec := &fakeRecorder{} + p, err := New(WithName("orders"), WithMinWorkers(2), WithMaxWorkers(8), WithQueueSize(64), + WithLogger(discardLogger()), WithRecorder(rec)) + require.NoError(t, err) + + rec.mu.Lock() + require.NotNil(t, rec.info, "Attach must be called by New") + assert.Equal(t, PoolInfo{Name: "orders", MinWorkers: 2, MaxWorkers: 8, QueueSize: 64}, *rec.info) + assert.Equal(t, 2, rec.stats.ActiveWorkers(), "stats reflect the live pool") + assert.False(t, rec.detached) + rec.mu.Unlock() + + require.NoError(t, p.Shutdown(context.Background())) + rec.mu.Lock() + defer rec.mu.Unlock() + assert.True(t, rec.detached, "Shutdown must call Detach") +} + +func TestAttachErrorFailsNew(t *testing.T) { + errRegister := errors.New("duplicate metrics") + _, err := New(WithRecorder(&fakeRecorder{attachErr: errRegister})) + assert.ErrorIs(t, err, errRegister) +} + +// panicRecorder panics on every event +type panicRecorder struct{ calls atomic.Int64 } + +func (r *panicRecorder) JobSubmitted(string) { r.calls.Add(1); panic("JobSubmitted") } +func (r *panicRecorder) JobRejected(string, RejectReason) { + r.calls.Add(1) + panic("JobRejected") +} + +func (r *panicRecorder) JobCompleted(string, Status, int, time.Duration, time.Duration) { + r.calls.Add(1) + panic("JobCompleted") +} +func (r *panicRecorder) JobDropped(string) { r.calls.Add(1); panic("JobDropped") } +func (r *panicRecorder) ScaledUp(int) { r.calls.Add(1); panic("ScaledUp") } + +type panicDetacher struct{ panicRecorder } + +func (*panicDetacher) Attach(PoolInfo, Metrics) error { return nil } +func (*panicDetacher) Detach() { panic("Detach") } + +// A recorder is user code: its panics must not kill workers or callers, and +// only the first one is logged. +func TestRecorderPanicsAreContained(t *testing.T) { + logs := &logRecorder{} + rec := &panicRecorder{} + done := make(chan TaskResult, 2) + p := newTestPool(t, WithMinWorkers(1), WithMaxWorkers(1), WithLogger(logs.logger()), WithRecorder(rec), + WithOnTaskDone(func(r TaskResult) { done <- r })) + + ctx := context.Background() + for range 2 { + require.NoError(t, p.Submit(ctx, func(context.Context) error { return nil }), "JobSubmitted panicked into the caller") + } + for range 2 { + select { + case r := <-done: + assert.Equal(t, StatusSuccess, r.Status, "the hook must still run after JobCompleted panics") + case <-time.After(2 * time.Second): + t.Fatal("worker died after a recorder panic") + } + } + + canceled, cancel := context.WithCancel(ctx) + cancel() + assert.ErrorIs(t, p.Submit(canceled, func(context.Context) error { return nil }), context.Canceled) + p.(*pool).metrics.recordScaleUp(1) + + assert.Equal(t, int64(2), p.Metrics().JobsProcessed()) + assert.Equal(t, int64(6), rec.calls.Load(), "every event still reaches the recorder") + assert.Len(t, logs.records("recorder panicked; later panics are ignored without logging"), 1) +} + +func TestRecorderPanicInDetachDoesNotHangShutdown(t *testing.T) { + logs := &logRecorder{} + p, err := New(WithLogger(logs.logger()), WithRecorder(&panicDetacher{})) + require.NoError(t, err) + + shutdownDone := make(chan error, 1) + go func() { shutdownDone <- p.Shutdown(context.Background()) }() + select { + case err := <-shutdownDone: + require.NoError(t, err) + case <-time.After(2 * time.Second): + t.Fatal("Shutdown hung after Detach panicked") + } + require.NoError(t, p.Shutdown(context.Background()), "a second Shutdown must not hang either") + records := logs.records("recorder panicked; later panics are ignored without logging") + require.Len(t, records, 1) + assert.Equal(t, "Detach", records[0]["method"]) +} diff --git a/retry.go b/retry.go new file mode 100644 index 0000000..b261c2c --- /dev/null +++ b/retry.go @@ -0,0 +1,313 @@ +package adaptivepool + +import ( + "context" + "errors" + "fmt" + "log/slog" + "math" + "math/rand/v2" + "slices" + "time" +) + +const ( + defaultRetryDelay = 100 * time.Millisecond + defaultMultiplier = 1.5 + maxDuration = time.Duration(math.MaxInt64) +) + +// RetryPolicy configures how failed jobs are retried. Retries run inline on +// the worker; errors are retried unless wrapped with Permanent or the job's +// context is done, and panics are never retried. A job that stops retrying +// fails with a *RetryError. +// +// A graceful Shutdown lets retries finish; a forced one aborts backoff waits. +type RetryPolicy struct { + // MaxAttempts is the maximum number of times a job runs, including the + // first attempt. Required and must be >= 1. + MaxAttempts int + + // Backoff computes the wait before each retry. + // Default: ExponentialBackoff{Base: 100ms} + Backoff Backoff + + // MaxDelay caps any single wait, including RetryAfter hints, so a job + // cannot hold a worker for an unbounded time. Zero means no cap. + MaxDelay time.Duration + + // Jitter draws each wait uniformly from [0, delay), after MaxDelay, to + // spread out retries of jobs that failed together. + Jitter bool + + // MaxElapsedTime bounds a job's total time across attempts and waits. + // Retrying stops if the next wait would exceed it; a running attempt is + // never interrupted. Zero means no budget. + MaxElapsedTime time.Duration + + // ErrorLimits caps attempts for specific errors. Failures are matched + // with errors.Is against each limit in order; the first match counts. + // MaxAttempts still applies to the job as a whole. + ErrorLimits []ErrorLimit + + // Clock is the time source used for backoff waits. Override it in tests. + // Default: the system clock + Clock Clock +} + +// ErrorLimit limits how many attempts may fail with errors matching Err. +type ErrorLimit struct { + Err error + MaxAttempts int +} + +// Backoff computes the delay before a retry. retry starts at 1 for the +// first retry. Implementations must be safe for concurrent use; the +// built-in ones are stateless values. +type Backoff interface { + Next(retry int) time.Duration +} + +// ConstantBackoff waits the same Delay before every retry. +type ConstantBackoff struct { + Delay time.Duration +} + +// Next implements Backoff +func (b ConstantBackoff) Next(int) time.Duration { + return b.Delay +} + +// LinearBackoff waits Base * retry: Base, 2*Base, 3*Base, ... +type LinearBackoff struct { + Base time.Duration +} + +// Next implements Backoff +func (b LinearBackoff) Next(retry int) time.Duration { + if b.Base > 0 && time.Duration(retry) > maxDuration/b.Base { + return maxDuration + } + return b.Base * time.Duration(retry) +} + +// ExponentialBackoff waits Base * Multiplier^(retry-1). +// A zero Multiplier defaults to 1.5. +type ExponentialBackoff struct { + Base time.Duration + Multiplier float64 +} + +// Next implements Backoff +func (b ExponentialBackoff) Next(retry int) time.Duration { + if b.Base == 0 { + return 0 // 0 * +Inf below would be NaN, which converts to an arbitrary Duration + } + m := b.Multiplier + if m == 0 { + m = defaultMultiplier + } + d := float64(b.Base) * math.Pow(m, float64(retry-1)) + if d >= float64(maxDuration) { + return maxDuration + } + return time.Duration(d) +} + +func (b ConstantBackoff) validate() error { return nonNegative("ConstantBackoff.Delay", b.Delay) } +func (b LinearBackoff) validate() error { return nonNegative("LinearBackoff.Base", b.Base) } +func (b ExponentialBackoff) validate() error { + // NaN fails the >= 1 check + if b.Multiplier != 0 && !(b.Multiplier >= 1 && !math.IsInf(b.Multiplier, 1)) { + return fmt.Errorf("%w: ExponentialBackoff.Multiplier must be a finite value >= 1", ErrInvalidConfig) + } + return nonNegative("ExponentialBackoff.Base", b.Base) +} + +func nonNegative(field string, d time.Duration) error { + if d < 0 { + return fmt.Errorf("%w: %s must not be negative", ErrInvalidConfig, field) + } + return nil +} + +// Clock abstracts time so retry timing can be tested deterministically. +type Clock interface { + Now() time.Time + After(d time.Duration) <-chan time.Time +} + +type systemClock struct{} + +func (systemClock) Now() time.Time { return time.Now() } +func (systemClock) After(d time.Duration) <-chan time.Time { return time.After(d) } + +// WithRetry enables retries for every job submitted to the pool. +// Default: disabled +func WithRetry(policy RetryPolicy) Option { + return func(c *Config) { + c.retry = &policy + } +} + +func (rp *RetryPolicy) validate() error { + if rp.MaxAttempts < 1 { + return fmt.Errorf("%w: retry MaxAttempts must be >= 1", ErrInvalidConfig) + } + if err := nonNegative("retry MaxDelay", rp.MaxDelay); err != nil { + return err + } + if err := nonNegative("retry MaxElapsedTime", rp.MaxElapsedTime); err != nil { + return err + } + for _, l := range rp.ErrorLimits { + if l.Err == nil || l.MaxAttempts < 1 { + return fmt.Errorf("%w: ErrorLimit needs a non-nil Err and MaxAttempts >= 1", ErrInvalidConfig) + } + } + if v, ok := rp.Backoff.(interface{ validate() error }); ok { + return v.validate() + } + return nil +} + +// retrier executes jobs according to a normalized RetryPolicy +type retrier struct { + policy RetryPolicy + logger *slog.Logger + stop <-chan struct{} // aborts backoff waits on forced shutdown +} + +func newRetrier(policy RetryPolicy, logger *slog.Logger, stop <-chan struct{}) *retrier { + if policy.Backoff == nil { + policy.Backoff = ExponentialBackoff{Base: defaultRetryDelay} + } + if policy.Clock == nil { + policy.Clock = systemClock{} + } + policy.ErrorLimits = slices.Clone(policy.ErrorLimits) + if logger == nil { + logger = slog.New(slog.DiscardHandler) + } + return &retrier{policy: policy, logger: logger, stop: stop} +} + +// execute runs the job until it succeeds or the policy says to stop. It +// returns the number of attempts made and the final error. +func (r *retrier) execute(w *jobWrapper) (int, error) { + ctx := w.ctx + var start time.Time + if r.policy.MaxElapsedTime > 0 { + start = r.policy.Clock.Now() + } + + // Per-error failure counts live on the stack for typical limit counts + var buf [8]int + var counts []int + if n := len(r.policy.ErrorLimits); n > len(buf) { + counts = make([]int, n) + } else { + counts = buf[:n] + } + + for attempt := 1; ; attempt++ { + err := runJob(ctx, w.job) + if err == nil { + return attempt, nil + } + if _, panicked := err.(*PanicError); panicked { + return attempt, err + } + if reason := r.stopReason(ctx, attempt, err, counts); reason != nil { + return attempt, &RetryError{Reason: reason, Attempts: attempt, Err: err} + } + delay := r.delay(attempt, err) + if r.policy.MaxElapsedTime > 0 && delay > r.policy.MaxElapsedTime-r.policy.Clock.Now().Sub(start) { + return attempt, &RetryError{Reason: ErrRetryBudgetExceeded, Attempts: attempt, Err: err} + } + r.logRetry(w, attempt, delay, err) + if waitErr := r.wait(ctx, delay); waitErr != nil { + return attempt, &RetryError{Reason: waitErr, Attempts: attempt, Err: err} + } + } +} + +func (r *retrier) logRetry(w *jobWrapper, attempt int, delay time.Duration, err error) { + if !r.logger.Enabled(w.ctx, slog.LevelDebug) { + return + } + r.logger.LogAttrs(w.ctx, slog.LevelDebug, "retrying task", + slog.String("task_id", w.taskID), + slog.String("kind", w.kind), + slog.Int("attempt", attempt), + slog.Duration("delay", delay), + slog.Any("err", err), + ) +} + +// stopReason returns why retrying must stop after a failed attempt, or nil to retry +func (r *retrier) stopReason(ctx context.Context, attempt int, err error, counts []int) error { + switch { + case hasMarker[*permanentError](err): + return ErrPermanentFailure + case ctx.Err() != nil: + return ctx.Err() + case attempt >= r.policy.MaxAttempts, r.errorLimitReached(err, counts): + return ErrRetriesExhausted + } + return nil +} + +// errorLimitReached counts err against the first matching ErrorLimit and +// reports whether that limit is now used up +func (r *retrier) errorLimitReached(err error, counts []int) bool { + for i, l := range r.policy.ErrorLimits { + if errors.Is(err, l.Err) { + counts[i]++ + return counts[i] >= l.MaxAttempts + } + } + return false +} + +// delay computes the wait before the given retry. A RetryAfter hint on err +// replaces the backoff value and is not jittered; MaxDelay caps both. +func (r *retrier) delay(retry int, err error) time.Duration { + if hint, ok := findMarker[*retryAfterError](err); ok { + return r.capDelay(hint.delay) + } + d := r.capDelay(r.policy.Backoff.Next(retry)) + if r.policy.Jitter && d > 0 { + d = rand.N(d) + } + return d +} + +func (r *retrier) capDelay(d time.Duration) time.Duration { + if r.policy.MaxDelay > 0 { + return min(d, r.policy.MaxDelay) + } + return d +} + +// wait blocks for d, returning early if the context is done or the pool is +// force-stopped +func (r *retrier) wait(ctx context.Context, d time.Duration) error { + if d <= 0 { + if err := ctx.Err(); err != nil { + return err + } + if closed(r.stop) { + return ErrPoolShutdown + } + return nil + } + select { + case <-ctx.Done(): + return ctx.Err() + case <-r.stop: + return ErrPoolShutdown + case <-r.policy.Clock.After(d): + return nil + } +} diff --git a/retry_test.go b/retry_test.go new file mode 100644 index 0000000..254c649 --- /dev/null +++ b/retry_test.go @@ -0,0 +1,462 @@ +package adaptivepool + +import ( + "context" + "errors" + "fmt" + "sync" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +// fakeClock advances instantly on After and records every requested wait. +type fakeClock struct { + mu sync.Mutex + now time.Time + waits []time.Duration +} + +func newFakeClock() *fakeClock { + return &fakeClock{now: time.Unix(0, 0)} +} + +func (c *fakeClock) Now() time.Time { + c.mu.Lock() + defer c.mu.Unlock() + return c.now +} + +func (c *fakeClock) After(d time.Duration) <-chan time.Time { + c.mu.Lock() + defer c.mu.Unlock() + c.now = c.now.Add(d) + c.waits = append(c.waits, d) + ch := make(chan time.Time, 1) + ch <- c.now + return ch +} + +func (c *fakeClock) Advance(d time.Duration) { + c.mu.Lock() + defer c.mu.Unlock() + c.now = c.now.Add(d) +} + +func (c *fakeClock) Waits() []time.Duration { + c.mu.Lock() + defer c.mu.Unlock() + return append([]time.Duration(nil), c.waits...) +} + +// failN returns a job that fails n times with err, then succeeds. +func failN(n int, err error) (Job, *int) { + calls := 0 + return func(context.Context) error { + calls++ + if calls <= n { + return err + } + return nil + }, &calls +} + +var errTransient = errors.New("transient") + +func newTestRetrier(policy RetryPolicy) *retrier { + return newRetrier(policy, nil, nil) +} + +func (r *retrier) run(ctx context.Context, job Job) (int, error) { + return r.execute(&jobWrapper{ctx: ctx, job: job}) +} + +func TestRetrySucceedsAfterFailures(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{MaxAttempts: 5, Backoff: ConstantBackoff{Delay: time.Second}, Clock: clock}) + + job, calls := failN(2, errTransient) + attempts, err := r.run(context.Background(), job) + + require.NoError(t, err) + assert.Equal(t, 3, attempts) + assert.Equal(t, 3, *calls) + assert.Equal(t, []time.Duration{time.Second, time.Second}, clock.Waits()) +} + +func TestRetryExhausted(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{MaxAttempts: 3, Clock: clock}) + + job, calls := failN(10, errTransient) + attempts, err := r.run(context.Background(), job) + + assert.Equal(t, 3, attempts) + assert.Equal(t, 3, *calls) + assert.ErrorIs(t, err, ErrRetriesExhausted) + assert.ErrorIs(t, err, errTransient) + assert.Equal(t, StatusRetriesExhausted, statusOf(err)) + + var re *RetryError + require.ErrorAs(t, err, &re) + assert.Equal(t, 3, re.Attempts) + assert.Equal(t, []time.Duration{100 * time.Millisecond, 150 * time.Millisecond}, clock.Waits(), "default exponential backoff") +} + +func TestRetrySingleAttempt(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{MaxAttempts: 1, Clock: clock}) + + attempts, err := r.run(context.Background(), func(context.Context) error { return errTransient }) + assert.Equal(t, 1, attempts) + assert.ErrorIs(t, err, ErrRetriesExhausted) + assert.Empty(t, clock.Waits()) +} + +func TestRetryStopsWhenContextDone(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + r := newTestRetrier(RetryPolicy{MaxAttempts: 5, Clock: newFakeClock()}) + + attempts, err := r.run(ctx, func(context.Context) error { + cancel() + return context.Canceled + }) + assert.Equal(t, 1, attempts, "context errors are not retried") + assert.ErrorIs(t, err, context.Canceled) + assert.Equal(t, StatusCanceled, statusOf(err)) +} + +func TestRetryWaitInterruptedByContext(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + r := newTestRetrier(RetryPolicy{MaxAttempts: 5, Backoff: ConstantBackoff{Delay: time.Hour}}) + + time.AfterFunc(20*time.Millisecond, cancel) + start := time.Now() + attempts, err := r.run(ctx, func(context.Context) error { return errTransient }) + + assert.Less(t, time.Since(start), time.Second, "backoff wait must abort on cancellation") + assert.Equal(t, 1, attempts) + assert.ErrorIs(t, err, context.Canceled) + assert.ErrorIs(t, err, errTransient) +} + +func TestRetryDoesNotRetryPanics(t *testing.T) { + r := newTestRetrier(RetryPolicy{MaxAttempts: 5, Clock: newFakeClock()}) + + attempts, err := r.run(context.Background(), func(context.Context) error { panic("bug") }) + assert.Equal(t, 1, attempts) + var pe *PanicError + assert.ErrorAs(t, err, &pe) +} + +func TestRetryPolicyValidation(t *testing.T) { + _, err := New(WithRetry(RetryPolicy{})) + assert.ErrorIs(t, err, ErrInvalidConfig) +} + +func TestPoolRetriesJobs(t *testing.T) { + results := make(chan TaskResult, 1) + p := newTestPool(t, + WithLogger(discardLogger()), + WithRetry(RetryPolicy{MaxAttempts: 3, Backoff: ConstantBackoff{Delay: time.Millisecond}}), + WithOnTaskDone(func(r TaskResult) { results <- r }), + ) + + job, _ := failN(2, errTransient) + require.NoError(t, p.SubmitTask(context.Background(), Task{ID: "t1", Run: job})) + + select { + case r := <-results: + assert.Equal(t, StatusSuccess, r.Status) + assert.Equal(t, 3, r.Attempts) + case <-time.After(2 * time.Second): + t.Fatal("task did not finish") + } +} + +func TestRetryMaxDelayCapsBackoff(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{ + MaxAttempts: 5, + Backoff: ExponentialBackoff{Base: time.Second, Multiplier: 2}, + MaxDelay: 3 * time.Second, + Clock: clock, + }) + + _, _ = r.run(context.Background(), func(context.Context) error { return errTransient }) + assert.Equal(t, []time.Duration{time.Second, 2 * time.Second, 3 * time.Second, 3 * time.Second}, clock.Waits()) +} + +func TestRetryFullJitter(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{ + MaxAttempts: 200, + Backoff: ConstantBackoff{Delay: time.Second}, + MaxDelay: 500 * time.Millisecond, + Jitter: true, + Clock: clock, + }) + + _, _ = r.run(context.Background(), func(context.Context) error { return errTransient }) + + waits := clock.Waits() + distinct := map[time.Duration]bool{} + for _, w := range waits { + distinct[w] = true + assert.GreaterOrEqual(t, w, time.Duration(0)) + assert.Less(t, w, 500*time.Millisecond, "jitter applies after MaxDelay") + } + assert.Greater(t, len(distinct), 1, "waits should be randomized") +} + +func TestRetryNegativeMaxDelayInvalid(t *testing.T) { + _, err := New(WithRetry(RetryPolicy{MaxAttempts: 2, MaxDelay: -time.Second})) + assert.ErrorIs(t, err, ErrInvalidConfig) +} + +func TestRetryMaxElapsedTime(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{ + MaxAttempts: 100, + Backoff: ConstantBackoff{Delay: 3 * time.Second}, + MaxElapsedTime: 10 * time.Second, + Clock: clock, + }) + + attempts, err := r.run(context.Background(), func(context.Context) error { return errTransient }) + + // Waits start at 0s, 3s and 6s; a fourth would end at 12s, past the 10s budget + assert.Equal(t, 4, attempts) + assert.Len(t, clock.Waits(), 3) + assert.ErrorIs(t, err, ErrRetryBudgetExceeded) + assert.ErrorIs(t, err, errTransient) + assert.Equal(t, StatusBudgetExceeded, statusOf(err)) +} + +func TestRetryMaxElapsedTimeCountsAttemptDuration(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{ + MaxAttempts: 100, + Backoff: ConstantBackoff{Delay: time.Second}, + MaxElapsedTime: 10 * time.Second, + Clock: clock, + }) + + attempts, err := r.run(context.Background(), func(context.Context) error { + clock.Advance(4 * time.Second) + return errTransient + }) + + // Attempts end at 4s, 9s and 14s; the third overruns the 10s budget + assert.Equal(t, 3, attempts) + assert.ErrorIs(t, err, ErrRetryBudgetExceeded) +} + +func TestRetryMaxElapsedTimeHugeDelayDoesNotOverflow(t *testing.T) { + r := newTestRetrier(RetryPolicy{ + MaxAttempts: 5, + Backoff: ExponentialBackoff{Base: time.Hour, Multiplier: 1e9}, + MaxElapsedTime: time.Minute, + Clock: newFakeClock(), + }) + + attempts, err := r.run(context.Background(), func(context.Context) error { return errTransient }) + assert.Equal(t, 1, attempts) + assert.ErrorIs(t, err, ErrRetryBudgetExceeded) +} + +func TestRetryStopsOnPermanent(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{MaxAttempts: 5, Clock: clock}) + errBadInput := errors.New("bad input") + + attempts, err := r.run(context.Background(), func(context.Context) error { + return fmt.Errorf("validating: %w", Permanent(errBadInput)) + }) + + assert.Equal(t, 1, attempts) + assert.Empty(t, clock.Waits()) + assert.ErrorIs(t, err, ErrPermanentFailure) + assert.ErrorIs(t, err, errBadInput) + assert.Equal(t, StatusPermanent, statusOf(err)) + assert.Equal(t, "permanent failure after 1 attempt(s): validating: bad input", err.Error()) +} + +func TestPermanentNil(t *testing.T) { + assert.NoError(t, Permanent(nil)) +} + +func TestRetryAfterOverridesBackoff(t *testing.T) { + clock := newFakeClock() + r := newTestRetrier(RetryPolicy{ + MaxAttempts: 4, + Backoff: ConstantBackoff{Delay: time.Second}, + MaxDelay: 10 * time.Second, + Jitter: true, + Clock: clock, + }) + errRateLimited := errors.New("429") + + calls := 0 + _, err := r.run(context.Background(), func(context.Context) error { + calls++ + switch calls { + case 1: + return RetryAfter(errRateLimited, 7*time.Second) + case 2: + return RetryAfter(errRateLimited, time.Minute) + } + return nil + }) + + require.NoError(t, err) + assert.Equal(t, []time.Duration{7 * time.Second, 10 * time.Second}, clock.Waits(), "hint is exact, not jittered, and capped by MaxDelay") +} + +func TestRetryAfterKeepsError(t *testing.T) { + errRateLimited := errors.New("429") + err := RetryAfter(errRateLimited, time.Second) + assert.ErrorIs(t, err, errRateLimited) + assert.Equal(t, "429", err.Error()) + assert.NoError(t, RetryAfter(nil, time.Second)) +} + +func TestRetryErrorLimits(t *testing.T) { + errRateLimited := errors.New("rate limited") + errTimeout := errors.New("timeout") + + tests := []struct { + name string + errs []error // error returned by each attempt; nil = success + wantAttempts int + wantErr error + }{ + {"limited error stops early", []error{errTimeout, errTimeout, errTimeout}, 2, ErrRetriesExhausted}, + {"wrapped errors match", []error{fmt.Errorf("op: %w", errTimeout), errTimeout}, 2, ErrRetriesExhausted}, + {"counts per error", []error{errTimeout, errRateLimited, errRateLimited, errRateLimited, nil}, 5, nil}, + {"MaxAttempts still applies", []error{errRateLimited, errTransient, errRateLimited, errTransient, errRateLimited, errTransient}, 6, ErrRetriesExhausted}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + r := newTestRetrier(RetryPolicy{ + MaxAttempts: 6, + ErrorLimits: []ErrorLimit{{Err: errTimeout, MaxAttempts: 2}, {Err: errRateLimited, MaxAttempts: 5}}, + Clock: newFakeClock(), + }) + calls := 0 + attempts, err := r.run(context.Background(), func(context.Context) error { + err := tt.errs[calls] + calls++ + return err + }) + assert.Equal(t, tt.wantAttempts, attempts) + if tt.wantErr == nil { + assert.NoError(t, err) + } else { + assert.ErrorIs(t, err, tt.wantErr) + } + }) + } +} + +func TestRetryErrorLimitsBeyondStackBuffer(t *testing.T) { + limits := make([]ErrorLimit, 10) + for i := range limits { + limits[i] = ErrorLimit{Err: fmt.Errorf("err %d", i), MaxAttempts: 3} + } + r := newTestRetrier(RetryPolicy{MaxAttempts: 10, ErrorLimits: limits, Clock: newFakeClock()}) + + attempts, err := r.run(context.Background(), func(context.Context) error { return limits[9].Err }) + assert.Equal(t, 3, attempts) + assert.ErrorIs(t, err, ErrRetriesExhausted) +} + +func TestRetryErrorLimitsValidation(t *testing.T) { + for _, l := range []ErrorLimit{{Err: nil, MaxAttempts: 1}, {Err: errTransient, MaxAttempts: 0}} { + _, err := New(WithRetry(RetryPolicy{MaxAttempts: 2, ErrorLimits: []ErrorLimit{l}})) + assert.ErrorIs(t, err, ErrInvalidConfig) + } +} + +func TestPoolRetryObservability(t *testing.T) { + var rec logRecorder + events := &fakeRecorder{} + results := make(chan TaskResult, 2) + p := newTestPool(t, + WithMinWorkers(1), WithMaxWorkers(1), + WithLogger(rec.logger()), + WithRecorder(events), + WithRetry(RetryPolicy{MaxAttempts: 3, Backoff: ConstantBackoff{Delay: time.Millisecond}}), + WithOnTaskDone(func(r TaskResult) { results <- r }), + ) + + ctx := context.Background() + recovers, _ := failN(1, errTransient) + require.NoError(t, p.SubmitTask(ctx, Task{ID: "a", Kind: "sync", Run: recovers})) + require.NoError(t, p.SubmitTask(ctx, Task{ID: "b", Kind: "sync", Run: func(context.Context) error { return errTransient }})) + + got := map[string]TaskResult{} + for range 2 { + select { + case r := <-results: + got[r.ID] = r + case <-time.After(2 * time.Second): + t.Fatal("tasks did not finish") + } + } + + assert.Equal(t, StatusSuccess, got["a"].Status) + assert.Equal(t, 2, got["a"].Attempts) + assert.Equal(t, StatusRetriesExhausted, got["b"].Status) + assert.Equal(t, 3, got["b"].Attempts) + assert.ErrorIs(t, got["b"].Err, errTransient) + + assert.Equal(t, int64(2), p.Metrics().JobsRetried()) + assert.Equal(t, int64(3), p.Metrics().RetryAttempts()) + assert.Equal(t, int64(1), p.Metrics().JobsFailed()) + + assert.ElementsMatch(t, []completedEvent{ + {kind: "sync", status: StatusSuccess, attempts: 2}, + {kind: "sync", status: StatusRetriesExhausted, attempts: 3}, + }, events.completedEvents()) + + retries := rec.records("retrying task") + require.Len(t, retries, 3) + assert.Equal(t, "sync", retries[0]["kind"]) + failed := rec.records("task failed") + require.Len(t, failed, 1) + assert.Equal(t, "b", failed[0]["task_id"]) + assert.Equal(t, "retries_exhausted", failed[0]["status"]) + assert.InDelta(t, 3, failed[0]["attempts"], 0) +} + +func TestForcedShutdownAbortsBackoff(t *testing.T) { + results := make(chan TaskResult, 1) + p, err := New( + WithMinWorkers(1), WithMaxWorkers(1), + WithLogger(discardLogger()), + WithRetry(RetryPolicy{MaxAttempts: 5, Backoff: ConstantBackoff{Delay: time.Hour}}), + WithOnTaskDone(func(r TaskResult) { results <- r }), + ) + require.NoError(t, err) + + attempted := make(chan struct{}) + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { + close(attempted) + return errTransient + })) + <-attempted + + ctx, cancel := context.WithTimeout(context.Background(), 50*time.Millisecond) + defer cancel() + start := time.Now() + _ = p.Shutdown(ctx) + assert.Less(t, time.Since(start), time.Second) + + r := <-results + assert.Equal(t, StatusShutdown, r.Status) + assert.ErrorIs(t, r.Err, ErrPoolShutdown) + assert.ErrorIs(t, r.Err, errTransient) +} diff --git a/shutdown.go b/shutdown.go index 5f26a25..27486f3 100644 --- a/shutdown.go +++ b/shutdown.go @@ -2,26 +2,31 @@ package adaptivepool import ( "context" - "log" + "log/slog" "time" ) -// Shutdown gracefully shuts down the pool +// Shutdown gracefully shuts down the pool. The first call does the work; a +// later call returns the first call's result, or ctx's error if ctx ends +// before the shutdown does. func (p *pool) Shutdown(ctx context.Context) error { - var shutdownErr error + if p.state.shutdownStarted.CompareAndSwap(false, true) { + p.logger.Info("initiating pool shutdown") - p.state.shutdownOnce.Do(func() { - log.Println("initiating pool shutdown") - - // Transition to draining state + // Transition to draining state and wake Submits blocked on a full queue p.state.setShutdownState(shutdownStateDraining) + close(p.state.closing) // Stop the dispatcher p.dispatcherCancel() p.dispatcherWg.Wait() - // Close the job queue to prevent new submissions + // Closing the queue is only safe once no Submit can still send to it. + // In-flight calls either finish their send or return via closing, so + // taking the lock is brief, and new Submits wait behind it. + p.state.submitMu.Lock() close(p.state.jobQueue) + p.state.submitMu.Unlock() // Wait for workers to finish with timeout workersDone := make(chan struct{}) @@ -30,49 +35,82 @@ func (p *pool) Shutdown(ctx context.Context) error { close(workersDone) }() + drained := false select { case <-workersDone: // All workers finished gracefully - log.Println("all workers finished gracefully") + p.logger.Info("all workers finished gracefully") + drained = true case <-ctx.Done(): // Timeout or cancellation - force shutdown - log.Println("shutdown timeout, forcing worker termination") - - // Signal all workers to terminate - currentWorkers := p.state.getWorkerCount() - for range currentWorkers { - select { - case p.state.workerShutdown <- struct{}{}: - default: - } + p.logger.Warn("shutdown timeout, forcing worker termination") + + // Abort retry backoff waits and stop idle workers + close(p.state.forceStop) + + // Drop what is still queued. The queue is closed, so this ends + // once it is empty; a worker that took a job just before seeing + // forceStop drops that one itself. + for job := range p.state.jobQueue { + p.dropJob(job) } // Wait a bit more for workers to respond select { case <-workersDone: - log.Println("workers terminated after force signal") + p.logger.Info("workers terminated after force signal") + drained = true case <-time.After(1 * time.Second): - log.Println("some workers may not have terminated cleanly") - shutdownErr = ctx.Err() + p.logger.Warn("some workers may not have terminated cleanly") + p.state.shutdownErr = ctx.Err() } } + dropped := p.metrics.JobsDropped() + if dropped > 0 { + p.state.shutdownErr = &ShutdownError{Dropped: int(dropped), Err: ctx.Err()} + } + + p.detachRecorder(workersDone, drained) + // Transition to terminated state p.state.setShutdownState(shutdownStateTerminated) close(p.state.shutdownDone) - // Check if there are any jobs left in the queue - remainingJobs := p.state.getQueueDepth() - if remainingJobs > 0 { - log.Printf("shutdown complete with %d jobs remaining in queue", remainingJobs) + if dropped > 0 { + p.logger.Warn("shutdown complete, dropped queued jobs", slog.Int64("dropped", dropped)) } else { - log.Println("shutdown complete, all jobs processed") + p.logger.Info("shutdown complete, all jobs processed") } - }) + return p.state.shutdownErr + } - // Wait for shutdown to complete - <-p.state.shutdownDone + // Not sync.Once: it would hold this call until the first one finishes, + // whatever ctx says + if closed(p.state.shutdownDone) { + return p.state.shutdownErr + } + select { + case <-p.state.shutdownDone: + return p.state.shutdownErr + case <-ctx.Done(): + return ctx.Err() + } +} - return shutdownErr +// detachRecorder detaches the recorder once no worker can still report to it: +// now if the workers have exited, otherwise when the last one does +func (p *pool) detachRecorder(workersDone <-chan struct{}, drained bool) { + if p.metrics.rec == nil { + return + } + if drained { + p.metrics.detach() + return + } + go func() { + <-workersDone + p.metrics.detach() + }() } diff --git a/shutdown_test.go b/shutdown_test.go index f2b8a52..02382cd 100644 --- a/shutdown_test.go +++ b/shutdown_test.go @@ -2,6 +2,8 @@ package adaptivepool import ( "context" + "fmt" + "sync" "sync/atomic" "testing" "time" @@ -71,9 +73,12 @@ func TestShutdownWithTimeout(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond) defer cancel() + // One job is running; the other four are still queued and get dropped err = pool.Shutdown(ctx) - assert.Error(t, err) - assert.Equal(t, context.DeadlineExceeded, err) + assert.ErrorIs(t, err, context.DeadlineExceeded) + var se *ShutdownError + require.ErrorAs(t, err, &se) + assert.Equal(t, numJobs-1, se.Dropped) // Cleanup close(blockChan) @@ -191,3 +196,274 @@ func TestShutdownConcurrent(t *testing.T) { assert.NoError(t, err) } } + +// Regression: a Submit blocked on a full queue panicked with "send on +// closed channel" when Shutdown closed the queue. +func TestShutdownWakesBlockedSubmit(t *testing.T) { + p, err := New(WithMinWorkers(1), WithMaxWorkers(1), WithQueueSize(1), WithLogger(discardLogger())) + require.NoError(t, err) + + release := make(chan struct{}) + slow := func(context.Context) error { //nolint:unparam + <-release + return nil + } + require.NoError(t, p.Submit(context.Background(), slow)) // occupies the worker + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + require.NoError(t, p.Submit(context.Background(), slow)) // fills the queue + + blocked := make(chan error, 1) + go func() { blocked <- p.Submit(context.Background(), slow) }() + time.Sleep(20 * time.Millisecond) // let it block on the full queue + + shutdownDone := make(chan error, 1) + go func() { shutdownDone <- p.Shutdown(context.Background()) }() + + select { + case err := <-blocked: + assert.ErrorIs(t, err, ErrPoolShutdown) + case <-time.After(2 * time.Second): + t.Fatal("blocked Submit was not woken by Shutdown") + } + close(release) + require.NoError(t, <-shutdownDone) +} + +// Regression: Submits racing with Shutdown must never panic, and every job +// whose Submit returned nil must still run during the graceful drain. +func TestSubmitConcurrentWithShutdown(t *testing.T) { + for range 20 { + p, err := New(WithMinWorkers(2), WithMaxWorkers(4), WithQueueSize(8), WithLogger(discardLogger())) + require.NoError(t, err) + + var accepted, executed atomic.Int64 + job := func(context.Context) error { //nolint:unparam + executed.Add(1) + return nil + } + + var submitters sync.WaitGroup + for range 16 { + submitters.Go(func() { + for { + if err := p.Submit(context.Background(), job); err != nil { + assert.ErrorIs(t, err, ErrPoolShutdown) + return + } + accepted.Add(1) + } + }) + } + + time.Sleep(5 * time.Millisecond) + require.NoError(t, p.Shutdown(context.Background())) + submitters.Wait() + assert.Equal(t, accepted.Load(), executed.Load(), "accepted jobs must not be dropped") + } +} + +// Regression: select picks randomly when forceStop and the queue are both +// ready, so a worker that finished its job after a forced shutdown could +// still start queued ones. +func TestForcedShutdownDoesNotStartQueuedJobs(t *testing.T) { + for range 20 { + var started atomic.Int64 + release := make(chan struct{}) + p, err := New(WithMinWorkers(1), WithMaxWorkers(1), WithQueueSize(50), WithLogger(discardLogger())) + require.NoError(t, err) + + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { + <-release + return nil + })) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + for range 50 { + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { + started.Add(1) + return nil + })) + } + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + go func() { + <-ctx.Done() + time.Sleep(20 * time.Millisecond) // forceStop is closed by now + close(release) + }() + var se *ShutdownError + require.ErrorAs(t, p.Shutdown(ctx), &se) + cancel() + assert.Zero(t, started.Load(), "queued jobs started after a forced shutdown") + assert.Equal(t, 50, se.Dropped) + } +} + +// A forced shutdown reports each queued job it drops through OnTaskDone, the +// recorder and Shutdown's error, so callers can tell that work was lost. +func TestForcedShutdownReportsDroppedJobs(t *testing.T) { + const queued = 10 + release := make(chan struct{}) + rec := &fakeRecorder{} + var mu sync.Mutex + var results []TaskResult + p, err := New(WithMinWorkers(1), WithMaxWorkers(1), WithQueueSize(queued), + WithLogger(discardLogger()), WithRecorder(rec), + WithOnTaskDone(func(r TaskResult) { + mu.Lock() + defer mu.Unlock() + results = append(results, r) + })) + require.NoError(t, err) + + bg := context.Background() + require.NoError(t, p.SubmitTask(bg, Task{ID: "running", Kind: "k", Run: func(context.Context) error { + <-release + return nil + }})) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + for i := range queued { + require.NoError(t, p.SubmitTask(bg, Task{ID: fmt.Sprint(i), Kind: "k", Run: func(context.Context) error { return nil }})) + } + + ctx, cancel := context.WithTimeout(bg, 20*time.Millisecond) + defer cancel() + go func() { + <-ctx.Done() + time.Sleep(20 * time.Millisecond) // forceStop is closed by now + close(release) + }() + err = p.Shutdown(ctx) + + var se *ShutdownError + require.ErrorAs(t, err, &se) + assert.Equal(t, queued, se.Dropped) + assert.ErrorIs(t, err, context.DeadlineExceeded) + assert.ErrorIs(t, p.Shutdown(bg), context.DeadlineExceeded, "a later call should see the same result") + assert.Equal(t, int64(queued), p.Metrics().JobsDropped()) + assert.Equal(t, int64(1), p.Metrics().JobsProcessed(), "dropped jobs aren't processed") + + mu.Lock() + defer mu.Unlock() + require.Len(t, results, queued+1) + for _, r := range results { + if r.ID == "running" { + assert.Equal(t, StatusSuccess, r.Status) + continue + } + assert.Equal(t, StatusShutdown, r.Status) + assert.Zero(t, r.Attempts) + assert.ErrorIs(t, r.Err, ErrPoolShutdown) + } + rec.mu.Lock() + defer rec.mu.Unlock() + assert.Len(t, rec.dropped, queued) + assert.Len(t, rec.completed, 1) +} + +// Regression: a zero-length backoff skipped the forceStop check, so the retry +// loop kept running at full speed after a forced shutdown. +func TestForcedShutdownStopsZeroDelayRetries(t *testing.T) { + var attempts atomic.Int64 + p, err := New(WithMinWorkers(1), WithMaxWorkers(1), WithLogger(discardLogger()), + WithRetry(RetryPolicy{MaxAttempts: 1 << 30, Backoff: ConstantBackoff{}})) + require.NoError(t, err) + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { + attempts.Add(1) + return errTransient + })) + require.Eventually(t, func() bool { return attempts.Load() > 0 }, time.Second, time.Millisecond) + + ctx, cancel := context.WithTimeout(context.Background(), 30*time.Millisecond) + defer cancel() + start := time.Now() + require.NoError(t, p.Shutdown(ctx), "the worker should stop within the grace period") + assert.Less(t, time.Since(start), 900*time.Millisecond) + + after := attempts.Load() + time.Sleep(50 * time.Millisecond) + assert.Equal(t, after, attempts.Load(), "retries kept running after Shutdown returned") +} + +// Regression: Detach ran when the grace period ended even if workers were +// still running and reporting to the recorder. +func TestRecorderDetachedAfterWorkersExit(t *testing.T) { + rec := &fakeRecorder{} + p, err := New(WithMinWorkers(1), WithMaxWorkers(1), WithLogger(discardLogger()), WithRecorder(rec)) + require.NoError(t, err) + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { + time.Sleep(1300 * time.Millisecond) // outlives the 1s grace period + return nil + })) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + require.ErrorIs(t, p.Shutdown(ctx), context.DeadlineExceeded) + + rec.mu.Lock() + assert.False(t, rec.detached, "detached while a worker was still running") + rec.mu.Unlock() + + require.Eventually(t, func() bool { + rec.mu.Lock() + defer rec.mu.Unlock() + return rec.detached + }, 3*time.Second, 10*time.Millisecond) + assert.Len(t, rec.completedEvents(), 1, "the late job should be reported before Detach") +} + +// Regression: a second Shutdown returned nil even when the first had timed +// out, because only the call that ran the shutdown kept its result. +func TestLaterShutdownReportsFirstResult(t *testing.T) { + release := make(chan struct{}) + defer close(release) + p, err := New(WithMinWorkers(1), WithMaxWorkers(1), WithLogger(discardLogger())) + require.NoError(t, err) + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { + <-release + return nil + })) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + require.ErrorIs(t, p.Shutdown(ctx), context.DeadlineExceeded) // the worker is stuck + + assert.ErrorIs(t, p.Shutdown(context.Background()), context.DeadlineExceeded, + "a later call should report that the shutdown timed out") + expired, cancelExpired := context.WithCancel(context.Background()) + cancelExpired() + assert.ErrorIs(t, p.Shutdown(expired), context.DeadlineExceeded, + "a finished shutdown's result wins over the caller's own context") +} + +// Regression: sync.Once made a later Shutdown wait for the first to finish +// whatever its own context said. +func TestLaterShutdownHonoursItsOwnContext(t *testing.T) { + release := make(chan struct{}) + p, err := New(WithMinWorkers(1), WithMaxWorkers(1), WithLogger(discardLogger())) + require.NoError(t, err) + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { + <-release + return nil + })) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + + first := make(chan error, 1) + go func() { first <- p.Shutdown(context.Background()) }() // blocked on the running job + require.Eventually(t, func() bool { return p.(*pool).state.isShutdown() }, time.Second, time.Millisecond) + + ctx, cancel := context.WithTimeout(context.Background(), 30*time.Millisecond) + defer cancel() + later := make(chan error, 1) + go func() { later <- p.Shutdown(ctx) }() + select { + case err := <-later: + assert.ErrorIs(t, err, context.DeadlineExceeded) + case <-time.After(2 * time.Second): + t.Fatal("a later Shutdown ignored its own context") + } + + close(release) + require.NoError(t, <-first) +} diff --git a/submit.go b/submit.go index 53b4b92..938cfe5 100644 --- a/submit.go +++ b/submit.go @@ -7,32 +7,87 @@ import ( // Submit Submits a job to the pool for execution func (p *pool) Submit(ctx context.Context, job Job) error { - // Check if pool is shutdown + return p.SubmitTask(ctx, Task{Run: job}) +} + +// SubmitTask submits a task to the pool for execution +func (p *pool) SubmitTask(ctx context.Context, task Task) error { + return p.submit(ctx, task, true) +} + +// TrySubmit submits a task only if the queue has space +func (p *pool) TrySubmit(ctx context.Context, task Task) error { + return p.submit(ctx, task, false) +} + +func (p *pool) submit(ctx context.Context, task Task, wait bool) error { + if task.Run == nil { + return ErrNilJob + } + + // Shutdown sets the state, then takes the write lock to close the queue: + // either this call sees the shutdown or Shutdown waits for it to finish. + p.state.submitMu.RLock() + defer p.state.submitMu.RUnlock() + if p.state.isShutdown() { - p.metrics.recordJobRejected() + p.metrics.recordJobRejected(task.Kind, RejectShutdown) return ErrPoolShutdown } - // creating job wrapper + // Without Task.Context, ctx is also the job's context: a job queued with a + // done one would be cancelled before it runs + runCtx := task.Context + if runCtx == nil { + if ctx.Err() != nil { + return p.rejectDone(ctx, task.Kind) + } + runCtx = ctx + } wrapper := jobWrapper{ - job: job, - SubmittedAt: time.Now(), - id: p.state.nextID(), - ctx: ctx, + job: task.Run, + submittedAt: int64(time.Since(p.epoch)), + ctx: runCtx, + taskID: task.ID, + kind: task.Kind, + } + + // Enqueue immediately if there is space. Without this, a done submit + // context (with Task.Context set) would race the send in the select below + // and be rejected at random even with room. + select { + case p.state.jobQueue <- wrapper: + p.metrics.recordJobSubmitted(task.Kind) + return nil + default: + } + + if !wait { + p.metrics.recordJobRejected(task.Kind, RejectQueueFull) + return ErrQueueFull } - // Try to enqueue the job with backpressure + // Queue is full: wait for space with backpressure select { case p.state.jobQueue <- wrapper: - // Job successfully enqueued + p.metrics.recordJobSubmitted(task.Kind) return nil + case <-p.state.closing: + p.metrics.recordJobRejected(task.Kind, RejectShutdown) + return ErrPoolShutdown + case <-ctx.Done(): - // Context cancelled or timed out - p.metrics.recordJobRejected() - if ctx.Err() == context.DeadlineExceeded { - return ErrTimeout - } - return ctx.Err() + return p.rejectDone(ctx, task.Kind) + } +} + +// rejectDone records and returns the rejection for a done submit context +func (p *pool) rejectDone(ctx context.Context, kind string) error { + if ctx.Err() == context.DeadlineExceeded { + p.metrics.recordJobRejected(kind, RejectTimeout) + return ErrTimeout } + p.metrics.recordJobRejected(kind, RejectCanceled) + return ctx.Err() } diff --git a/task.go b/task.go new file mode 100644 index 0000000..cf235e4 --- /dev/null +++ b/task.go @@ -0,0 +1,96 @@ +package adaptivepool + +import ( + "context" + "time" +) + +// Task is a Job annotated with identity used for observability. +type Task struct { + // ID identifies a single task (e.g. an order or request ID). It appears in + // logs and TaskResult only, never in metric labels, so it may be unique. + ID string + + // Kind groups tasks of the same type (e.g. "send_email") and is used as a + // metric label. Keep the set of kinds small and bounded. + Kind string + + // Run is the work to execute. + Run Job + + // Context is the context Run executes with. When nil, the ctx passed to + // SubmitTask is used for both waiting for queue space and execution. Set it + // so a submit deadline doesn't cancel the job; see ExamplePool_SubmitTask. + Context context.Context +} + +// TaskResult describes how a task finished. It is passed to the OnTaskDone hook. +type TaskResult struct { + ID string + Kind string + + // QueueWait is the time between submission and the start of execution + QueueWait time.Duration + // Duration is the total execution time, including any retries + Duration time.Duration + // Attempts is the number of times the job was run + Attempts int + + Status Status + // Err is the final error, nil on success + Err error +} + +// Status describes how a task finished. The same values are used for the +// "status" metric label and log attribute. +type Status string + +const ( + // StatusSuccess means the job returned nil + StatusSuccess Status = "success" + // StatusError means the job returned an error while its context was still active + StatusError Status = "error" + // StatusPanic means the job panicked; the error is a *PanicError + StatusPanic Status = "panic" + // StatusRetriesExhausted means the job failed on every allowed attempt + StatusRetriesExhausted Status = "retries_exhausted" + // StatusBudgetExceeded means retrying stopped because of MaxElapsedTime + StatusBudgetExceeded Status = "budget_exceeded" + // StatusPermanent means the job returned an error wrapped with Permanent, + // with or without retries + StatusPermanent Status = "permanent" + // StatusShutdown means a forced pool shutdown aborted retrying, or dropped + // the task from the queue before it ran (Attempts is 0) + StatusShutdown Status = "shutdown" + // StatusCanceled means the job failed after its context was done + StatusCanceled Status = "canceled" +) + +// statusOf classifies the final error of a task. Errors reaching it come +// straight from runJob or the retrier, so a type switch is sufficient, apart +// from Permanent, which also reaches it unwrapped when retries are disabled. +func statusOf(err error) Status { + switch e := err.(type) { + case nil: + return StatusSuccess + case *PanicError: + return StatusPanic + case *RetryError: + switch e.Reason { + case ErrRetriesExhausted: + return StatusRetriesExhausted + case ErrRetryBudgetExceeded: + return StatusBudgetExceeded + case ErrPermanentFailure: + return StatusPermanent + case ErrPoolShutdown: + return StatusShutdown + case context.Canceled, context.DeadlineExceeded: + return StatusCanceled + } + } + if hasMarker[*permanentError](err) { + return StatusPermanent + } + return StatusError +} diff --git a/task_test.go b/task_test.go new file mode 100644 index 0000000..d8e8c59 --- /dev/null +++ b/task_test.go @@ -0,0 +1,139 @@ +package adaptivepool + +import ( + "context" + "errors" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" +) + +func TestSubmitTask(t *testing.T) { + p := newTestPool(t, WithMinWorkers(1), WithMaxWorkers(1)) + + done := make(chan struct{}) + err := p.SubmitTask(context.Background(), Task{ + ID: "order-1", + Kind: "send_email", + Run: func(context.Context) error { + close(done) + return nil + }, + }) + require.NoError(t, err) + + select { + case <-done: + case <-time.After(2 * time.Second): + t.Fatal("task did not run") + } +} + +func TestSubmitNilJob(t *testing.T) { + p := newTestPool(t) + + assert.ErrorIs(t, p.Submit(context.Background(), nil), ErrNilJob) + assert.ErrorIs(t, p.SubmitTask(context.Background(), Task{ID: "x"}), ErrNilJob) +} + +type ctxKey struct{} + +func TestTaskContextOutlivesSubmitContext(t *testing.T) { + p := newTestPool(t, WithMinWorkers(1), WithMaxWorkers(1), WithLogger(discardLogger())) + + reqCtx, cancelReq := context.WithCancel(context.WithValue(context.Background(), ctxKey{}, "trace-1")) + result := make(chan error, 1) + err := p.SubmitTask(reqCtx, Task{ + Context: context.WithoutCancel(reqCtx), + Run: func(ctx context.Context) error { + assert.Equal(t, "trace-1", ctx.Value(ctxKey{}), "values carry over") + select { + case <-time.After(20 * time.Millisecond): + result <- nil + case <-ctx.Done(): + result <- ctx.Err() + } + return nil + }, + }) + require.NoError(t, err) + cancelReq() // the request ends right after submitting + + select { + case err := <-result: + assert.NoError(t, err, "job must not be cancelled with the submit context") + case <-time.After(2 * time.Second): + t.Fatal("job did not finish") + } +} + +func TestTaskContextBoundsOnlyTheWait(t *testing.T) { + p := newTestPool(t, WithMinWorkers(1), WithMaxWorkers(1), WithQueueSize(1), WithLogger(discardLogger())) + + release := make(chan struct{}) + defer close(release) + block := func(context.Context) error { //nolint:unparam + <-release + return nil + } + require.NoError(t, p.Submit(context.Background(), block)) + require.Eventually(t, func() bool { return p.Metrics().BusyWorkers() == 1 }, time.Second, time.Millisecond) + require.NoError(t, p.Submit(context.Background(), block)) // queue now full + + submitCtx, cancel := context.WithTimeout(context.Background(), 20*time.Millisecond) + defer cancel() + err := p.SubmitTask(submitCtx, Task{Context: context.Background(), Run: block}) + assert.ErrorIs(t, err, ErrTimeout, "the submit context still bounds waiting for space") +} + +func TestTaskContextUsedForRetries(t *testing.T) { + results := make(chan TaskResult, 1) + p := newTestPool(t, + WithLogger(discardLogger()), + WithRetry(RetryPolicy{MaxAttempts: 5, Backoff: ConstantBackoff{Delay: time.Hour}}), + WithOnTaskDone(func(r TaskResult) { results <- r }), + ) + + runCtx, cancelRun := context.WithCancel(context.Background()) + attempted := make(chan struct{}) + require.NoError(t, p.SubmitTask(context.Background(), Task{ + Context: runCtx, + Run: func(context.Context) error { + close(attempted) + return errors.New("transient") + }, + })) + <-attempted + cancelRun() // aborts the hour-long backoff wait + + select { + case r := <-results: + assert.Equal(t, StatusCanceled, r.Status) + case <-time.After(2 * time.Second): + t.Fatal("backoff wait was not tied to the execution context") + } +} + +// Regression: without WithRetry, Permanent errors were reported as plain +// errors, so the status depended on whether retries were configured. +func TestPermanentStatusDoesNotDependOnRetry(t *testing.T) { + cause := errors.New("bad input") + for name, opts := range map[string][]Option{ + "no retry": nil, + "retry": {WithRetry(RetryPolicy{MaxAttempts: 3, Backoff: ConstantBackoff{}})}, + } { + t.Run(name, func(t *testing.T) { + done := make(chan TaskResult, 1) + opts = append(opts, WithLogger(discardLogger()), WithOnTaskDone(func(r TaskResult) { done <- r })) + p := newTestPool(t, opts...) + require.NoError(t, p.Submit(context.Background(), func(context.Context) error { return Permanent(cause) })) + + r := <-done + assert.Equal(t, StatusPermanent, r.Status) + assert.Equal(t, 1, r.Attempts) + assert.ErrorIs(t, r.Err, cause) + }) + } +}