diff --git a/components/egress/docs/opentelemetry.md b/components/egress/docs/opentelemetry.md index d7779c5c9..08b852fef 100644 --- a/components/egress/docs/opentelemetry.md +++ b/components/egress/docs/opentelemetry.md @@ -17,6 +17,31 @@ This page lists the OpenTelemetry metrics currently implemented in egress. | `egress.system.memory.usage_bytes` | Observable Gauge | `By` | System memory used bytes (Linux: gopsutil; non-Linux build: `0`). | | `egress.system.cpu.utilization` | Observable Gauge | `1` | CPU busy ratio in `[0,1]` (Linux: gopsutil; non-Linux build: `0`). | +`egress.dns.query.duration` declares its bucket boundaries explicitly: + +``` +0.001 0.0025 0.005 0.01 0.025 0.05 0.1 0.25 0.5 1 2.5 5 10 15 30 60 120 300 600 +``` + +Do not drop them: the instrument records **seconds**, while the SDK default boundaries are +the spec's millisecond ladder (`0, 5, 10, … 10000`), so every realistic latency would fall +into the single `le=5` bucket and the quantiles would be meaningless. + +The head resolves a cache hit (sub-millisecond) up to one upstream timeout +(`OPENSANDBOX_EGRESS_DNS_UPSTREAM_TIMEOUT`, 5s by default). The coarse tail exists because +the recorded duration covers the **whole resolver chain**: forwarding walks the upstreams +serially, each with the full timeout, so a query can legitimately take +`timeout x len(upstreams)` — 15s is three resolvers at the default, and 120s is the cap a +single exchange can be configured to wait. A late **success** lands in the tail too, not only an exhausted failure: a query can +succeed on the second resolver after the first burned a full timeout. The chain has no finite +worst case either (`OPENSANDBOX_EGRESS_DNS_UPSTREAM` accepts an unbounded resolver list), so +past the last boundary quantile resolution is lost by construction and `_count` is what +remains. A configuration that gets there — several resolvers each waiting close to the 120s +per-exchange cap — has bigger problems than a percentile. + +Note both successful and failed lookups feed this histogram, so its tail mixes slow +resolutions with exhausted retry chains. + ## Shared Attributes All egress metrics may include shared attributes: diff --git a/components/egress/go.mod b/components/egress/go.mod index 5e6842b32..3799b6d44 100644 --- a/components/egress/go.mod +++ b/components/egress/go.mod @@ -9,6 +9,7 @@ require ( github.com/stretchr/testify v1.11.1 go.opentelemetry.io/otel v1.43.0 go.opentelemetry.io/otel/metric v1.43.0 + go.opentelemetry.io/otel/sdk/metric v1.43.0 go.uber.org/automaxprocs v1.6.0 golang.org/x/sys v0.45.0 k8s.io/apimachinery v0.34.2 @@ -30,7 +31,6 @@ require ( go.opentelemetry.io/auto/sdk v1.2.1 // indirect go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp v1.43.0 // indirect go.opentelemetry.io/otel/sdk v1.43.0 // indirect - go.opentelemetry.io/otel/sdk/metric v1.43.0 // indirect go.opentelemetry.io/otel/trace v1.43.0 // indirect go.opentelemetry.io/proto/otlp v1.10.0 // indirect go.uber.org/multierr v1.11.0 // indirect diff --git a/components/egress/pkg/telemetry/metrics.go b/components/egress/pkg/telemetry/metrics.go index aa585b50e..6405f3fb8 100644 --- a/components/egress/pkg/telemetry/metrics.go +++ b/components/egress/pkg/telemetry/metrics.go @@ -74,6 +74,24 @@ func registerEgressMetrics() error { "egress.dns.query.duration", metric.WithDescription("DNS forward latency"), metric.WithUnit("s"), + // Explicit boundaries: this instrument records seconds, but the SDK default + // boundaries are the spec's millisecond ladder (0, 5, 10, ... 10000), so every + // realistic DNS latency lands in the same bucket and the quantiles are noise. + // + // The head spans a cache hit (sub-ms) to one upstream timeout + // (DefaultDNSUpstreamTimeoutSec = 5s). The coarse tail covers the retry chain: + // forward() walks the resolvers serially, each with the full timeout, and the + // recorded duration is the whole chain — so a query can legitimately take + // timeout x len(upstreams), and a late *success* lands there too, not just an + // exhausted failure. 15s is three resolvers at the default; 600s covers the 120s + // per-exchange cap across a handful of them. The chain has no finite worst case + // (OPENSANDBOX_EGRESS_DNS_UPSTREAM takes an unbounded resolver list), so past the + // last boundary quantile resolution is lost by construction and _count is what + // remains — a configuration that gets there has bigger problems than a percentile. + metric.WithExplicitBucketBoundaries( + 0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10, + 15, 30, 60, 120, 300, 600, + ), ) if err != nil { return err diff --git a/components/egress/pkg/telemetry/metrics_test.go b/components/egress/pkg/telemetry/metrics_test.go index a757c4548..e4e33bea7 100644 --- a/components/egress/pkg/telemetry/metrics_test.go +++ b/components/egress/pkg/telemetry/metrics_test.go @@ -15,11 +15,17 @@ package telemetry import ( + "context" "testing" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" + "github.com/alibaba/opensandbox/egress/pkg/constants" inttelemetry "github.com/alibaba/opensandbox/internal/telemetry" ) @@ -45,3 +51,63 @@ func TestAppendMetricAttrsFromKeyValuePairs(t *testing.T) { out = inttelemetry.AppendAttrsFromKeyValuePairs(nil, "novalue=,=bad,nokv") assert.Len(t, out, 0) } + +// The instrument records seconds, so it needs boundaries on a seconds ladder. With the +// SDK default (the spec's millisecond ladder) every realistic DNS latency collapses into +// one bucket and the quantiles are meaningless. +func TestDNSQueryDurationBucketsSpanRealisticLatencies(t *testing.T) { + reader := sdkmetric.NewManualReader() + previous := otel.GetMeterProvider() + otel.SetMeterProvider(sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader))) + t.Cleanup(func() { otel.SetMeterProvider(previous) }) + + require.NoError(t, registerEgressMetrics()) + + // Cache hit, LAN upstream, slow upstream, one upstream timeout, a serial retry through + // three resolvers at the default timeout, and a late success after two resolvers each + // burning the configurable 120s maximum. + for _, seconds := range []float64{0.0008, 0.012, 0.4, 5, 15, 240} { + RecordDNSForward(seconds) + } + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + + dp := dnsDurationDataPoint(t, &rm) + require.NotEmpty(t, dp.Bounds) + assert.Less(t, dp.Bounds[0], 0.01, + "boundaries look like the millisecond default, not a seconds ladder") + // forward() retries resolvers serially with the full timeout each and records the + // whole chain, so the tail has to reach well past a single timeout. + assert.Greater(t, dp.Bounds[len(dp.Bounds)-1], float64(constants.DefaultDNSUpstreamTimeoutSec), + "the top boundary must leave room for a serial retry chain, not just one timeout") + + populated := 0 + for _, count := range dp.BucketCounts { + if count > 0 { + populated++ + } + } + assert.Equal(t, 6, populated, + "the six latencies must land in six different buckets, got counts %v for bounds %v", + dp.BucketCounts, dp.Bounds) + assert.Zero(t, dp.BucketCounts[len(dp.BucketCounts)-1], + "a retry-chain latency fell into +Inf, where it cannot be distinguished or interpolated") +} + +func dnsDurationDataPoint(t *testing.T, rm *metricdata.ResourceMetrics) metricdata.HistogramDataPoint[float64] { + t.Helper() + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + if m.Name != "egress.dns.query.duration" { + continue + } + hist, ok := m.Data.(metricdata.Histogram[float64]) + require.True(t, ok, "unexpected aggregation %T", m.Data) + require.Len(t, hist.DataPoints, 1) + return hist.DataPoints[0] + } + } + t.Fatal("egress.dns.query.duration not collected") + return metricdata.HistogramDataPoint[float64]{} +} diff --git a/docs/components/egress.md b/docs/components/egress.md index eeeb610b5..bac58311d 100644 --- a/docs/components/egress.md +++ b/docs/components/egress.md @@ -181,6 +181,31 @@ See [Credential Vault](/guides/credential-vault) for full API usage, binding rul Egress can export **OTLP metrics**; application logs use the **native zap** logger (JSON to stdout by default, configurable via `OPENSANDBOX_LOG_OUTPUT` / `OPENSANDBOX_EGRESS_LOG_LEVEL`). OTLP log export is not used. +#### DNS latency buckets + +`egress.dns.query.duration` is recorded in **seconds** and declares its bucket boundaries +explicitly: + +``` +0.001 0.0025 0.005 0.01 0.025 0.05 0.1 0.25 0.5 1 2.5 5 10 15 30 60 120 300 600 +``` + +The head resolves a cache hit up to one upstream timeout +(`OPENSANDBOX_EGRESS_DNS_UPSTREAM_TIMEOUT`, 5s by default). The coarse tail is there because +the recorded duration covers the **whole resolver chain** — forwarding walks the upstreams +serially with the full timeout each, so a query can legitimately take +`timeout x len(upstreams)`. A late **success** lands in the tail too, not only an +exhausted failure: a query can succeed on the second resolver after the first burned a full +timeout. Past the last boundary quantile resolution is lost by construction — the chain has no +finite worst case, since the resolver list is unbounded — and `_count` is what remains. + +If you tune these, keep them on a seconds ladder. The SDK default boundaries are the spec's +millisecond ladder (`0, 5, 10, … 10000`), which would put every realistic DNS latency in the +single `le=5` bucket and make `histogram_quantile()` return an interpolation rather than a +measurement. + +Full metric inventory and attribute semantics: [egress OpenTelemetry reference](https://github.com/opensandbox-group/OpenSandbox/blob/main/components/egress/docs/opentelemetry.md). + ## Build & Run ### Build Docker Image