diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 0e03efdc..7a4b2089 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -84,10 +84,12 @@ is no release-candidate branch. |:---|:---| | `docs/ogc-api-tiles.md` | `docs/ogc-api-tiles.md` | | `docs/tile-matrix-sets.md` | `docs/ogc-api-tiles.md`, `tms/doc.go`, `tms/registry.go` | - | `docs/layered-cache.md` | `README.md` § "Layered cache" | + | `docs/layered-cache.md` | `README.md` § "Layered cache", `observability/prometheus/README.md` | | `docs/configuration.md` § Redis | `cache/redis/README.md` | | `docs/tracing.md`, `docs/configuration.md` § Tracing | `tracing/README.md` | - | `docs/logging.md` | `internal/log/log.go`, `tracing/README.md` § "Correlating logs with traces" | + | `docs/logging.md` | `internal/log/log.go`, `tracing/README.md` §§ "Correlating logs with traces", "Correlating metrics with traces" | + | `docs/http-endpoints.md` § `/metrics` | `observability/prometheus/README.md`, `observability/prometheus.metricsHandler` | + | `docs/tracing.md` § "Relationship to metrics" | `observability/prometheus/README.md` § "Trace exemplars", `tracing/README.md` § "Correlating metrics with traces" | Once the pull request is open a maintainer reviews it and may ask for changes. Keep it up to date as other work lands on `master` ahead of yours. diff --git a/atlas/cache_init_test.go b/atlas/cache_init_test.go index 42a70249..83202f0c 100644 --- a/atlas/cache_init_test.go +++ b/atlas/cache_init_test.go @@ -8,6 +8,15 @@ import ( "github.com/MapColonies/shigola/cache" ) +// TestCheckCacheTypes asserts the exact set of cache types the tree registers, +// which makes it sensitive to the fake types the other test files in this +// package register through cache.Register — a process-wide registry with no way +// to unregister. +// +// It passes because Go runs a package's tests in declaration order, files taken +// in sorted order, and every file that registers a fake sorts after this one. +// That is load-bearing: a new test file registering a fake type from a name +// sorting before "cache_init_test.go" fails this test rather than its own. func TestCheckCacheTypes(t *testing.T) { c := cache.Registered() exp := []string{"azblob", "file", "multi", "redis", "s3", "gcs"} diff --git a/atlas/cache_observability_test.go b/atlas/cache_observability_test.go index b85213ff..26115de1 100644 --- a/atlas/cache_observability_test.go +++ b/atlas/cache_observability_test.go @@ -11,6 +11,7 @@ import ( "github.com/MapColonies/shigola/cache" "github.com/MapColonies/shigola/dict" "github.com/MapColonies/shigola/internal/faketier" + "github.com/MapColonies/shigola/internal/ttools" "github.com/MapColonies/shigola/observability" "github.com/MapColonies/shigola/observability/prometheus" ) @@ -96,21 +97,7 @@ func counter(t *testing.T, name string, labels map[string]string) float64 { } for _, m := range family.GetMetric() { - matched := true - for k, v := range labels { - found := false - for _, pair := range m.GetLabel() { - if pair.GetName() == k && pair.GetValue() == v { - found = true - break - } - } - if !found { - matched = false - break - } - } - if !matched { + if !ttools.HasLabels(m.GetLabel(), labels) { continue } diff --git a/atlas/cache_trace_exemplar_test.go b/atlas/cache_trace_exemplar_test.go new file mode 100644 index 00000000..4ad06a30 --- /dev/null +++ b/atlas/cache_trace_exemplar_test.go @@ -0,0 +1,171 @@ +package atlas + +import ( + "context" + "testing" + "time" + + promclient "github.com/prometheus/client_golang/prometheus" + "go.opentelemetry.io/otel/sdk/trace/tracetest" + + "github.com/MapColonies/shigola/cache" + "github.com/MapColonies/shigola/internal/faketier" + "github.com/MapColonies/shigola/internal/faketracer" + "github.com/MapColonies/shigola/internal/log" + "github.com/MapColonies/shigola/internal/ttools" + "github.com/MapColonies/shigola/tracing" +) + +// Tier names are unique to this file for the reason the neighbouring test files +// give: the observer registers against the process-wide registry. + +// TestExemplarNamesTheSpanThatMeasuredIt is what the wrapping order in +// instrumentCache is for, checked rather than asserted in prose. +// +// Both prior tickets left a comment saying tracing goes outside the metric +// wrapper so that the operation's span is the active one when the duration is +// observed (MAPCO-11497, and the same at server.NewRouter). Nothing depended on +// it until exemplars: with the order inverted every exemplar on the per-tier +// histogram would name the cache-wide span instead — the same value for every +// tier, on the one histogram whose whole purpose is telling tiers apart. +// +// The two rows are the two levels the claim has to hold at, and they fail +// differently, which is why the per-tier row also names the inversion +// explicitly: a whole-cache exemplar naming the cache span is right, and a tier +// exemplar naming it is the bug. +func TestExemplarNamesTheSpanThatMeasuredIt(t *testing.T) { + type tcase struct { + hotType, durableType string + family string + labels map[string]string + // wantSpan picks the span the exemplar must name out of the exporter. + wantSpan func(*testing.T, *tracetest.InMemoryExporter) tracetest.SpanStub + // rejectCacheSpan is the inversion this row can catch: a tier exemplar + // naming the cache-wide span is the bug, and a whole-cache exemplar + // naming it is correct, so only one row can look for it. + rejectCacheSpan bool + } + + fn := func(tc tcase) func(*testing.T) { + return func(t *testing.T) { + hot := faketier.New("hot") + durable := faketier.New("durable") + durable.Seed(obsKey, []byte("tile")) + + tracer, exporter := faketracer.New(t) + + a := &Atlas{} + a.SetCache(tieredCache(t, tc.hotType, tc.durableType, tc.hotType, tc.durableType, hot, durable, 0)) + a.SetObservability(newObserver(t)) + a.SetTracing(tracer) + + if _, hit, err := a.GetCache().Get(context.Background(), obsKey); err != nil || !hit { + t.Fatalf("Get() = hit %v, err %v; want a hit from the durable tier", hit, err) + } + + measured := tc.wantSpan(t, exporter) + + ttools.AssertExemplar(t, promclient.DefaultGatherer, tc.family, tc.labels, + measured.SpanContext.TraceID().String(), measured.SpanContext.SpanID().String()) + + if !tc.rejectCacheSpan { + return + } + + // Named so a failure says which way round it went wrong. + whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) + exemplar := ttools.ExemplarLabels(t, promclient.DefaultGatherer, tc.family, tc.labels) + if exemplar[log.SpanIDKey] == whole.SpanContext.SpanID().String() { + t.Error("tier exemplar names the cache-wide span; the metric wrapper is outside the tracing one") + } + } + } + + tests := map[string]tcase{ + "the tier read": { + hotType: "exhot1", durableType: "exdurable1", + family: "shigola_cache_tier_duration_seconds", + labels: map[string]string{"tier": "exhot1", "sub_command": "get"}, + wantSpan: func(t *testing.T, exporter *tracetest.InMemoryExporter) tracetest.SpanStub { + return faketracer.TierSpan(t, exporter, tracing.SpanTierGet, "exhot1") + }, + rejectCacheSpan: true, + }, + "the chain as a whole": { + hotType: "exhot2", durableType: "exdurable2", + family: "shigola_cache_duration_seconds", + labels: map[string]string{"sub_command": "get"}, + wantSpan: func(t *testing.T, exporter *tracetest.InMemoryExporter) tracetest.SpanStub { + return faketracer.SpanNamed(t, exporter, tracing.SpanCacheGet) + }, + }, + } + + for name, tc := range tests { + t.Run(name, fn(tc)) + } +} + +// TestDetachedWriteExemplarNamesItsRequest is the property the docs claim for +// writes and nothing asserted: a cache write runs on the pool goroutine, after +// the response it belongs to has gone, and its exemplar still names the trace +// that caused it. +// +// It holds only because WritePool derives the write's context with +// context.WithoutCancel, which drops cancellation and keeps values — so the +// span context survives into a goroutine whose parent request is over. Swap +// that for context.Background() and the write still happens, the metric is +// still observed, and the exemplar silently becomes nothing: a latency spike on +// cache.Set would stop being clickable with no test failing. +func TestDetachedWriteExemplarNamesItsRequest(t *testing.T) { + hot := faketier.New("hot") + durable := faketier.New("durable") + + tracer, exporter := faketracer.New(t) + + a := &Atlas{} + a.SetCache(tieredCache(t, "exwhot", "exwdurable", "exwhot", "exwdurable", hot, durable, 0)) + a.SetObservability(newObserver(t)) + a.SetTracing(tracer) + + ctx, cancel := context.WithCancel(context.Background()) + if err := a.GetCache().Set(ctx, obsKey, []byte("tile")); err != nil { + t.Fatalf("Set() = %v", err) + } + + // The request ends here, which is the whole point: everything the write + // still needs has to have been carried by value rather than borrowed. + cancel() + + pool := cache.WritePoolOf(a.GetCache()) + if pool == nil { + t.Fatal("no write pool behind the chain; this test would prove nothing about detached writes") + } + pool.Drain(5 * time.Second) + + // The *per-tier* family, not the whole-cache one. The detachment decorator + // sits inside the observability wrapper, so the whole-cache Set is observed + // synchronously on the response path, where the live request context is + // still in hand and WithoutCancel has nothing to do. Only the tier write + // runs on the pool goroutine, which is the observation this property is + // about — asserting the whole-cache family instead passes with the + // derivation replaced by context.Background(), and so proves nothing. + tier := faketracer.TierSpan(t, exporter, tracing.SpanTierSet, "exwdurable") + + // The trace compared against is the *request's*, taken from the whole-cache + // span, which is created on the response path while the original context is + // still live. Comparing the tier exemplar against the tier span's own trace + // would prove nothing: with the derivation replaced by context.Background() + // the tier write still gets a span, it is simply the root of a new and + // orphaned trace — and an exemplar naming that span would still match it. + whole := faketracer.SpanNamed(t, exporter, tracing.SpanCacheSet) + + if tier.SpanContext.TraceID() != whole.SpanContext.TraceID() { + t.Fatalf("the detached write ran in trace %v, not the request's %v; it lost the span context on the way to the pool", + tier.SpanContext.TraceID(), whole.SpanContext.TraceID()) + } + + ttools.AssertExemplar(t, promclient.DefaultGatherer, "shigola_cache_tier_duration_seconds", + map[string]string{"tier": "exwdurable", "sub_command": "set"}, + whole.SpanContext.TraceID().String(), tier.SpanContext.SpanID().String()) +} diff --git a/go.mod b/go.mod index f72ceb76..c369de96 100644 --- a/go.mod +++ b/go.mod @@ -19,6 +19,7 @@ require ( github.com/jackc/pgx/v5 v5.9.2 github.com/mattn/goveralls v0.0.5 github.com/prometheus/client_golang v1.14.0 + github.com/prometheus/client_model v0.6.2 github.com/redis/go-redis/v9 v9.7.3 github.com/theckman/goconstraint v1.10.1-0.20180216224824-e867bde6e4e1 go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.67.0 @@ -67,7 +68,6 @@ require ( github.com/jmespath/go-jmespath v0.3.0 // indirect github.com/matttproud/golang_protobuf_extensions v1.0.4 // indirect github.com/planetscale/vtprotobuf v0.6.1-0.20240319094008-0393e58bdf10 // indirect - github.com/prometheus/client_model v0.6.2 // indirect github.com/prometheus/common v0.39.0 // indirect github.com/prometheus/procfs v0.9.0 // indirect github.com/spf13/pflag v1.0.1 // indirect diff --git a/internal/faketracer/faketracer.go b/internal/faketracer/faketracer.go index 43a7c8b6..97a8752d 100644 --- a/internal/faketracer/faketracer.go +++ b/internal/faketracer/faketracer.go @@ -125,3 +125,53 @@ func Int64Attr(span tracetest.SpanStub, key attribute.Key) int64 { return -1 } + +// TierSpan returns the span named name that carries the given tier — a read, +// a write or a purge on one tier of a chain. +// +// Here rather than in a test because the lookup is two facts about the tracing +// package's own data rather than about any test: the span name a tier read +// takes, and the attribute the tier name lands in. A test that hard-codes +// either is a test that breaks when tracing renames them. +// +// Not used by atlas/tracing_test.go, which wants every tier name at once for a +// set comparison rather than one span by name. +func TierSpan(t *testing.T, exporter *tracetest.InMemoryExporter, name, tier string) tracetest.SpanStub { + t.Helper() + + for _, span := range SpansNamed(exporter, name) { + if StringAttr(span, tracing.AttrCacheTier) == tier { + return span + } + } + + t.Fatalf("no %v span carries tier %v", name, tier) + + return tracetest.SpanStub{} +} + +// RootSpan returns the one recorded span with no parent, failing if there is +// not exactly one. +// +// "Exactly one" is the useful part: a request should root a single trace, and +// two roots mean something started a sibling trace instead of joining this one. +// +// One caller today. server/tracing_test.go checks the same property but finds +// its roots inside a loop that also tallies span names and trace ids in one +// pass, and splitting that to call this would make it worse. +func RootSpan(t *testing.T, exporter *tracetest.InMemoryExporter) tracetest.SpanStub { + t.Helper() + + var roots []tracetest.SpanStub + for _, span := range exporter.GetSpans() { + if !span.Parent.IsValid() { + roots = append(roots, span) + } + } + + if len(roots) != 1 { + t.Fatalf("%d root spans, want exactly 1", len(roots)) + } + + return roots[0] +} diff --git a/internal/ttools/metrics.go b/internal/ttools/metrics.go index 23b07ee3..92676b36 100644 --- a/internal/ttools/metrics.go +++ b/internal/ttools/metrics.go @@ -5,6 +5,9 @@ import ( "testing" "github.com/prometheus/client_golang/prometheus" + dto "github.com/prometheus/client_model/go" + + "github.com/MapColonies/shigola/internal/log" ) // MetricFamilyNames is every metric family the process publishes right now, @@ -36,3 +39,134 @@ func MetricFamilyNames(t *testing.T) []string { return names } + +// HistogramSample returns the one sample of the named histogram family whose labels +// include every pair in labels. +// +// The family-then-label walk, in one place: ExemplarLabels starts from it, the +// observer's own untraced-observation assertion reads a sample count off it, +// and it was otherwise written out at each site that needed either. +// +// gatherer rather than the default registry, because both are needed: a test +// that can build its own registry should, since the default one is +// process-wide and accumulates whatever else the binary registered, but a test +// going through atlas or a real request reaches the metrics only through the +// default registry the observer installs itself against. +func HistogramSample(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) *dto.Histogram { + t.Helper() + + families, err := gatherer.Gather() + if err != nil { + t.Fatalf("gather: %v", err) + } + + for _, family := range families { + if family.GetName() != name { + continue + } + + for _, metric := range family.GetMetric() { + if HasLabels(metric.GetLabel(), labels) { + return metric.GetHistogram() + } + } + } + + t.Fatalf("no sample of %v matches %v", name, labels) + + return nil +} + +// ExemplarLabels returns the labels of the most recently stored exemplar on +// that histogram — the trace and span the caller's own observation named. +// +// "Most recently stored", not "the first bucket that has one", and the +// difference is a real test failure rather than a nicety. Prometheus keeps one +// exemplar *per bucket*, and a family on the process-wide registry outlives the +// test that observed into it — so two tests observing the same family leave two +// exemplars behind whenever their observations land in different buckets, and +// the lower bucket's is whichever happened to be faster rather than whichever +// was later. Taking the newest by timestamp makes a caller read back what it +// just recorded; scanning bucket order made that flaky under -race, where the +// spread between two observations is wide enough to separate them. +// +// Fatal when no bucket carries one: every caller is asserting that an exemplar +// was attached, and "absent" and "attached with the wrong labels" are different +// failures worth different messages. Use HistogramSample directly to assert the +// opposite, that nothing was attached. +func ExemplarLabels(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) map[string]string { + t.Helper() + + histogram := HistogramSample(t, gatherer, name, labels) + + var newest *dto.Exemplar + for _, bucket := range histogram.GetBucket() { + exemplar := bucket.GetExemplar() + if exemplar == nil { + continue + } + if newest == nil || exemplar.GetTimestamp().AsTime().After(newest.GetTimestamp().AsTime()) { + newest = exemplar + } + } + + if newest == nil { + t.Fatalf("no bucket of %v matching %v carries an exemplar", name, labels) + + return nil + } + + got := make(map[string]string, len(newest.GetLabel())) + for _, pair := range newest.GetLabel() { + got[pair.GetName()] = pair.GetValue() + } + + return got +} + +// HasLabels reports whether pairs contain every label in want — a subset +// match, so a caller names only the labels it cares about and ignores whatever +// else the observe-vars added. +// +// Exported because the sample lookups here are not the only place that needs +// it: atlas's own counter() reader matches labels the same way. +func HasLabels(pairs []*dto.LabelPair, want map[string]string) bool { + for name, value := range want { + found := false + for _, pair := range pairs { + if pair.GetName() == name && pair.GetValue() == value { + found = true + break + } + } + if !found { + return false + } + } + + return true +} + +// AssertExemplar checks that the named histogram's most recent exemplar points +// at the given trace and span. +// +// Shared because tests in three packages make exactly this pair of comparisons +// — the prometheus observer's own against a fixed fixture, atlas's against the +// tier span the read produced and the span a detached write ran in, server's +// against the request span — +// and the label names are the load-bearing part: log.TraceIDKey and +// log.SpanIDKey are what Grafana is configured with, so a test spelling them +// itself is a test that keeps passing after a rename that broke correlation. +func AssertExemplar(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string, wantTrace, wantSpan string) { + t.Helper() + + exemplar := ExemplarLabels(t, gatherer, name, labels) + + if got := exemplar[log.TraceIDKey]; got != wantTrace { + t.Errorf("%v exemplar names trace %q, want %q", name, got, wantTrace) + } + + if got := exemplar[log.SpanIDKey]; got != wantSpan { + t.Errorf("%v exemplar names span %q, want %q", name, got, wantSpan) + } +} diff --git a/internal/ttools/openmetrics.go b/internal/ttools/openmetrics.go new file mode 100644 index 00000000..a26d7a34 --- /dev/null +++ b/internal/ttools/openmetrics.go @@ -0,0 +1,137 @@ +package ttools + +import ( + "net/http" + "net/http/httptest" + "regexp" + "testing" + + "github.com/prometheus/client_golang/prometheus" + "github.com/prometheus/client_golang/prometheus/promhttp" +) + +// This file is the evidence for a claim the docs make and an operator acts on: +// which bucket boundaries are respelled by serving OpenMetrics, and therefore +// which `le` series change identity. Getting that list wrong understates an +// upgrade break — the first version of those docs named a boundary that is not +// affected at all, and the second missed two whole families — so it is derived +// rather than worked out by hand. +// +// Derived by *scraping both encoders* rather than by reimplementing the rule +// they apply. An earlier version copied expfmt's unexported +// writeOpenMetricsFloat, which put the docs one vendored change away from being +// wrong with the test still green; the copy also silently dropped that +// function's NaN and ±Inf cases. Nothing here knows the rule, so a change to it +// shows up as a failure naming the boundary that moved. +// +// It lives in ttools rather than beside the observer because the families it +// has to cover do not all live there. provider/postgis declares its own +// duration buckets, and a differ private to package prometheus could not see +// them — which is exactly how those two families came to be missing from the +// documented list while a test named "derives this from the bucket sets" stayed +// green. + +// labelPattern pulls the values of one label out of an exposition line. +// +// Built here rather than taken as a *regexp.Regexp parameter: the two callers +// want a bucket boundary or a summary quantile, and a function promising to +// differ on any regexp at all would be promising more than it is asked for. +func labelPattern(label string) *regexp.Regexp { + return regexp.MustCompile(label + `="([^"]+)"`) +} + +// The two exposition formats, named so a call site says which it means rather +// than passing a bare true or false. +const ( + openMetricsText = true + classicText = false +) + +// scrapeLabel serves a gatherer in one exposition format and returns the values +// pattern captures, in the order they were written. +func scrapeLabel(t *testing.T, gatherer prometheus.Gatherer, label string, openMetrics bool) []string { + t.Helper() + + request := httptest.NewRequest(http.MethodGet, "/metrics", nil) + if openMetrics { + // The one Accept header that reaches the OpenMetrics encoder in this + // vendored expfmt, which negotiates version 0.0.1 only. + request.Header.Set("Accept", "application/openmetrics-text;version=0.0.1") + } + + recorder := httptest.NewRecorder() + promhttp.HandlerFor(gatherer, promhttp.HandlerOpts{EnableOpenMetrics: openMetrics}). + ServeHTTP(recorder, request) + + var found []string + for _, match := range labelPattern(label).FindAllStringSubmatch(recorder.Body.String(), -1) { + found = append(found, match[1]) + } + + return found +} + +// Respelled serves gatherer under both exposition formats, pairs the label +// values written by each, and returns the ones the two spell differently as +// "before -> after". +// +// The pairing is positional, which is why the lengths are checked first: the +// two encoders write the same samples in the same order, and a length mismatch +// means they no longer do, which would make every comparison below meaningless +// rather than merely wrong. +func Respelled(t *testing.T, gatherer prometheus.Gatherer, label string) []string { + t.Helper() + + classic := scrapeLabel(t, gatherer, label, classicText) + openMetrics := scrapeLabel(t, gatherer, label, openMetricsText) + + if len(classic) == 0 { + t.Fatal("no matching labels in the exposition; this test would prove nothing") + } + if len(classic) != len(openMetrics) { + t.Fatalf("%d labels classic, %d under OpenMetrics; the two are not comparable", + len(classic), len(openMetrics)) + } + + var changed []string + for i := range classic { + if classic[i] != openMetrics[i] { + changed = append(changed, classic[i]+" -> "+openMetrics[i]) + } + } + + return changed +} + +// RespelledBuckets is Respelled over one histogram's bucket set, which is what +// every caller but the summary case wants. +// +// The single observation is what makes every bucket appear in the exposition; +// without it there is nothing to compare. +func RespelledBuckets(t *testing.T, buckets []float64) []string { + t.Helper() + + registry := prometheus.NewRegistry() + histogram := prometheus.NewHistogram(prometheus.HistogramOpts{ + Name: "test_le_seconds", + Buckets: buckets, + }) + registry.MustRegister(histogram) + histogram.Observe(0) + + return Respelled(t, registry, "le") +} + +// AssertRespelled compares what actually moved against what the docs say did. +func AssertRespelled(t *testing.T, got, want []string) { + t.Helper() + + if len(got) != len(want) { + t.Fatalf("respelled = %v, documented %v", got, want) + } + for i := range got { + if got[i] != want[i] { + t.Errorf("respelled %d = %q, documented %q", i, got[i], want[i]) + } + } +} diff --git a/observability/prometheus/README.md b/observability/prometheus/README.md index 7d86997c..8b9555b0 100644 --- a/observability/prometheus/README.md +++ b/observability/prometheus/README.md @@ -13,7 +13,9 @@ type = "prometheus" ``` -The metrics will be exposed on the `/metrics` end point. +The metrics will be exposed on the `/metrics` end point, in the **OpenMetrics** +format when the scraper asks for it — see [Trace exemplars](#trace-exemplars), +which is the reason it does. ### Configuration Properties @@ -28,6 +30,95 @@ The metrics will be exposed on the `/metrics` end point. - `push_cadence` (int) : [Optional] How often to push to the Prometheus Gateway. Defaults to 10 secs. Use a zero or less to only push at the end of the process. +### Trace exemplars + +When [tracing](../../tracing/README.md) is enabled, each duration observation +made inside a **sampled** trace carries that trace and span as a Prometheus +exemplar, so a slow bucket in Grafana links to the trace that produced it. + +| Family | Exemplar | +|:---|:---| +| `shigola_cache_duration_seconds` | the `cache.Get`/`Set`/`Purge` span | +| `shigola_cache_tier_duration_seconds` | the `cache.tier.*` span for that tier | +| `shigola_api_duration_seconds` | the request span | + +The labels are `trace_id` and `span_id`, the same names the log records carry. +Nothing is attached to an observation made outside a trace, or inside an +unsampled one — the observation is recorded exactly as it would have been, with +no empty label. + +`span_id` names the operation that was measured rather than the request, which +is what makes an exemplar on the per-tier histogram useful: it points at the +tier read that was slow, on the one family whose purpose is telling tiers apart. + +**Wiring it up.** Three things outside this repo have to be true, and each fails +quietly on its own: + +1. The scraper must ask for OpenMetrics. Prometheus does by default; the format + is the only one that encodes exemplars, and the classic text format drops + them silently. +2. The server must store them — Prometheus needs + `--enable-feature=exemplar-storage`, Mimir its equivalent. +3. Grafana's Prometheus datasource needs an exemplar link on `trace_id` + pointing at the Tempo datasource. Without it the exemplars render as dots on + the panel with no link behind them. + +Then a bucket with a dot on it is one click from the trace. + +**On pushed metrics.** A `push_url` deployment does not go through the +exposition format above at all: `push.New` defaults to protobuf +(`expfmt.FmtProtoDelim`) and nothing here overrides it. Protobuf *can* carry +exemplars — `(*histogram).Write` fills in `dto.Bucket.Exemplar` — so they are on +the wire, and whether they are stored and re-exposed is the Pushgateway's own +business rather than anything this repo decides. Untested here either way. Note +that `push_url` is documented above for ephemeral jobs such as `shigola cache +seed`, which is not the latency-spike-to-trace workflow this section is about. + +**The `le` label spelling changed, whether or not you run tracing.** This +section sits under trace exemplars because they are the reason the format was +switched, but the switch itself is unconditional: `metricsHandler` sets +`EnableOpenMetrics` on every metrics route it serves and never consults the +tracing config. An operator running the observer with `[tracing]` off — the +default — gets this break and no exemplars. + +Negotiating OpenMetrics respells a boundary that renders as a whole number with +a trailing `.0`, so `le="1"` is now `le="1.0"`, which is a different series. The +format is negotiated per scrape rather than per family, so this reaches the size +histograms too even though they carry no exemplars: + +| Family | Respelled | +|:---|:---| +| `shigola_cache_duration_seconds`, `shigola_cache_tier_duration_seconds` | `1`, `5` | +| `shigola_api_duration_seconds` | `1`, `5`, `10` | +| `shigola_cache_response_size_bytes`, `shigola_cache_tier_response_size_bytes` | `1024`, `5120`, `25600`, `102400`, `256000`, `512000` | +| `shigola_api_response_size_bytes` | `512000` | +| `shigola_mvt_provider_sql_query_seconds` | `1`, `5`, `20` | + +`2.5` is untouched, because it already contains a `.`, and so are the megabyte +boundaries, which render as `1.048576e+06` and `5.24288e+06`; so is the provider +family's `.1`, which renders as `0.1`. + +`TestRespelledBucketBoundaries` derives the first four rows from the bucket sets +they name, and `postgis.TestRespelledQueryBuckets` derives the last, so none of +them can drift from the code. It takes two tests because the provider declares +its own boundaries: while the differ was private to this package it could not +see them, and that row was missing from this table for exactly as long. + +**It is not only `le`, and not only Shigola's own metrics.** The respelling is a +property of the encoder rather than of histograms: it writes summary `quantile` +labels through the same float formatter. The Go runtime collector's +`go_gc_duration_seconds` is a summary, so `quantile="0"` becomes `quantile="0.0"` +and `quantile="1"` becomes `quantile="1.0"` — on a metric this package never +touches and that every Go process publishes. `TestRespelledQuantileBoundaries` +keeps that claim honest by scraping a summary carrying the Go collector's own +objectives, rather than the collector itself: its constructor is deprecated in +the vendored client, and the replacement lives in a package this tree does not +vendor, so registering one to prove a fact about the encoder would have meant +vendor churn on a ticket whose acceptance criteria turn on `vendor/` being +untouched. + +Anything matching an exact `le` or `quantile` needs checking. + ### Metrics exposed #### shigola build info @@ -52,6 +143,8 @@ versions of the application. ##### shigola_api_duration_seconds +Carries a [trace exemplar](#trace-exemplars) naming the request span. + A histogram of latencies for requests. As part of a histogram include the support tags: @@ -122,6 +215,8 @@ A counter of the number of tile hits ##### shigola_cache_duration_seconds +Carries a [trace exemplar](#trace-exemplars) naming the cache operation's span. + Buckets: 1-2-5 per decade from 100µs to 5 seconds — 100µs, 250µs, 500µs, 1ms, 2.5ms, 5ms, 10ms, 25ms, 50ms, 100ms, 250ms, 500ms, 1s, 2.5s, 5s. @@ -192,6 +287,13 @@ A histogram of the query time for the SQLs for the mvt provider ##### shigola_provider_sql_query_seconds +**Publishes nothing today.** The histogram is constructed and registered, but +nothing observes it: its `layer_name` label belongs to the feature-returning +`postgis` provider removed in MAPCO-11487, and `mvt_postgis` records against +`shigola_mvt_provider_sql_query_seconds` instead. A `HistogramVec` with no +observed child emits no family, so this one never reaches a scrape — which is +also why it is absent from the respelled-`le` table above. + Labels: "map_name", "layer_name", and "z" Buckets: .1 second, 1 second, 5 seconds, and 20+ seconds diff --git a/observability/prometheus/cache.go b/observability/prometheus/cache.go index a3a1aab2..a6b33e3d 100644 --- a/observability/prometheus/cache.go +++ b/observability/prometheus/cache.go @@ -192,6 +192,17 @@ func (co *cache) labels(cmd string, key *tegolaCache.Key) (lbs prometheus.Labels return lbs } +// observeDuration records one operation's latency, pointing at the trace it +// was part of. +// +// ctx is the operation's own context, so the exemplar names the span that +// measured this read rather than the request as a whole: the tracing wrapper is +// installed *outside* this one (atlas.instrumentCache), which is what makes the +// tier's span the active one by the time this runs. +func (co *cache) observeDuration(ctx context.Context, lbs prometheus.Labels, seconds float64) { + observeWithExemplar(co.durationSeconds.With(lbs), seconds, exemplarFrom(ctx)) +} + // Get will record metrics around the getting the tile from the sub cache func (co *cache) Get(ctx context.Context, key *tegolaCache.Key) ([]byte, bool, error) { co.inFlightGauge.Inc() @@ -201,7 +212,7 @@ func (co *cache) Get(ctx context.Context, key *tegolaCache.Key) ([]byte, bool, e // Observed outside the deadline, deliberately: instrumenting inside it // would drop timed-out reads from the histogram — the very events that // make a too-tight timeout_ms diagnosable. - co.durationSeconds.With(lbs).Observe(time.Since(now).Seconds()) + co.observeDuration(ctx, lbs, time.Since(now).Seconds()) if err != nil { co.countReadError(ctx, lbs, err) co.inFlightGauge.Dec() @@ -250,7 +261,7 @@ func (co *cache) Set(ctx context.Context, key *tegolaCache.Key, body []byte) err lbs := co.labels("set", key) now := time.Now() err := co.cache.Set(ctx, key, body) - co.durationSeconds.With(lbs).Observe(time.Since(now).Seconds()) + co.observeDuration(ctx, lbs, time.Since(now).Seconds()) if err != nil { co.errors.With(lbs).Add(1) co.inFlightGauge.Dec() @@ -267,7 +278,7 @@ func (co *cache) Purge(ctx context.Context, key *tegolaCache.Key) error { lbs := co.labels("purge", key) now := time.Now() err := co.cache.Purge(ctx, key) - co.durationSeconds.With(lbs).Observe(time.Since(now).Seconds()) + co.observeDuration(ctx, lbs, time.Since(now).Seconds()) if err != nil { co.errors.With(lbs).Add(1) } diff --git a/observability/prometheus/exemplar.go b/observability/prometheus/exemplar.go new file mode 100644 index 00000000..9ca7dce9 --- /dev/null +++ b/observability/prometheus/exemplar.go @@ -0,0 +1,79 @@ +package prometheus + +import ( + "context" + + "github.com/prometheus/client_golang/prometheus" + "go.opentelemetry.io/otel/trace" + + "github.com/MapColonies/shigola/internal/log" +) + +// exemplarFrom returns the exemplar labels naming the trace active in ctx, or +// nil when there is no trace worth pointing at. +// +// nil is the client's own "no exemplar" signal, so an untraced observation is +// recorded exactly as a plain Observe would record it, with no empty label +// attached and nothing for the exposition to carry. +// +// Sampling *is* consulted here, which is the opposite of what the log handler +// does with the same span context (MAPCO-11494) — and for the reason the two +// differ in purpose. A trace id on a log line still groups that request's +// lines together whether or not Tempo received the trace. An exemplar has no +// such consolation use: its only job is to be a link, and Prometheus keeps one +// exemplar per bucket, overwritten by the next observation that lands there. At +// the default sample_ratio of 0.01 an unfiltered exemplar would therefore be a +// dead link roughly 99 times out of 100 — the stored one is almost always the +// most recent observation, and the most recent observation is almost never +// sampled. Filtering on IsSampled costs the feature nothing it could have had +// and is what makes clicking a bucket actually open a trace. +// +// The span is carried alongside the trace because the observation is made +// *inside* the operation's span, not merely inside the request: the tracing +// wrappers are installed outside the metric ones at both seams +// (atlas.instrumentCache, server.NewRouter). So a slow bucket on the per-tier +// histogram names the tier read that was slow, and a slow bucket on the HTTP +// histogram names the request — rather than both resolving to whatever span +// happened to be open. Without the span id that ordering would make no +// observable difference, which is why it is asserted rather than assumed: +// atlas.TestExemplarNamesTheSpanThatMeasuredIt. +func exemplarFrom(ctx context.Context) prometheus.Labels { + sc := trace.SpanContextFromContext(ctx) + if !sc.IsValid() || !sc.IsSampled() { + return nil + } + + // log.TraceIDKey and log.SpanIDKey, not a second spelling of "trace_id". + // The exemplar link on Grafana's Prometheus datasource and the derived + // field on its Loki datasource are configured separately, and both fail + // *silently* when the name is wrong — so one pair of constants is what + // makes it impossible for a rename to fix one surface and quietly break + // the other. There is deliberately no alias for them in this package + // either: the tests here and in atlas and server all assert through these + // same two names. + return prometheus.Labels{ + log.TraceIDKey: sc.TraceID().String(), + log.SpanIDKey: sc.SpanID().String(), + } +} + +// observeWithExemplar records seconds on obs, attaching exemplar when there is one. +// +// The ExemplarObserver assertion cannot fail for a HistogramVec's observers, +// which are histograms. It is an assertion rather than a cast so that a family +// later changed to a summary — an Observer that is not an ExemplarObserver — +// loses its exemplars instead of panicking on the first traced request. +// +// The nil check is not redundant with ObserveWithExemplar's own handling of nil +// labels. It keeps "an untraced observation is a plain Observe" true at this +// level rather than resting on a documented detail of the client's internals. +func observeWithExemplar(obs prometheus.Observer, seconds float64, exemplar prometheus.Labels) { + if exemplar != nil { + if withExemplar, ok := obs.(prometheus.ExemplarObserver); ok { + withExemplar.ObserveWithExemplar(seconds, exemplar) + return + } + } + + obs.Observe(seconds) +} diff --git a/observability/prometheus/exemplar_internal_test.go b/observability/prometheus/exemplar_internal_test.go new file mode 100644 index 00000000..3198d302 --- /dev/null +++ b/observability/prometheus/exemplar_internal_test.go @@ -0,0 +1,319 @@ +package prometheus + +import ( + "context" + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/prometheus/client_golang/prometheus" + "go.opentelemetry.io/otel/trace" + + tegolaCache "github.com/MapColonies/shigola/cache" + "github.com/MapColonies/shigola/internal/fakelog" + "github.com/MapColonies/shigola/internal/faketier" + "github.com/MapColonies/shigola/internal/log" + "github.com/MapColonies/shigola/internal/ttools" +) + +// The trace fixture comes from internal/fakelog rather than internal/faketracer +// on purpose. What these tests need is a bare span context with a recognisable +// id, which is what fakelog holds — faketracer builds a whole SDK tracer +// provider, which is more than an exemplar reads and would put a fourth +// spelling of the same fixed id in the tree. See MAPCO-11494. + +var exemplarKey = &tegolaCache.Key{MapName: "osm", Z: 6, X: 5, Y: 4} + +// TestExemplarFromContext covers the three ways there is nothing to point at +// and the one way there is. +func TestExemplarFromContext(t *testing.T) { + type tcase struct { + ctx context.Context + want string // the trace id expected in the labels; empty means no exemplar + } + + fn := func(tc tcase) func(*testing.T) { + return func(t *testing.T) { + got := exemplarFrom(tc.ctx) + + if tc.want == "" { + if got != nil { + t.Fatalf("exemplarFrom() = %v, want nil so the observation is recorded without one", got) + } + return + } + + if got[log.TraceIDKey] != tc.want { + t.Fatalf("exemplarFrom()[%q] = %q, want %q", log.TraceIDKey, got[log.TraceIDKey], tc.want) + } + if got[log.SpanIDKey] != fakelog.SpanIDHex { + t.Errorf("exemplarFrom()[%q] = %q, want %q", log.SpanIDKey, got[log.SpanIDKey], fakelog.SpanIDHex) + } + if len(got) != 2 { + t.Errorf("exemplarFrom() = %v, want the trace and span ids alone", got) + } + } + } + + tests := map[string]tcase{ + "outside any trace": {ctx: context.Background()}, + // The zero trace id is what an uninitialised or stripped span context + // looks like; pointing an exemplar at it would link nowhere. + "invalid span context": {ctx: fakelog.ContextWith(trace.TraceID{}, fakelog.SpanID, true)}, + // The one that is a judgement rather than a validity check: the trace + // is real but was never exported, so a link to it resolves to nothing. + "valid but unsampled": {ctx: fakelog.TracedContext(false)}, + "sampled": {ctx: fakelog.TracedContext(true), want: fakelog.TraceIDHex}, + } + + for name, tc := range tests { + t.Run(name, fn(tc)) + } +} + +// TestExemplarFitsTheRuneLimit is the acceptance criterion that the label set +// stays inside what the client allows, checked the way the client checks it. +// +// ObserveWithExemplar panics past ExemplarMaxRunes rather than returning an +// error, so the failure mode this guards is a tile server that dies on its +// first traced cache read. A real observation, not just a rune count: the +// limit counts label names and values together, which is easy to get wrong by +// hand and impossible to get wrong this way. +func TestExemplarFitsTheRuneLimit(t *testing.T) { + labels := exemplarFrom(fakelog.TracedContext(true)) + + runes := 0 + for name, value := range labels { + runes += len([]rune(name)) + len([]rune(value)) + } + if runes > prometheus.ExemplarMaxRunes { + t.Fatalf("exemplar labels are %d runes, over the limit of %d", runes, prometheus.ExemplarMaxRunes) + } + + // Pinned, not just logged: the exact figure is quoted in tracing/README.md + // and in the PR, and a quoted number nothing asserts is a number that goes + // stale. Change it here and there together — a rise is only a problem at + // the limit, but it should be a deliberate edit either way. + const documented = 63 + if runes != documented { + t.Errorf("exemplar labels are %d runes; tracing/README.md says %d", runes, documented) + } + + histogram := prometheus.NewHistogram(prometheus.HistogramOpts{ + Name: "test_exemplar_limit_seconds", + Buckets: cacheDurationBuckets, + }) + + defer func() { + if r := recover(); r != nil { + t.Fatalf("ObserveWithExemplar panicked on %v: %v", labels, r) + } + }() + + histogram.(prometheus.ExemplarObserver).ObserveWithExemplar(0.002, labels) +} + +// TestDurationExemplars is the ticket's two halves against its two states — +// the cache path and the HTTP path, each inside a sampled trace and outside any +// trace. +// +// One table rather than four functions because the four rows assert one claim +// between them, and the interesting comparison is down the columns: the two +// paths attach their exemplar through entirely different machinery — the cache +// calls ObserveWithExemplar itself, the HTTP side hands the hook to promhttp — +// so neither's behaviour tells you the other's, in either state. +func TestDurationExemplars(t *testing.T) { + type tcase struct { + // observe makes one duration observation against the registry, in the + // context the row is about, and returns the family and label set it + // landed on. + observe func(*testing.T, *prometheus.Registry) (string, map[string]string) + traced bool + } + + fn := func(tc tcase) func(*testing.T) { + return func(t *testing.T) { + // A registry per row, which is why the two closures below can each + // use one fixed metric prefix. The exemplar tests in atlas and + // server need a name unique to each test because they go through + // the process-wide default registry, where one bucket's exemplar is + // overwritten by the next observation to land in it; nothing here + // is shared, so nothing here has to be. + registry := prometheus.NewRegistry() + + family, labels := tc.observe(t, registry) + + if !tc.traced { + assertRecordedWithoutExemplar(t, registry, family, labels) + + return + } + + ttools.AssertExemplar(t, registry, family, labels, fakelog.TraceIDHex, fakelog.SpanIDHex) + } + } + + // cacheOp observes one cache operation through the metric wrapper. op names + // the sub_command the observation lands under, which is how the three are + // told apart in the exposition. + // + // The errors are ignored in all three: a miss, and two writes to a fake + // that cannot fail. The exemplar on the duration observation is the + // subject, and that is recorded either way. + cacheOp := func(ctx context.Context, op string) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { + const prefix = "test_cache" + + c := newCache(registry, prefix, nil, faketier.New("hot")) + + switch op { + case "get": + //nolint:errcheck + c.Get(ctx, exemplarKey) + case "set": + //nolint:errcheck + c.Set(ctx, exemplarKey, []byte("tile")) + case "purge": + //nolint:errcheck + c.Purge(ctx, exemplarKey) + default: + t.Fatalf("unknown cache op %q", op) + } + + return prefix + "_duration_seconds", map[string]string{"sub_command": op} + } + } + + // request serves one request through the metrics middleware. The span + // context arrives on the request, which is how it arrives in production: + // the tracing handler is installed outside the metrics one and has already + // replaced the request by the time this runs. + request := func(ctx context.Context) func(*testing.T, *prometheus.Registry) (string, map[string]string) { + return func(t *testing.T, registry *prometheus.Registry) (string, map[string]string) { + const ( + prefix = "test_api" + route = "/collections/osm/tiles" + ) + + handler := newHttpHandler(registry, prefix, "", nil) + instrumented := handler.InstrumentedHttpHandler(http.MethodGet, route, + http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) })) + + r := httptest.NewRequest(http.MethodGet, route, nil) + if ctx != nil { + r = r.WithContext(ctx) + } + instrumented.ServeHTTP(httptest.NewRecorder(), r) + + return prefix + "_duration_seconds", map[string]string{"handler": route} + } + } + + tests := map[string]tcase{ + "a cache read in a sampled trace": { + observe: cacheOp(fakelog.TracedContext(true), "get"), + traced: true, + }, + "a cache read outside any trace": { + observe: cacheOp(context.Background(), "get"), + }, + // Set and Purge run through the same observeDuration, and the docs name + // all three spans — but every test here observed a read until these two + // rows existed. The write is the one that matters most: on the detached + // pool its observation outlives the response it belongs to. + "a cache write in a sampled trace": { + observe: cacheOp(fakelog.TracedContext(true), "set"), + traced: true, + }, + "a cache purge in a sampled trace": { + observe: cacheOp(fakelog.TracedContext(true), "purge"), + traced: true, + }, + "a request in a sampled trace": { + observe: request(fakelog.TracedContext(true)), + traced: true, + }, + "a request outside any trace": { + observe: request(nil), + }, + } + + for name, tc := range tests { + t.Run(name, fn(tc)) + } +} + +// TestExemplarReachesTheExposition is the one that would have made every other +// test in this file worthless. +// +// Exemplars are recorded in the client either way, but only the OpenMetrics +// encoding transmits them — the classic text encoder has no syntax for them and +// drops them silently. So this scrapes the handler the metrics route actually +// serves, with the Accept header Prometheus sends, and looks for the exemplar +// in the bytes. +// +// Through Handler, not through metricsHandler, which is the whole point of the +// distinction. Handler is what server.go mounts on the metrics route, and it is +// where EnableOpenMetrics is chosen; calling the unexported helper directly +// would assert the encoding of a handler nothing serves, and replacing +// Handler's body with a plain promhttp.Handler() — the default, which leaves +// OpenMetrics off — would drop every exemplar on the wire with this test still +// green. That is also what the observer's registry field is doing here: it is +// what lets the production entry point be exercised against a registry of this +// test's own rather than the process-wide default. +func TestExemplarReachesTheExposition(t *testing.T) { + registry := prometheus.NewRegistry() + tier := faketier.New("hot") + c := newCache(registry, "test_scraped_cache", nil, tier) + + //nolint:errcheck // as above + c.Get(fakelog.TracedContext(true), exemplarKey) + + request := httptest.NewRequest(http.MethodGet, "/metrics", nil) + // Prometheus's own scrape header, verbatim. The version list matters: the + // vendored expfmt negotiates OpenMetrics 0.0.1 only, so a header offering + // 1.0.0 alone falls back to the classic text format and the exemplars + // vanish. Prometheus offers both, which is why this works in production. + request.Header.Set("Accept", "application/openmetrics-text;version=1.0.0,"+ + "application/openmetrics-text;version=0.0.1;q=0.75,"+ + "text/plain;version=0.0.4;q=0.5,*/*;q=0.1") + recorder := httptest.NewRecorder() + obs := &observer{registry: registry} + // The route name Handler is given is the one server.go passes it, and is + // ignored by every implementation; it is the mounting path, not a selector. + obs.Handler("/metrics").ServeHTTP(recorder, request) + + if contentType := recorder.Header().Get("Content-Type"); !strings.Contains(contentType, "openmetrics-text") { + t.Fatalf("Content-Type = %q, want the OpenMetrics encoding that carries exemplars", contentType) + } + + want := log.TraceIDKey + `="` + fakelog.TraceIDHex + `"` + if body := recorder.Body.String(); !strings.Contains(body, want) { + t.Fatalf("the exposition does not contain %q; exemplars are recorded but never scraped", want) + } +} + +// assertRecordedWithoutExemplar is the acceptance criterion for an observation +// made outside a trace: recorded exactly as it would have been, carrying +// nothing. Both halves matter — a guard that dropped the observation entirely +// would satisfy "no exemplar" while losing the measurement. +// +// Shared by the cache and HTTP cases, which assert the same thing about two +// entirely different mechanisms: one calls ObserveWithExemplar itself, the +// other hands the hook to promhttp. +func assertRecordedWithoutExemplar(t *testing.T, gatherer prometheus.Gatherer, name string, labels map[string]string) { + t.Helper() + + histogram := ttools.HistogramSample(t, gatherer, name, labels) + + if histogram.GetSampleCount() != 1 { + t.Fatalf("sample count = %d, want the observation to have been recorded anyway", histogram.GetSampleCount()) + } + + for _, bucket := range histogram.GetBucket() { + if bucket.GetExemplar() != nil { + t.Fatalf("bucket le=%v carries an exemplar outside a trace", bucket.GetUpperBound()) + } + } +} diff --git a/observability/prometheus/http.go b/observability/prometheus/http.go index b58f3f93..ec634d2a 100644 --- a/observability/prometheus/http.go +++ b/observability/prometheus/http.go @@ -64,12 +64,14 @@ func newHttpHandler(registry prometheus.Registerer, prefix string, URLPrefix str []string{}, ) - registry.MustRegister( - handler.inFlightGauge, - handler.counter, - handler.durationSeconds, - handler.responseSizeBytes, - ) + // Through registerOrReuse, for the reason its own doc comment gives — a + // second observer in the same process re-registers these four families, and + // MustRegister panics on that. newCache has always done this; this + // constructor was simply missed. + handler.inFlightGauge = registerOrReuse(registry, handler.inFlightGauge) + handler.counter = registerOrReuse(registry, handler.counter) + handler.durationSeconds = registerOrReuse(registry, handler.durationSeconds) + handler.responseSizeBytes = registerOrReuse(registry, handler.responseSizeBytes) return &handler } @@ -108,7 +110,12 @@ func (handler *httpHandler) instrumentHandlerDuration(originalRoute string, next labels := prometheus.Labels{ "handler": strings.Join(parts, "/"), } - promhttp.InstrumentHandlerDuration(handler.durationSeconds.MustCurryWith(labels), next).ServeHTTP(w, r) + // The exemplar comes off the request context, which by this point + // carries the server span: the tracing handler wraps this one + // (server.NewRouter), so it has already replaced the request. + promhttp.InstrumentHandlerDuration(handler.durationSeconds.MustCurryWith(labels), next, + promhttp.WithExemplarFromContext(exemplarFrom), + ).ServeHTTP(w, r) }) } diff --git a/observability/prometheus/openmetrics_le_internal_test.go b/observability/prometheus/openmetrics_le_internal_test.go new file mode 100644 index 00000000..1b0d3d52 --- /dev/null +++ b/observability/prometheus/openmetrics_le_internal_test.go @@ -0,0 +1,118 @@ +package prometheus + +import ( + "strings" + "testing" + + "github.com/prometheus/client_golang/prometheus" + + "github.com/MapColonies/shigola/internal/ttools" +) + +// The differ these tests use lives in internal/ttools, with the reasoning for +// deriving the list rather than restating the rule. It is shared because the +// families the docs cover are not all declared in this package: see +// provider/postgis's own row. + +// TestRespelledBucketBoundaries scrapes each bucket set under both exposition +// formats and reports every boundary the two spell differently. +func TestRespelledBucketBoundaries(t *testing.T) { + type tcase struct { + buckets []float64 + // respelled is every boundary whose le label changed, as + // "before -> after". unchanged records the boundaries that surprise by + // *not* changing, so the reason sits next to the list they are absent + // from. + respelled []string + unchanged []string + } + + fn := func(tc tcase) func(*testing.T) { + return func(t *testing.T) { + changed := ttools.RespelledBuckets(t, tc.buckets) + + // Before AssertRespelled, which fails fatally on a length + // mismatch. A documented-unchanged boundary that starts moving + // *is* a length mismatch, so checking afterwards would report the + // generic list difference and never the specific boundary — the + // one thing this loop exists to name. + for _, le := range tc.unchanged { + for _, entry := range changed { + if strings.HasPrefix(entry, le+" -> ") { + t.Errorf("%v was documented as unchanged but moved: %v", le, entry) + } + } + } + + ttools.AssertRespelled(t, changed, tc.respelled) + } + } + + tests := map[string]tcase{ + "shigola_cache{,_tier}_duration_seconds": { + buckets: cacheDurationBuckets, + respelled: []string{"1 -> 1.0", "5 -> 5.0"}, + // 2.5 already contains a ".", which is the whole rule. + unchanged: []string{"2.5"}, + }, + "shigola_api_duration_seconds": { + buckets: httpHandlerDurationBuckets, + respelled: []string{"1 -> 1.0", "5 -> 5.0", "10 -> 10.0"}, + unchanged: []string{"2.5"}, + }, + "shigola_cache{,_tier}_response_size_bytes": { + buckets: cacheResponseSizeBuckets, + respelled: []string{ + "1024 -> 1024.0", "5120 -> 5120.0", "25600 -> 25600.0", + "102400 -> 102400.0", "256000 -> 256000.0", "512000 -> 512000.0", + }, + // The megabyte boundaries render in exponent form, so they already + // contain an "e". This is why the list stops at 512000. + unchanged: []string{"1.048576e+06", "5.24288e+06"}, + }, + "shigola_api_response_size_bytes": { + buckets: httpHandlerResponseSizeBuckets, + respelled: []string{"512000 -> 512000.0"}, + unchanged: []string{"1.048576e+06", "5.24288e+06"}, + }, + } + + for name, tc := range tests { + t.Run(name, fn(tc)) + } +} + +// TestRespelledQuantileBoundaries is the half the bucket table misses. +// +// The respelling is a property of the OpenMetrics *encoder*, not of histograms: +// it writes summary quantile labels through the same float writer. So turning +// the format on also respells series this package never touches — most visibly +// go_gc_duration_seconds, which every Go process publishes and which plenty of +// dashboards pin a quantile on. The docs said "le" and named only shigola's +// families until this test was written. +// +// The fixture publishes the quantiles the Go collector publishes — 0, 0.25, +// 0.5, 0.75 and 1 — rather than registering the collector itself, whose +// constructor is deprecated in the vendored client and whose replacement lives +// in a package this tree does not vendor: registering one to prove a fact about +// the encoder would have meant vendor churn on a ticket whose acceptance +// criteria turn on vendor/ being untouched. +// +// A summary is the only way to publish a quantile label from this side, so the +// quantiles arrive here as Objectives. The Go collector reaches the same labels +// by another route — MustNewConstSummary over runtime.MemStats.PauseQuantiles, +// which has no objectives at all — and the epsilons below are therefore +// arbitrary. Only the label spelling is under test, and that is written by the +// encoder from the map keys. +func TestRespelledQuantileBoundaries(t *testing.T) { + registry := prometheus.NewRegistry() + summary := prometheus.NewSummary(prometheus.SummaryOpts{ + Name: "test_quantile_seconds", + Objectives: map[float64]float64{0: 0, 0.25: 0.25, 0.5: 0.05, 0.75: 0.02, 1: 0}, + }) + registry.MustRegister(summary) + summary.Observe(0) + + ttools.AssertRespelled(t, ttools.Respelled(t, registry, "quantile"), + []string{"0 -> 0.0", "1 -> 1.0"}) +} diff --git a/observability/prometheus/prometheus.go b/observability/prometheus/prometheus.go index b5899d90..503a4d1a 100644 --- a/observability/prometheus/prometheus.go +++ b/observability/prometheus/prometheus.go @@ -133,8 +133,85 @@ func New(config dict.Dicter) (observability.Interface, error) { func (*observer) Name() string { return Name } -func (observer) Handler(string) http.Handler { return promhttp.Handler() } -func (obs *observer) Init() { obs.initCall.Do(obs.init) } +// Handler serves the metrics route. +// +// A pointer receiver like every sibling. It was a value receiver, which copied +// the observer's sync.Once fields on every call — a vet copylocks finding, and +// harmless only because the copy was discarded unread. +func (obs *observer) Handler(string) http.Handler { + // The observer's own registry, not the package default, even though New + // only ever sets it to that: an observer built against some other registry + // should serve that registry rather than quietly serving the global one. + // + // Both halves have to follow it or it serves the wrong thing either way — + // registering its scrape counter into one registry while gathering + // another's metrics would be worse than not following it at all. There is + // no gatherer field to read, so it comes off the registerer, which is a + // *prometheus.Registry in every case this has: that type is both. + // + // nil-guarded like every sibling here — the pointer receiver this took to + // clear a vet copylocks finding is also a receiver that can now be nil. + // obs.registry as well as obs: New always sets it, but the value receiver + // this replaced could not have been nil at all, so the guard covers both + // ways the zero value can now arrive. + if obs == nil || obs.registry == nil { + return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) + } + + // Both halves or neither, which is what the paragraph above rules out any + // middle ground for. A Registerer that cannot also gather leaves nothing to + // serve its own metrics from, and pairing it with the default gatherer + // would be exactly the mismatch described: the scrape counter landing in + // one registry while another's metrics go out on the wire. + own, ok := obs.registry.(prometheus.Gatherer) + if !ok { + // Said out loud rather than swallowed. This is unreachable for every + // registry New can produce, so it exists to avoid a panic rather than + // to handle a real case — but serving a different registry's metrics + // than the one the caller configured is precisely the kind of silent + // substitution the exemplar label names are commented against, and an + // operator staring at an empty /metrics deserves the reason. + log.Warnf("prometheus: registry %T cannot gather; serving the default registry on the metrics route instead", obs.registry) + + return metricsHandler(prometheus.DefaultRegisterer, prometheus.DefaultGatherer) + } + + return metricsHandler(obs.registry, own) +} + +// metricsHandler serves the metrics route, negotiating OpenMetrics. +// +// EnableOpenMetrics is what makes the exemplars this package records reach +// Prometheus at all: OpenMetrics is the only exposition format that encodes +// them, and the classic text format drops them without a word. Recording +// exemplars while serving the default handler would have been a change with no +// observable effect whatsoever. +// +// It changes one other thing, which is the cost of the feature. Under +// OpenMetrics a boundary that renders as a whole number is written with a +// trailing ".0", so a histogram exposes le="1.0" where it used to expose +// le="1" — and a label value is part of a series' identity, so those are +// different series. Anything matching an exact le, such as a recording rule or +// a panel pinned to one bucket, has to be checked. +// +// Which boundaries those are is deliberately not written out here. +// TestRespelledBucketBoundaries derives the list from the bucket sets, and +// README.md § "Trace exemplars" states it for operators — a prose copy in a +// third place is how the previous version of this comment came to name a +// boundary that is not affected at all. +// +// Split out from Handler so a test can scrape a registry of its own: the +// exposition is the half of exemplar support that fails silently, and asserting +// on it against the process-wide default registry would depend on whatever else +// the test binary had registered. +func metricsHandler(registerer prometheus.Registerer, gatherer prometheus.Gatherer) http.Handler { + return promhttp.InstrumentMetricHandler( + registerer, + promhttp.HandlerFor(gatherer, promhttp.HandlerOpts{EnableOpenMetrics: true}), + ) +} + +func (obs *observer) Init() { obs.initCall.Do(obs.init) } func (obs *observer) init() { obs.PublishBuildInfo() if obs == nil || obs.pushURL == "" { diff --git a/provider/postgis/openmetrics_le_internal_test.go b/provider/postgis/openmetrics_le_internal_test.go new file mode 100644 index 00000000..b57612ef --- /dev/null +++ b/provider/postgis/openmetrics_le_internal_test.go @@ -0,0 +1,34 @@ +package postgis + +import ( + "testing" + + "github.com/MapColonies/shigola/internal/ttools" +) + +// TestRespelledQueryBuckets is this package's row in a table the docs keep. +// +// Serving OpenMetrics is what makes exemplars reach a scrape at all +// (MAPCO-11496), and the encoder respells any bucket boundary whose shortest +// rendering contains neither "." nor "e" — so `le="1"` becomes `le="1.0"`, a +// different series as far as Prometheus is concerned, and any dashboard panel +// or recording rule pinning an exact `le` stops matching. +// +// observability/prometheus has the same test over the families declared there, +// and the documented list of what moved was assembled from it alone. These two +// families were missed for exactly that reason: their buckets are declared +// here, so a differ private to that package could not see them while still +// reporting that it derived the list from the bucket sets. Hence a row here. +// +// No database: the boundaries are a package-level var, and what is under test +// is how the encoder writes them, not anything the provider does with them. +// That matters because every other test in this package is gated behind +// RUN_POSTGIS_TESTS and would not run in a normal `go test ./...`. +func TestRespelledQueryBuckets(t *testing.T) { + // These are the boundaries of shigola_mvt_provider_sql_query_seconds, the + // one family here that is actually observed — see queryDurationBuckets for + // why its sibling is not. .1 is untouched: it renders as "0.1", which + // already has the "." the rule looks for. + ttools.AssertRespelled(t, ttools.RespelledBuckets(t, queryDurationBuckets), + []string{"1 -> 1.0", "5 -> 5.0", "20 -> 20.0"}) +} diff --git a/provider/postgis/postgis.go b/provider/postgis/postgis.go index 56d2b819..eb47f963 100644 --- a/provider/postgis/postgis.go +++ b/provider/postgis/postgis.go @@ -182,6 +182,25 @@ func (p Provider) startQuerySpan(ctx context.Context, sql string) (context.Conte return ctx, span } +// queryDurationBuckets are the boundaries of the provider query-duration +// histograms. +// +// Two families are built from them, but only shigola_mvt_provider_sql_query_seconds +// is ever observed. shigola_provider_sql_query_seconds is constructed and +// returned as a collector and nothing calls Observe on it anywhere in the tree +// — its layer_name label is a feature-returning-provider concept, left behind +// when that provider was removed in MAPCO-11487. A HistogramVec with no +// observed child publishes no family, so that one reaches no exposition and +// has no le series to change. +// +// Package-level rather than a local, so that a test can reach them: serving +// OpenMetrics respells any boundary whose shortest rendering contains neither +// "." nor "e", which changes the identity of the le series an operator's +// dashboards pin. 1, 5 and 20 are all in that set, and the documented list of +// what moved missed this whole family while it was a local in the function +// below. See internal/ttools.RespelledBuckets and TestRespelledQueryBuckets. +var queryDurationBuckets = []float64{.1, 1, 5, 20} + func (p *Provider) Collectors( prefix string, cfgFn func(configKey string) map[string]any, @@ -190,7 +209,6 @@ func (p *Provider) Collectors( return nil, nil } - buckets := []float64{.1, 1, 5, 20} c, err := p.pool.Collectors(prefix, cfgFn) if err != nil { return nil, err @@ -204,7 +222,7 @@ func (p *Provider) Collectors( prometheus.HistogramOpts{ Name: prefix + "_mvt_provider_sql_query_seconds", Help: "A histogram of query time for sql for mvt providers", - Buckets: buckets, + Buckets: queryDurationBuckets, ConstLabels: prometheus.Labels{"provider_name": p.name}, }, []string{"map_name", "z"}, @@ -214,7 +232,7 @@ func (p *Provider) Collectors( prometheus.HistogramOpts{ Name: prefix + "_provider_sql_query_seconds", Help: "A histogram of query time for sql for providers", - Buckets: buckets, + Buckets: queryDurationBuckets, ConstLabels: prometheus.Labels{"provider_name": p.name}, }, []string{"map_name", "layer_name", "z"}, diff --git a/server/http_exemplar_test.go b/server/http_exemplar_test.go new file mode 100644 index 00000000..9f068c4e --- /dev/null +++ b/server/http_exemplar_test.go @@ -0,0 +1,69 @@ +package server_test + +import ( + "net/http" + "net/url" + "testing" + + promclient "github.com/prometheus/client_golang/prometheus" + + "github.com/MapColonies/shigola/dict" + "github.com/MapColonies/shigola/internal/faketracer" + "github.com/MapColonies/shigola/internal/ttools" + "github.com/MapColonies/shigola/observability/prometheus" + "github.com/MapColonies/shigola/server" +) + +// A zoom of its own, inside testLayer2's 10-15 range. +// +// The `handler` label keeps the tile matrix — :tile_matrix is in the observer's +// default observe-vars — so requesting a zoom no other test in this package +// uses puts this test's observations on a series of their own. That matters +// here and nowhere else in the package: prometheus keeps one exemplar per +// bucket and overwrites it, so two tests sharing a series would each be reading +// whichever ran last. +const exemplarTileURI = "/collections/test-map/tiles/WebMercatorQuad/11/3/2" + +// exemplarHandlerLabel is exemplarTileURI as the observer labels it: the route +// variables named in the observer's default observe-vars keep their value, and +// the tile row and column are collapsed back to their names, because a label +// per tile is a cardinality explosion rather than a metric. +const exemplarHandlerLabel = "/collections/test-map/tiles/WebMercatorQuad/11/:tile_row/:tile_col" + +// TestRequestExemplarNamesTheRequestSpan is the HTTP half of MAPCO-11496, and +// the regression test for the middleware order server.NewRouter documents. +// +// Inverting that order leaves the span tree exactly as it is — the request span +// is still the root and everything still hangs off it — so +// TestTileRequestProducesOneSpanTree would keep passing. What it changes is +// that the metrics middleware would then run *outside* the tracing one, take +// its duration observation off a request whose context has no span yet, and +// attach no exemplar at all. +func TestRequestExemplarNamesTheRequestSpan(t *testing.T) { + server.HostName = &url.URL{Host: serverHostName} + server.URIPrefix = "/" + + a := newTestMapWithLayers(testLayer2) + c, _, _ := twoTierCache(t, "exemplarhot", "exemplardurable") + a.SetCache(c) + + observer, err := prometheus.New(dict.Dict{}) + if err != nil { + t.Fatalf("prometheus observer: %v", err) + } + a.SetObservability(observer) + + tracer, exporter := faketracer.New(t) + tracer.Install() + a.SetTracing(tracer) + + if _, _, err := doRequest(t, a, http.MethodGet, exemplarTileURI, nil); err != nil { + t.Fatalf("traced request: %v", err) + } + + root := faketracer.RootSpan(t, exporter) + + ttools.AssertExemplar(t, promclient.DefaultGatherer, "shigola_api_duration_seconds", + map[string]string{"handler": exemplarHandlerLabel}, + root.SpanContext.TraceID().String(), root.SpanContext.SpanID().String()) +} diff --git a/server/tracing_test.go b/server/tracing_test.go index 5b03e726..197de7b5 100644 --- a/server/tracing_test.go +++ b/server/tracing_test.go @@ -27,15 +27,30 @@ import ( // like tracing being unwired. const tracedTileURI = "/collections/test-map/tiles/WebMercatorQuad/10/3/2" +// tracedTileKey is tracedTileURI as the cache addresses it — the whole map, so +// no layer name, and tileRow/tileCol the other way round from X/Y. +// +// assertSeededKeyWasRead checks it against the key a tier is actually asked for +// rather than trusting it: seeding the wrong key would leave the tile +// unreadable and silently reintroduce the race it exists to remove. +var tracedTileKey = &cache.Key{ + TileMatrixSetID: "WebMercatorQuad", + MapName: "test-map", + Z: 10, + X: 2, + Y: 3, +} + // twoTierCache builds hot → durable through cache.For, so the request walks the -// same decorator stack it would in production. -func twoTierCache(t *testing.T, hotType, durableType string) cache.Interface { +// same decorator stack it would in production. The tiers come back so a caller +// can seed one directly, which is how TestTracedRequestPublishesNoNewMetrics +// gets a warm cache without waiting on a detached write. +func twoTierCache(t *testing.T, hotType, durableType string) (cache.Interface, *faketier.Tier, *faketier.Tier) { t.Helper() - for cacheType, tier := range map[string]*faketier.Tier{ - hotType: faketier.New(hotType), - durableType: faketier.New(durableType), - } { + hot, durable := faketier.New(hotType), faketier.New(durableType) + + for cacheType, tier := range map[string]*faketier.Tier{hotType: hot, durableType: durable} { c := tier if err := cache.Register(cacheType, func(dict.Dicter) (cache.Interface, error) { return c, nil }); err != nil { t.Fatalf("register %v: %v", cacheType, err) @@ -52,7 +67,24 @@ func twoTierCache(t *testing.T, hotType, durableType string) cache.Interface { t.Fatalf("building the chain: %v", err) } - return c + return c, hot, durable +} + +// assertSeededKeyWasRead fails if the tile a request looked for is not the one +// the caller seeded, which is the only way seeding could quietly stop working. +// +// tier names the tier whose calls these are, so a failure says where to look. +func assertSeededKeyWasRead(t *testing.T, tier string, calls []faketier.Call) { + t.Helper() + + for _, call := range calls { + if call.Op == faketier.OpGet && call.Key == tracedTileKey.String() { + return + } + } + + t.Fatalf("the %v tier was never asked for %v; the seeded key is wrong and this test is racing a detached write again", + tier, tracedTileKey.String()) } // TestTileRequestProducesOneSpanTree is the acceptance criterion end to end: a @@ -72,7 +104,8 @@ func TestTileRequestProducesOneSpanTree(t *testing.T) { tracer, exporter := faketracer.New(t) a := newTestMapWithLayers(testLayer2) - a.SetCache(twoTierCache(t, "tracedhot", "traceddurable")) + c, _, _ := twoTierCache(t, "tracedhot", "traceddurable") + a.SetCache(c) a.SetTracing(tracer) w, _, err := doRequest(t, a, http.MethodGet, tracedTileURI, nil) @@ -150,7 +183,8 @@ func TestTileRequestWithoutTracingRecordsNothing(t *testing.T) { _, exporter := faketracer.New(t) a := newTestMapWithLayers(testLayer2) - a.SetCache(twoTierCache(t, "untracedhot", "untraceddurable")) + c, _, _ := twoTierCache(t, "untracedhot", "untraceddurable") + a.SetCache(c) w, _, err := doRequest(t, a, http.MethodGet, tracedTileURI, nil) if err != nil { @@ -182,7 +216,9 @@ func TestTracedRequestPublishesNoNewMetrics(t *testing.T) { server.URIPrefix = "/" a := newTestMapWithLayers(testLayer2) - a.SetCache(twoTierCache(t, "metrichot", "metricdurable")) + c, hot, durable := twoTierCache(t, "metrichot", "metricdurable") + durable.Seed(tracedTileKey, []byte("tile")) + a.SetCache(c) observer, err := prometheus.New(dict.Dict{}) if err != nil { @@ -190,22 +226,27 @@ func TestTracedRequestPublishesNoNewMetrics(t *testing.T) { } a.SetObservability(observer) - // Two untraced requests before the snapshot, not one. + // One untraced request before the snapshot, against a cache that is + // already warm. // // A prometheus *Vec publishes a family only once a label set on it has // been observed, so the snapshot has to be taken in a state where every - // family the traced request will touch already exists. One request is not - // enough: the first is a miss on an empty cache and populates only the - // misses families, and it then writes the tile — so the second is a hit - // and publishes shigola_cache_hits_total and its per-tier sibling for the - // first time. Snapshotting after one request blames tracing for the cache - // warming up. - for range 2 { - if _, _, err := doRequest(t, a, http.MethodGet, tracedTileURI, nil); err != nil { - t.Fatalf("untraced request: %v", err) - } + // family the traced request will touch already exists — otherwise the + // cache warming up is blamed on tracing. Against a seeded durable tier one + // request does it: the hot tier misses and the durable one hits, so the + // hit and miss families are both published, and the traced request has the + // same shape. + // + // This used to be two requests against an empty cache, relying on the + // first request's write making the second a hit. Writes are detached + // through the bounded pool, so that was a race, and it lost often enough + // to fail this test roughly half the time on the trunk. + if _, _, err := doRequest(t, a, http.MethodGet, tracedTileURI, nil); err != nil { + t.Fatalf("untraced request: %v", err) } + assertSeededKeyWasRead(t, "metrichot", hot.Calls()) + before := ttools.MetricFamilyNames(t) httpBefore := map[string]float64{} for _, family := range []string{ diff --git a/tracing/README.md b/tracing/README.md index 9ccebffc..08450716 100644 --- a/tracing/README.md +++ b/tracing/README.md @@ -11,6 +11,12 @@ publishes exactly the metric families it published before. `atlas`'s `TestMetricsAreUnaffectedByTracing` asserts that rather than leaving it to be believed. +What tracing does add to both other signals is its ids: on log records, and as +exemplars on the duration histograms — see +[Correlating logs with traces](#correlating-logs-with-traces) and +[Correlating metrics with traces](#correlating-metrics-with-traces). Neither +adds a metric family or a log field outside a trace. + ## What tracing answers that metrics cannot A histogram can say a tile took 300ms. It cannot say whether that was the @@ -239,6 +245,111 @@ Two consequences worth knowing: too — it is now `stack` at the top level rather than `shigola.stack`. Anything parsing that path needs updating; nothing else about the record changed. +## Correlating metrics with traces + +Cache, per-tier and HTTP duration observations carry the active trace and span +as a **Prometheus exemplar**, so a slow histogram bucket in Grafana links +straight to the trace that landed in it (MAPCO-11496): + +``` +shigola_cache_tier_duration_seconds_bucket{tier="durable",sub_command="get",le="0.5"} 3 # {trace_id="4bf92f3577b34da6a3ce929d0e0e4736",span_id="00f067aa0ba902b7"} 0.41 1.7e+09 +``` + +The labels are `internal/log.TraceIDKey` and `SpanIDKey` — the same constants the +log records carry, deliberately. Logs-to-traces and metrics-to-traces are wired +up separately in Grafana (a derived field on the Loki datasource, an exemplar +link on the Prometheus one) and **both fail silently on a wrong name**, so one +pair of constants is what stops a rename from fixing one surface and breaking +the other. + +Which observations carry one: `shigola_cache_duration_seconds`, +`shigola_cache_tier_duration_seconds` and `shigola_api_duration_seconds` — the +three MAPCO-11496 named. The size histograms and the counters do not, and +neither does `shigola_mvt_provider_sql_query_seconds`, which *is* a duration +histogram and *is* observed inside its own query span, so the trace is in hand +at the point of observation. (Its sibling +`shigola_provider_sql_query_seconds` is registered but never observed, so it +publishes no series at all — see `observability/prometheus/README.md`.) + +The reason is a dependency rather than a judgement. `exemplarFrom` lives in +`observability/prometheus`, and a provider that imported it would defeat the +`noPrometheusObserver` build tag, which exists so the observer can be compiled +out entirely; nothing in `provider/` imports that package today. Attaching one +there means first giving `exemplarFrom` a neutral home, which is a larger change +than this ticket asked for and is worth its own. + +**The exposition format is not optional.** OpenMetrics is the only format that +encodes exemplars; the classic Prometheus text format has no syntax for them and +drops them without a word. The metrics route therefore negotiates OpenMetrics +(`observability/prometheus.metricsHandler`), which Prometheus offers in its own +scrape `Accept` header. The vendored `expfmt` negotiates version `0.0.1` only — +enough, because Prometheus offers both `1.0.0` and `0.0.1`, but a hand-rolled +scrape offering `1.0.0` alone silently gets the classic format and no exemplars. + +Storing them is a server-side switch as well: Prometheus needs +`--enable-feature=exemplar-storage`, and Mimir its equivalent, or the exemplars +are scraped and discarded. + +Three properties of this are load-bearing. + +**Sampling *is* consulted — the opposite of the log records above.** An exemplar +is only ever a link, and prometheus keeps one per bucket, overwritten by the next +observation to land there. So the stored exemplar is almost always the most +recent observation, and at `sample_ratio = 0.01` the most recent observation is +almost never sampled: unfiltered, clicking a bucket would open nothing roughly +99 times out of 100. A log line's trace id keeps its consolation use when the +trace was dropped — it still groups that request's lines — and an exemplar has +none, which is why the same span context is filtered here and not there. + +**The span, not just the trace.** The observation is made *inside* the +operation's span because the tracing wrappers are installed outside the metric +ones at both seams — `atlas.instrumentCache` and `server.NewRouter`, each with a +comment saying so. A slow bucket on the per-tier histogram therefore names the +tier read that was slow, not the request as a whole. Inverting either order +leaves the span tree unchanged, so it is pinned by the exemplar instead: +`atlas.TestExemplarNamesTheSpanThatMeasuredIt` and +`server.TestRequestExemplarNamesTheRequestSpan` both fail on it, though they +fail differently: the atlas one names the inversion, because a tier exemplar +can only go wrong by naming the cache-wide span, and the server one reports +that no bucket carries an exemplar at all, because a request observed outside +its own span has no trace to point at. + +**Nothing is attached outside a trace.** `exemplarFrom` returns nil, which is +the client's own "no exemplar" signal, so an untraced observation is recorded +exactly as a plain `Observe` would record it — no empty label, nothing for the +exposition to carry. The label set is 63 of the 128 runes the client allows; +past that limit `ObserveWithExemplar` panics rather than returning an error, +which `TestExemplarFitsTheRuneLimit` guards by making a real observation. + +Two consequences worth knowing: + +- **`le` label values changed.** Under OpenMetrics a boundary that renders as a + whole number is written with a trailing `.0`, and a label value is part of a + series' identity — so `le="1"` is now `le="1.0"`, a different series. + Anything pinning an exact `le`, such as a recording rule or a panel showing + one bucket, has to be checked. + + **Which labels, exactly, is deliberately not repeated here.** + `TestRespelledBucketBoundaries` and `TestRespelledQuantileBoundaries` derive + the lists by scraping both encoders, and + `observability/prometheus/README.md` § "Trace exemplars" states them for + operators. A prose copy in a third place is how the previous version of this + section came to name a boundary that never changes at all. + + Two things about the scope surprise people. `2.5` is untouched, because it + already contains a `.`. And it reaches beyond `le` and beyond this project: + the encoder writes summary `quantile` labels through the same formatter, so + `go_gc_duration_seconds{quantile="0"}` — a Go runtime metric nothing here + touches — is respelled too. + +- **Pushed metrics are a different path, and an unverified one.** A `push_url` + deployment never reaches the exposition format above, and the exemplars are + neither lost nor confirmed on the way. The mechanism is set out once, in + `observability/prometheus/README.md` § "On pushed metrics" — deliberately not + restated here, because this is the paragraph whose earlier prose copy stated + the opposite of what the code does and had to be corrected in three places at + once. + ## Costs when disabled Nothing. A disabled config returns the no-op backend before an exporter is