Skip to content

Commit 7ead66e

Browse files
alexluongclaude
andcommitted
feat(logmq): parallelize the post-persist pipeline, one goroutine per entry
After the batched insert, each entry's pipeline now runs on its own goroutine — dispatch-and-move-on — and an attempt's events are sent concurrently under a 5s emit timeout. A slow eval or sink send no longer blocks persisting the next batch, and one destination's slow sink no longer serializes everyone else's sends. Entries process in no particular order, including within a destination (discussed on #980): the consecutive-failure counter is a set of attempt IDs, so counting is idempotent and commutative, and per-process ordering was cosmetic anyway with multiple logmq replicas. No pools, queues, or sizing knobs: in-flight work is naturally bounded by arrival rate × the emit timeout, and Shutdown drains the in-flight goroutines (bounded by the same timeout). Characterization tests updated for the ordering relaxation: assertions pin topic multisets and disable calls, never arrival order or attempt identity; tests that need a deterministic sequence (success-reset keystone, suppression window) pace messages one at a time. New tests pin the decoupling (slow send/eval doesn't block persistence), same-destination independence, and shutdown draining. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
1 parent 296121e commit 7ead66e

6 files changed

Lines changed: 350 additions & 84 deletions

internal/logmq/batchprocessor.go

Lines changed: 66 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ import (
44
"context"
55
"errors"
66
"fmt"
7+
"sync"
78
"time"
89

910
"github.com/hookdeck/outpost/internal/alert"
@@ -13,11 +14,19 @@ import (
1314
"github.com/hookdeck/outpost/internal/opevents"
1415
"github.com/mikestefanello/batcher"
1516
"go.uber.org/zap"
17+
"golang.org/x/sync/errgroup"
1618
)
1719

1820
// ErrInvalidLogEntry is returned when a LogEntry is missing required fields.
1921
var ErrInvalidLogEntry = errors.New("invalid log entry: both event and attempt are required")
2022

23+
// emitTimeout caps a single sink send. It is the system's definition of the
24+
// worst acceptable send latency, and it bounds each entry goroutine's
25+
// lifetime: in-flight work steady-states at arrival rate × this timeout even
26+
// when every send is stuck, and the shutdown drain is bounded by it. Anything
27+
// slower fails into the nack/redelivery path.
28+
const emitTimeout = 5 * time.Second
29+
2130
// LogStore defines the interface for persisting log entries.
2231
// This is a consumer-defined interface containing only what logmq needs.
2332
type LogStore interface {
@@ -82,14 +91,25 @@ type BatchProcessorConfig struct {
8291
}
8392

8493
// BatchProcessor batches log entries and writes them to the log store, then
85-
// runs the alert pipeline per entry — evaluate, act on the verdict (disable,
86-
// operator events), dedup replays — serially in the batch loop.
94+
// runs the alert pipeline per entry on its own goroutine — dispatch-and-move-on,
95+
// so a slow eval or sink send never blocks persistence of the next batch.
96+
//
97+
// Entries process in no particular order, including within a destination: the
98+
// consecutive-failure count tolerates approximate order (its store is a set of
99+
// attempt IDs, so counting is idempotent and commutative; only a success/
100+
// failure race around the reset can skew it), and per-process ordering was
101+
// cosmetic anyway with multiple logmq replicas interleaving a destination's
102+
// attempts. See the discussion on the parallelism RFC.
87103
type BatchProcessor struct {
88104
ctx context.Context
89105
logger *logging.Logger
90106
logStore LogStore
91107
alerts AlertPipeline
92108
batcher *batcher.Batcher[*mqs.Message]
109+
// inflight tracks entry goroutines so Shutdown can drain them. Each is
110+
// bounded by emitTimeout, so the wait is bounded too.
111+
inflight sync.WaitGroup
112+
shutdownOnce sync.Once
93113
}
94114

95115
// NewBatchProcessor creates a new batch processor for log entries.
@@ -130,11 +150,16 @@ func (bp *BatchProcessor) Add(ctx context.Context, msg *mqs.Message) error {
130150
return nil
131151
}
132152

133-
// Shutdown gracefully shuts down the batch processor. The batcher flushes
134-
// pending batches, so every buffered message reaches a terminal state before
135-
// Shutdown returns.
153+
// Shutdown gracefully shuts down the batch processor: the batcher first
154+
// (flushes pending batches, which may still dispatch entry goroutines), then
155+
// the in-flight entries drain. Every dispatched message reaches a terminal
156+
// state before Shutdown returns, and the drain is bounded by emitTimeout.
157+
// Idempotent.
136158
func (bp *BatchProcessor) Shutdown() {
137-
bp.batcher.Shutdown()
159+
bp.shutdownOnce.Do(func() {
160+
bp.batcher.Shutdown()
161+
bp.inflight.Wait()
162+
})
138163
}
139164

140165
// processBatch processes a batch of messages.
@@ -227,7 +252,11 @@ func (bp *BatchProcessor) processBatch(_ string, msgs []*mqs.Message) {
227252
zap.Int("count", len(validMsgs)),
228253
zap.Int64("insert_duration_ms", time.Since(insertStart).Milliseconds()))
229254

230-
// Run the alert pipeline per persisted entry.
255+
// Spawn one goroutine per persisted entry and return — the batch loop
256+
// never waits on eval or delivery. In-flight goroutines are bounded by
257+
// arrival rate × emitTimeout (each lives at most about one send latency),
258+
// and every fetched message reaches ack/nack well inside the broker's
259+
// visibility window.
231260
for i, entry := range entries {
232261
if bp.alerts.Evaluator == nil {
233262
validMsgs[i].Ack()
@@ -243,7 +272,10 @@ func (bp *BatchProcessor) processBatch(_ string, msgs []*mqs.Message) {
243272
continue
244273
}
245274

246-
bp.processEntry(bp.ctx, entry, validMsgs[i])
275+
msg := validMsgs[i]
276+
bp.inflight.Go(func() {
277+
bp.processEntry(bp.ctx, entry, msg)
278+
})
247279
}
248280
}
249281

@@ -302,20 +334,30 @@ func (bp *BatchProcessor) processEntry(ctx context.Context, entry *models.LogEnt
302334
return
303335
}
304336

305-
// Deliver the attempt's events. Any failure nacks with nothing marked, so
337+
// Deliver the attempt's events concurrently; arrival order within an
338+
// attempt is not guaranteed. Any failure nacks with nothing marked, so
306339
// redelivery re-runs the attempt in full — events already sent may go out
307340
// again (at-least-once).
341+
g, gctx := errgroup.WithContext(ctx)
308342
for _, de := range events {
309-
if err := bp.send(ctx, de, entry); err != nil {
310-
bp.logger.Ctx(ctx).Error("opevent delivery failed",
311-
zap.Error(err),
312-
zap.String("topic", de.event.Topic),
313-
zap.String("attempt_id", entry.Attempt.ID),
314-
zap.String("event_id", entry.Event.ID),
315-
zap.String("destination_id", entry.Destination.ID))
316-
msg.Nack()
317-
return
318-
}
343+
g.Go(func() error {
344+
sendCtx, cancel := context.WithTimeout(gctx, emitTimeout)
345+
defer cancel()
346+
if err := bp.send(sendCtx, de, entry); err != nil {
347+
bp.logger.Ctx(ctx).Error("opevent delivery failed",
348+
zap.Error(err),
349+
zap.String("topic", de.event.Topic),
350+
zap.String("attempt_id", entry.Attempt.ID),
351+
zap.String("event_id", entry.Event.ID),
352+
zap.String("destination_id", entry.Destination.ID))
353+
return err
354+
}
355+
return nil
356+
})
357+
}
358+
if g.Wait() != nil {
359+
msg.Nack()
360+
return
319361
}
320362

321363
if err := bp.alerts.ProcessedIdemp.MarkProcessed(ctx, key); err != nil {
@@ -338,10 +380,11 @@ type deliveryEvent struct {
338380
}
339381

340382
// plan acts on an evaluation and builds the operator events owed for this
341-
// attempt — disabled, consecutive_failure, exhausted_retries, sent in slice
342-
// order. The disable (a DB write) happens here: it's an action, not a
343-
// notification, and it must precede event construction so the payloads carry
344-
// the destination's latest state (disabled).
383+
// attempt — disabled, consecutive_failure, exhausted_retries. They are sent
384+
// concurrently, so slice order carries no meaning. The disable (a DB write)
385+
// happens here: it's an action, not a notification, and it must precede event
386+
// construction so the payloads carry the destination's latest state
387+
// (disabled).
345388
func (bp *BatchProcessor) plan(ctx context.Context, eval alert.Evaluation, entry *models.LogEntry) ([]deliveryEvent, error) {
346389
if eval.ConsecutiveFailure == nil && !eval.RetriesExhausted {
347390
return nil, nil

internal/logmq/batchprocessor_test.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -48,7 +48,7 @@ func (m *mockLogStore) getInserted() (events []*models.Event, attempts []*models
4848
}
4949

5050
// mockQueueMessage implements mqs.QueueMessage for testing. Terminal state is
51-
// atomic: acks/nacks land off the test goroutine.
51+
// atomic: acks/nacks land on per-entry goroutines.
5252
type mockQueueMessage struct {
5353
acked atomic.Bool
5454
nacked atomic.Bool
Lines changed: 122 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,122 @@
1+
package logmq_test
2+
3+
// delivery. Each entry delivers on its own goroutine, so a slow sink stalls only
4+
// the messages that owe events, never the batch loop.
5+
6+
import (
7+
"fmt"
8+
"testing"
9+
"time"
10+
11+
"github.com/hookdeck/outpost/internal/models"
12+
"github.com/stretchr/testify/assert"
13+
"github.com/stretchr/testify/require"
14+
)
15+
16+
// A batch-1 attempt whose alert delivery hangs must not delay batch 2's
17+
// persistence or ack. (If sends ran serially in the batch loop, batch 2 would
18+
// wait on batch 1's sink call.)
19+
func TestCharacterization_SlowDeliveryDoesNotBlockPersistence(t *testing.T) {
20+
t.Parallel()
21+
h := newHarness(t, harnessConfig{
22+
batcher: batcherConfig{itemCount: 1},
23+
// max=2, thresholds[50,100] → a single failure (count 1 = 50%) alerts.
24+
alert: alertConfig{autoDisableCount: 2, thresholds: []int{50, 100}},
25+
doubles: doublesConfig{
26+
sinkBlockOn: map[string]bool{"att_slow": true},
27+
},
28+
})
29+
30+
tenant := "tenant_d1"
31+
32+
// Batch 1: alerting failure whose send blocks.
33+
cmSlow, msgSlow := newCountingMessage(makeEntry("dest_d1_slow", tenant, "att_slow", models.AttemptStatusFailed))
34+
h.add(msgSlow)
35+
36+
// Wait until the delivery is actually blocked inside the sink.
37+
require.Eventually(t, func() bool { return h.sink.inflightSends() >= 1 },
38+
5*time.Second, 5*time.Millisecond, "the slow delivery should reach the sink")
39+
40+
// Batch 2: a plain success — persists and acks while batch 1's send hangs.
41+
cmOK, msgOK := newCountingMessage(makeEntry("dest_d1_ok", tenant, "att_ok", models.AttemptStatusSuccess))
42+
h.add(msgOK)
43+
h.waitTerminal([]*countingMessage{cmOK})
44+
cmOK.requireAcked(t)
45+
require.Len(t, h.listAttempt("dest_d1_ok"), 1, "batch 2 persisted while batch 1's delivery hangs")
46+
47+
// The slow message is still in flight: persisted but no terminal state.
48+
require.Len(t, h.listAttempt("dest_d1_slow"), 1, "the slow attempt itself persisted immediately")
49+
assert.EqualValues(t, 0, cmSlow.acks()+cmSlow.nacks(), "the slow message stays un-acked until its delivery completes")
50+
51+
// Release the sink: the blocked delivery completes and acks.
52+
h.sink.release()
53+
h.waitTerminal([]*countingMessage{cmSlow})
54+
cmSlow.requireAcked(t)
55+
assert.Equal(t, []string{topicCF}, topics(h.sink.forDest("dest_d1_slow")))
56+
}
57+
58+
// A hot destination's alerting attempts deliver in parallel — one slow send
59+
// doesn't serialize the destination's other sends (the old per-dest serial
60+
// loop did exactly that).
61+
func TestCharacterization_HotDestinationDeliversInParallel(t *testing.T) {
62+
t.Parallel()
63+
h := newHarness(t, harnessConfig{
64+
batcher: batcherConfig{itemCount: 3},
65+
// max=100 with thresholds 1/2/3% → counts 1, 2 and 3 each cross one
66+
// threshold, so all three attempts alert.
67+
alert: alertConfig{autoDisableCount: 100, thresholds: []int{1, 2, 3}},
68+
doubles: doublesConfig{
69+
sinkBlockOn: map[string]bool{topicCF: true}, // every cf send blocks
70+
},
71+
})
72+
73+
destA, tenant := "dest_d2", "tenant_d2"
74+
msgs := make([]*countingMessage, 0, 3)
75+
for i := 1; i <= 3; i++ {
76+
cm, msg := newCountingMessage(makeEntry(destA, tenant, fmt.Sprintf("att_%d", i), models.AttemptStatusFailed))
77+
msgs = append(msgs, cm)
78+
h.add(msg)
79+
}
80+
81+
// All three sends block in the sink AT THE SAME TIME — same destination,
82+
// different goroutines.
83+
require.Eventually(t, func() bool { return h.sink.inflightSends() >= 3 },
84+
5*time.Second, 5*time.Millisecond, "the destination's deliveries should run concurrently")
85+
86+
h.sink.release()
87+
h.waitTerminal(msgs)
88+
for _, m := range msgs {
89+
m.requireAcked(t)
90+
}
91+
assert.GreaterOrEqual(t, h.sink.maxInflightSends(), int32(3))
92+
assert.ElementsMatch(t, []string{"att_1", "att_2", "att_3"}, attemptIDs(h.sink.forDest(destA)))
93+
}
94+
95+
// Shutdown drains in-flight deliveries: every dispatched entry reaches its
96+
// terminal state before Shutdown returns.
97+
func TestCharacterization_ShutdownDrainsDeliveries(t *testing.T) {
98+
t.Parallel()
99+
h := newHarness(t, harnessConfig{
100+
batcher: batcherConfig{itemCount: 1},
101+
alert: alertConfig{autoDisableCount: 2, thresholds: []int{50, 100}},
102+
doubles: doublesConfig{
103+
sinkBlockOn: map[string]bool{"att_drain": true},
104+
},
105+
})
106+
107+
cm, msg := newCountingMessage(makeEntry("dest_d3", "tenant_d3", "att_drain", models.AttemptStatusFailed))
108+
h.add(msg)
109+
require.Eventually(t, func() bool { return h.sink.inflightSends() >= 1 },
110+
5*time.Second, 5*time.Millisecond)
111+
112+
// Release while Shutdown is waiting on the drain.
113+
go func() {
114+
time.Sleep(50 * time.Millisecond)
115+
h.sink.release()
116+
}()
117+
h.bp.Shutdown()
118+
119+
// Shutdown returned → the delivery completed and acked.
120+
cm.requireAcked(t)
121+
assert.Equal(t, []string{topicCF}, topics(h.sink.forDest("dest_d3")))
122+
}

internal/logmq/characterization_harness_test.go

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -15,14 +15,19 @@ package logmq_test
1515
// - per-message ack/nack counters (exactly-once terminal state)
1616
// - logStore.ListAttempt / ListEvent
1717
//
18-
// Per-destination order only — never assert global cross-destination order.
18+
// Entries process concurrently and in no particular order (goroutine per
19+
// entry), so never assert arrival order — across destinations OR within one.
20+
// Tests whose semantics need a deterministic sequence pace it themselves:
21+
// add one message, waitTerminal, add the next.
1922
//
2023
// Files in this suite (concern → file):
2124
// - characterization_harness_test.go shared setup, doubles, helpers
22-
// - characterization_ordering_test.go eval ordering & counting
25+
// - characterization_ordering_test.go failure counting & thresholds
2326
// - characterization_idempotency_test.go replay / idempotency
2427
// - characterization_acknowledgement_test.go ack/nack exactly-once
2528
// - characterization_validation_test.go intake (parse / dedup / persist)
29+
// - characterization_decoupling_test.go persistence decoupled from delivery
30+
// - characterization_postprocess_test.go post-persist eval concurrency
2631

2732
import (
2833
"context"

0 commit comments

Comments
 (0)