Skip to content

Commit 899f30f

Browse files
sbalabanov-zzclaude
andcommitted
refactor(metrics): replace timers with histograms
Remove the NamedTimer helper and stop recording any durations as tally timers. Ad-hoc durations now go through NamedDurationHistogram (default latency buckets), and Op.Complete records its latency as a histogram named {name}.latency (previously a {name}.latency timer plus a redundant {name}.latency_histogram). Migrated call sites: consumer controller/ack-nack latency, mysql subscriber poll latency/message age, and Op.Complete. Timers are unsafe in a distributed system: per-host percentiles cannot be merged, so any aggregation beyond the mean is imprecise. Bucketed histograms merge exactly across hosts. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent 75f62a6 commit 899f30f

6 files changed

Lines changed: 53 additions & 66 deletions

File tree

platform/consumer/consumer.go

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -376,7 +376,7 @@ func (m *consumer) processDelivery(ctx context.Context, controller Controller, d
376376
}
377377
}
378378

379-
metrics.NamedTimer(controllerScope, opName, "controller_latency", elapsed, metrics.NewTag("success", successTag))
379+
metrics.NamedDurationHistogram(controllerScope, opName, "controller_latency", elapsed, metrics.NewTag("success", successTag))
380380

381381
if err != nil {
382382
// Single explicit classification pass through the configured
@@ -443,7 +443,7 @@ func (m *consumer) processDelivery(ctx context.Context, controller Controller, d
443443
metrics.NamedCounter(controllerScope, opName, "nack_errors", 1)
444444
} else {
445445
metrics.NamedCounter(controllerScope, opName, "nack_count", 1)
446-
metrics.NamedTimer(controllerScope, opName, "ack_nack_latency", time.Since(nackStart),
446+
metrics.NamedDurationHistogram(controllerScope, opName, "ack_nack_latency", time.Since(nackStart),
447447
metrics.NewTag("operation", "nack"),
448448
metrics.NewTag("success", "true"),
449449
)
@@ -461,7 +461,7 @@ func (m *consumer) processDelivery(ctx context.Context, controller Controller, d
461461
"error", ackErr,
462462
)
463463
metrics.NamedCounter(controllerScope, opName, "ack_errors", 1)
464-
metrics.NamedTimer(controllerScope, opName, "ack_nack_latency", time.Since(ackStart),
464+
metrics.NamedDurationHistogram(controllerScope, opName, "ack_nack_latency", time.Since(ackStart),
465465
metrics.NewTag("operation", "ack"),
466466
metrics.NewTag("success", "false"),
467467
)
@@ -470,7 +470,7 @@ func (m *consumer) processDelivery(ctx context.Context, controller Controller, d
470470

471471
metrics.NamedCounter(controllerScope, opName, "messages_processed", 1)
472472
metrics.NamedCounter(controllerScope, opName, "ack_count", 1)
473-
metrics.NamedTimer(controllerScope, opName, "ack_nack_latency", time.Since(ackStart),
473+
metrics.NamedDurationHistogram(controllerScope, opName, "ack_nack_latency", time.Since(ackStart),
474474
metrics.NewTag("operation", "ack"),
475475
metrics.NewTag("success", "true"),
476476
)

platform/consumer/consumer_test.go

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -470,14 +470,14 @@ func TestConsumer_ObservabilityTags(t *testing.T) {
470470

471471
snapshot := testScope.Snapshot()
472472

473-
timers := snapshot.Timers()
474-
assert.NotEmpty(t, timers, "Should have timer metrics")
473+
histograms := snapshot.Histograms()
474+
assert.NotEmpty(t, histograms, "Should have histogram metrics")
475475

476476
var foundLatency bool
477-
for _, timer := range timers {
478-
if strings.Contains(timer.Name(), "controller_latency") {
477+
for _, histogram := range histograms {
478+
if strings.Contains(histogram.Name(), "controller_latency") {
479479
foundLatency = true
480-
tags := timer.Tags()
480+
tags := histogram.Tags()
481481
if tt.expectSuccess {
482482
assert.Equal(t, "true", tags["success"])
483483
} else {
@@ -542,7 +542,7 @@ func TestConsumer_AckNackLatencyTracking(t *testing.T) {
542542
<-done
543543

544544
snapshot := scope.Snapshot()
545-
assert.NotEmpty(t, snapshot.Timers(), "Should have timer metrics for latency tracking")
545+
assert.NotEmpty(t, snapshot.Histograms(), "Should have histogram metrics for latency tracking")
546546
assert.NotEmpty(t, snapshot.Counters(), "Should have counter metrics")
547547

548548
err = c.Stop(30000)

platform/extension/messagequeue/mysql/subscriber.go

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -835,7 +835,7 @@ func (w *partitionWorker) pollAndDeliver(ctx context.Context) error {
835835

836836
// Calculate message age for metrics
837837
messageAge := time.Duration(time.Now().UnixMilli()-row.PublishedAt) * time.Millisecond
838-
metrics.NamedTimer(s.scope, "poll", "message_age", messageAge,
838+
metrics.NamedDurationHistogram(s.scope, "poll", "message_age", messageAge,
839839
metrics.NewTag("topic", sub.topic),
840840
metrics.NewTag("partition_key", partitionKey),
841841
)
@@ -920,7 +920,7 @@ func (w *partitionWorker) pollAndDeliver(ctx context.Context) error {
920920
metrics.NewTag("topic", sub.topic),
921921
metrics.NewTag("partition_key", partitionKey),
922922
)
923-
metrics.NamedTimer(s.scope, "poll", "latency", elapsed,
923+
metrics.NamedDurationHistogram(s.scope, "poll", "latency", elapsed,
924924
metrics.NewTag("topic", sub.topic),
925925
metrics.NewTag("partition_key", partitionKey),
926926
)

platform/metrics/README.md

Lines changed: 13 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -1,12 +1,12 @@
11
# Metrics Utilities (`platform/metrics`)
22

3-
The `metrics` package provides reusable helpers for emitting counters, timers, histograms, and gauges on a `tally.Scope`. It standardizes metric names across controllers and integrates with `platform/errs` for automatic error classification tags.
3+
The `metrics` package provides reusable helpers for emitting counters, histograms, and gauges on a `tally.Scope`. It standardizes metric names across controllers and integrates with `platform/errs` for automatic error classification tags.
44

55
## Design
66

77
**Free functions on `tally.Scope`** — no wrapper types. Existing constructors accept `tally.Scope` and don't need to change.
88

9-
**Operation lifecycle**`Begin` and `Complete` tie the full metrics lifecycle together. `Begin` captures the start time and emits `{name}.called`; `Complete` emits succeeded/failed counters, a latency timer, and a latency histogram. This prevents mismatched or forgotten metrics calls.
9+
**Operation lifecycle**`Begin` and `Complete` tie the full metrics lifecycle together. `Begin` captures the start time and emits `{name}.called`; `Complete` emits succeeded/failed counters and a latency histogram. This prevents mismatched or forgotten metrics calls.
1010

1111
**Error-aware tagging**`ErrorTags` integrates with `platform/errs` to produce `error_origin=user|infra`, `retryable=true|false`, and `dependency=true` tags automatically. `Complete` uses these to tag latency metrics on failure.
1212

@@ -19,7 +19,7 @@ For any operation with a clear start/end, use `Begin`/`Complete`:
1919
| Function | Emits |
2020
|----------|-------|
2121
| `Begin(scope, name, ...tags)` | `{name}.called` counter +1, returns `Op` |
22-
| `op.Complete(err)` | `{name}.succeeded` or `{name}.failed` counter, `{name}.latency` timer, `{name}.latency_histogram` histogram — all tagged with `result=success\|error` and error classification tags on failure |
22+
| `op.Complete(err)` | `{name}.succeeded` or `{name}.failed` counter, `{name}.latency` histogram — tagged with `result=success\|error` and error classification tags on failure |
2323

2424
```go
2525
// RPC controller
@@ -43,13 +43,11 @@ func (c *Controller) Process(ctx context.Context, delivery consumer.Delivery) (r
4343

4444
On success, `Complete` emits:
4545
- `{name}.succeeded` counter +1
46-
- `{name}.latency` timer tagged `result=success`
47-
- `{name}.latency_histogram` histogram tagged `result=success`
46+
- `{name}.latency` histogram tagged `result=success`
4847

4948
On failure, `Complete` emits:
5049
- `{name}.failed` counter +1
51-
- `{name}.latency` timer tagged `result=error`, `error_origin=user|infra`, `retryable=true|false`, and optionally `dependency=true`
52-
- `{name}.latency_histogram` histogram with the same tags
50+
- `{name}.latency` histogram tagged `result=error`, `error_origin=user|infra`, `retryable=true|false`, and optionally `dependency=true`
5351

5452
## Named Helpers
5553

@@ -58,25 +56,29 @@ For ad-hoc metrics that don't fit the Begin/Complete lifecycle. All follow the `
5856
| Function | Emits | Example |
5957
|----------|-------|---------|
6058
| `NamedCounter(scope, name, counter, value, ...tags)` | `{name}.{counter}` counter | `publish.attempts` |
61-
| `NamedTimer(scope, name, timer, duration, ...tags)` | `{name}.{timer}` timer | `publish.queue_latency` |
59+
| `NamedDurationHistogram(scope, name, histogram, duration, ...tags)` | `{name}.{histogram}` histogram (default latency buckets) | `publish.queue_latency` |
6260
| `NamedHistogram(scope, name, histogram, buckets, ...tags)` | `{name}.{histogram}` histogram | `process.duration` |
6361
| `NamedGauge(scope, name, gauge, value, ...tags)` | `{name}.{gauge}` gauge | `consumer.pending_messages` |
6462

6563
```go
6664
// Count a specific sub-event
6765
metrics.NamedCounter(c.scope, "publish", "attempts", 1)
6866

69-
// Record a specific sub-latency
70-
metrics.NamedTimer(c.scope, "publish", "queue_latency", elapsed)
67+
// Record a one-shot sub-latency as a histogram (default latency buckets)
68+
metrics.NamedDurationHistogram(c.scope, "publish", "queue_latency", elapsed)
7169

7270
// Track current queue depth (goes up and down)
7371
metrics.NamedGauge(c.scope, "consumer", "pending_messages", float64(len(pending)))
7472

75-
// Create a reusable histogram (store on struct, call RecordDuration per invocation)
73+
// Create a reusable histogram with custom buckets (store on struct, call RecordDuration per invocation)
7674
h := metrics.NamedHistogram(c.scope, "process", "duration", tally.DurationBuckets{...})
7775
h.RecordDuration(elapsed)
7876
```
7977

78+
### Why histograms, not timers
79+
80+
Durations are recorded as **histograms**, never timers. In a distributed system every service instance emits its own metrics, and the monitoring backend aggregates them across hosts. Timer percentiles (p50/p99/max) are computed per host and cannot be merged — averaging two hosts' p99 values, or taking the max of their maxes, does not yield the true fleet-wide p99. Only the mean survives cross-host aggregation intact, so every percentile you actually care about becomes imprecise. Bucketed histograms merge exactly: summing per-host bucket counts reconstructs the true global distribution, so percentiles stay accurate at any aggregation level.
81+
8082
## Error Tags
8183

8284
`ErrorTags` classifies errors using `platform/errs` and returns tags for dimensional filtering:

platform/metrics/metrics.go

Lines changed: 20 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -87,19 +87,21 @@ func Begin(scope tally.Scope, name string, tags ...Tag) Op {
8787
}
8888

8989
// Complete records the outcome of the operation. It emits a {name}.succeeded or
90-
// {name}.failed counter based on err, and records elapsed time on both
91-
// {name}.latency (timer) and {name}.latency_histogram (histogram with
92-
// defaultLatencyBuckets for percentile distributions), tagged with result=success|error.
93-
// On failure, error classification tags (error_origin, retryable, dependency)
94-
// are added to both the timer and histogram.
90+
// {name}.failed counter based on err, and records elapsed time on the
91+
// {name}.latency histogram (using defaultLatencyBuckets for percentile
92+
// distributions), tagged with result=success|error. On failure, error
93+
// classification tags (error_origin, retryable, dependency) are added to the
94+
// histogram.
95+
//
96+
// Latency is recorded as a histogram rather than a timer because timer
97+
// percentiles cannot be merged across hosts (see NamedDurationHistogram).
9598
func (o Op) Complete(err error) {
9699
elapsed := time.Since(o.start)
97100

98101
if err == nil {
99102
o.scope.Counter("succeeded").Inc(1)
100103
s := o.scope.Tagged(map[string]string{"result": "success"})
101-
s.Timer("latency").Record(elapsed)
102-
s.Histogram("latency_histogram", defaultLatencyBuckets).RecordDuration(elapsed)
104+
s.Histogram("latency", defaultLatencyBuckets).RecordDuration(elapsed)
103105
return
104106
}
105107

@@ -110,18 +112,24 @@ func (o Op) Complete(err error) {
110112
latencyTags[t.Key] = t.Value
111113
}
112114
s := o.scope.Tagged(latencyTags)
113-
s.Timer("latency").Record(elapsed)
114-
s.Histogram("latency_histogram", defaultLatencyBuckets).RecordDuration(elapsed)
115+
s.Histogram("latency", defaultLatencyBuckets).RecordDuration(elapsed)
115116
}
116117

117118
// NamedCounter increments the {name}.{counter} counter by value.
118119
func NamedCounter(scope tally.Scope, name string, counter string, value int64, tags ...Tag) {
119120
tagged(scope, tags).SubScope(name).Counter(counter).Inc(value)
120121
}
121122

122-
// NamedTimer records a duration on the {name}.{timer} timer.
123-
func NamedTimer(scope tally.Scope, name string, timer string, d time.Duration, tags ...Tag) {
124-
tagged(scope, tags).SubScope(name).Timer(timer).Record(d)
123+
// NamedDurationHistogram records a duration on the {name}.{histogram} histogram
124+
// using defaultLatencyBuckets. Use it for one-shot latency/duration measurements
125+
// that don't fit the Begin/Complete lifecycle.
126+
//
127+
// Prefer histograms over timers for durations: in a distributed system, timer
128+
// percentiles (p50/p99/max) are computed per-host and then merged, which is
129+
// statistically invalid — only the mean survives aggregation. Bucketed
130+
// histograms merge exactly across hosts, so every percentile stays accurate.
131+
func NamedDurationHistogram(scope tally.Scope, name string, histogram string, d time.Duration, tags ...Tag) {
132+
tagged(scope, tags).SubScope(name).Histogram(histogram, defaultLatencyBuckets).RecordDuration(d)
125133
}
126134

127135
// NamedHistogram returns a tally.Histogram at {name}.{histogram} with the given

platform/metrics/metrics_test.go

Lines changed: 8 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -105,14 +105,9 @@ func TestComplete(t *testing.T) {
105105
assert.True(t, ok, "expected process.succeeded counter")
106106
assert.Equal(t, int64(1), c.Value())
107107

108-
timers := snapshot.Timers()
109-
timer, ok := timers["process.latency+result=success"]
110-
assert.True(t, ok, "expected process.latency timer with result=success")
111-
assert.NotEmpty(t, timer.Values())
112-
113108
histograms := snapshot.Histograms()
114-
_, ok = histograms["process.latency_histogram+result=success"]
115-
assert.True(t, ok, "expected process.latency_histogram with result=success")
109+
_, ok = histograms["process.latency+result=success"]
110+
assert.True(t, ok, "expected process.latency histogram with result=success")
116111
} else {
117112
c, ok := counters["process.failed+"]
118113
assert.True(t, ok, "expected process.failed counter")
@@ -127,15 +122,7 @@ func TestComplete(t *testing.T) {
127122
tagSuffix += ",result=" + tt.expectResultTag
128123
tagSuffix += ",retryable=" + tt.expectRetryable
129124

130-
timerKey := "process.latency+" + tagSuffix
131-
timers := snapshot.Timers()
132-
timer, ok := timers[timerKey]
133-
assert.True(t, ok, "expected timer key %s, got keys: %v", timerKey, timerKeys(timers))
134-
if ok {
135-
assert.NotEmpty(t, timer.Values())
136-
}
137-
138-
histogramKey := "process.latency_histogram+" + tagSuffix
125+
histogramKey := "process.latency+" + tagSuffix
139126
histograms := snapshot.Histograms()
140127
_, ok = histograms[histogramKey]
141128
assert.True(t, ok, "expected histogram key %s, got keys: %v", histogramKey, histogramKeys(histograms))
@@ -172,15 +159,14 @@ func TestNamedCounter(t *testing.T) {
172159
assert.Equal(t, int64(5), c.Value())
173160
}
174161

175-
func TestNamedTimer(t *testing.T) {
162+
func TestNamedDurationHistogram(t *testing.T) {
176163
scope := tally.NewTestScope("", nil)
177-
NamedTimer(scope, "publish", "queue_latency", 42*time.Millisecond)
164+
NamedDurationHistogram(scope, "publish", "queue_latency", 42*time.Millisecond)
178165

179166
snapshot := scope.Snapshot()
180-
timers := snapshot.Timers()
181-
timer, ok := timers["publish.queue_latency+"]
182-
assert.True(t, ok, "expected publish.queue_latency timer")
183-
assert.Equal(t, []time.Duration{42 * time.Millisecond}, timer.Values())
167+
histograms := snapshot.Histograms()
168+
_, ok := histograms["publish.queue_latency+"]
169+
assert.True(t, ok, "expected publish.queue_latency histogram, got keys: %v", histogramKeys(histograms))
184170
}
185171

186172
func TestNamedHistogram(t *testing.T) {
@@ -269,15 +255,6 @@ func TestErrorTags(t *testing.T) {
269255
}
270256
}
271257

272-
// timerKeys extracts map keys for error messages.
273-
func timerKeys(m map[string]tally.TimerSnapshot) []string {
274-
keys := make([]string, 0, len(m))
275-
for k := range m {
276-
keys = append(keys, k)
277-
}
278-
return keys
279-
}
280-
281258
// counterKeys extracts map keys for error messages.
282259
func counterKeys(m map[string]tally.CounterSnapshot) []string {
283260
keys := make([]string, 0, len(m))

0 commit comments

Comments
 (0)