Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions docs-website/router/configuration.mdx
Original file line number Diff line number Diff line change
Expand Up @@ -711,7 +711,7 @@ This option may change or be removed in future versions as the OpenTelemetry SDK
| METRICS_OTLP_EXCLUDE_METRICS | exclude_metrics | <Icon icon="square" /> | The metrics to exclude from the OTEL metrics. Accepts a list of Go regular expressions. Use https://regex101.com/ to test your regular expressions. | [] |
| METRICS_OTLP_EXCLUDE_METRIC_LABELS | exclude_metric_labels | <Icon icon="square" /> | The metric labels to exclude from the OTEL metrics. Accepts a list of Go regular expressions. Use https://regex101.com/ to test your regular expressions. | [] |
| METRICS_OTLP_CONNECTION_STATS | connection_stats | <Icon icon="square" /> | Enable connection metrics. | false |
| METRICS_OTLP_NETWORK_ENABLED | network.enabled | <Icon icon="square" /> | Enable per-request subgraph HTTP phase metrics: DNS lookup, TCP connect, TLS handshake, time-to-first-request-byte, and time-to-first-byte histograms. | false |
| METRICS_OTLP_NETWORK_ENABLED | network.enabled | <Icon icon="square" /> | Enable per-request subgraph HTTP phase metrics: DNS lookup, TCP connect, TLS handshake, time-to-first-request-byte, time-to-last-request-byte (request transfer duration), time-to-first-byte, and time-to-last-byte (response transfer duration) histograms. | false |
| METRICS_OTLP_RESOLVER_ENABLED | resolver.enabled | <Icon icon="square" /> | Enable resolver metrics: resolver concurrency gauges and the resolver acquire duration histogram. | false |
| METRICS_OTLP_CIRCUIT_BREAKER | circuit_breaker | <Icon icon="square" /> | Ensure that circuit breaker metrics are enabled for OTEL. | false |
| METRICS_OTLP_STREAM | streams | <Icon icon="square" /> | Enable Cosmo Streams metrics. | false |
Expand Down Expand Up @@ -750,7 +750,7 @@ telemetry:
router_runtime: true
graphql_cache: true
connection_stats: false
# Per-request subgraph HTTP phase metrics (DNS, TCP connect, TLS handshake, time to first request byte, time to first byte)
# Per-request subgraph HTTP phase metrics (DNS, TCP connect, TLS handshake, time to first request byte, request transfer duration, time to first response byte, response transfer duration)
network:
enabled: false
# Resolver concurrency gauges and resolver acquire duration histogram
Expand Down Expand Up @@ -787,7 +787,7 @@ telemetry:
| PROMETHEUS_LISTEN_ADDR | listen_addr | <Icon icon="square" /> | The address to listen on for the prometheus metrics endpoint. | "127.0.0.1:8088" |
| PROMETHEUS_GRAPHQL_CACHE | graphql_cache | <Icon icon="square" /> | Enable the collection of metrics for the GraphQL operation router caches. | false |
| PROMETHEUS_CONNECTION_STATS | connection_stats | <Icon icon="square" /> | Enable connection metrics. | false |
| PROMETHEUS_NETWORK_ENABLED | network.enabled | <Icon icon="square" /> | Enable per-request subgraph HTTP phase metrics: DNS lookup, TCP connect, TLS handshake, time-to-first-request-byte, and time-to-first-byte histograms. | false |
| PROMETHEUS_NETWORK_ENABLED | network.enabled | <Icon icon="square" /> | Enable per-request subgraph HTTP phase metrics: DNS lookup, TCP connect, TLS handshake, time-to-first-request-byte, time-to-last-request-byte (request transfer duration), time-to-first-byte, and time-to-last-byte (response transfer duration) histograms. | false |
| PROMETHEUS_RESOLVER_ENABLED | resolver.enabled | <Icon icon="square" /> | Enable resolver metrics: resolver concurrency gauges and the resolver acquire duration histogram. | false |
| PROMETHEUS_EXCLUDE_METRICS | exclude_metrics | <Icon icon="square" /> | | |
| PROMETHEUS_EXCLUDE_METRIC_LABELS | exclude_metric_labels | <Icon icon="square" /> | | |
Expand All @@ -811,7 +811,7 @@ telemetry:
listen_addr: "127.0.0.1:8088"
graphql_cache: true
connection_stats: false
# Per-request subgraph HTTP phase metrics (DNS, TCP connect, TLS handshake, time to first request byte, time to first byte)
# Per-request subgraph HTTP phase metrics (DNS, TCP connect, TLS handshake, time to first request byte, request transfer duration, time to first response byte, response transfer duration)
network:
enabled: false
# Resolver concurrency gauges and resolver acquire duration histogram
Expand Down
2 changes: 2 additions & 0 deletions docs-website/router/configuration/template-expressions.mdx
Original file line number Diff line number Diff line change
Expand Up @@ -217,7 +217,9 @@ Client trace values describe the individual subgraph fetch that is being logged
- `subgraph.request.clientTrace.tcpConnectDuration` (time.Duration): The duration of the TCP connect (dial) for the subgraph request. It is 0 when an existing connection is reused. In case of retries, the value of the last attempt that dialed is recorded.
- `subgraph.request.clientTrace.tlsHandshakeDuration` (time.Duration): The duration of the TLS handshake for the subgraph request. It is 0 when an existing connection is reused or the subgraph is reached over plaintext. In case of retries, the value of the last attempt that performed a handshake is recorded.
- `subgraph.request.clientTrace.timeToFirstRequestByte` (time.Duration): The duration from the start of the HTTP attempt to writing the first request byte to the subgraph. It includes acquiring the connection. In case of retries, the value of the last attempt that wrote a request byte is recorded.
- `subgraph.request.clientTrace.timeToLastRequestByte` (time.Duration): The duration between the first request-header write callback and a successful request-complete callback from Go's HTTP transport. This approximates the time from the first to the last request byte. The value is 0 unless both callbacks are observed and the request-complete callback reports no error. In case of retries, the value of the last attempt with both callbacks is recorded. The value is also 0 for single-flight followers because they do not write a separate subgraph request.
- `subgraph.request.clientTrace.timeToFirstByte` (time.Duration): The duration from completing the request write to receiving the first response byte from the subgraph. In case of retries, only the last attempt is recorded.
- `subgraph.request.clientTrace.timeToLastByte` (time.Duration): The duration from receiving the first response byte to consuming the last response byte. The value is 0 unless the first response byte is observed and the full response body is consumed, either to EOF or through the declared `Content-Length`. A response that cannot carry a body completes when its headers have been read. The value remains 0 for bodies that are closed early or end in a read error, upgraded or streaming subscription responses, and single-flight followers that do not independently consume the origin response body. In case of retries, the value of the last attempt whose response is fully consumed is recorded.

This object is available in template expressions and can be accessed using the `subgraph` identifier. For example, you can access the subgraph name using `subgraph.name` or check for errors using `subgraph.request.error`.

Expand Down
6 changes: 6 additions & 0 deletions docs-website/router/metrics-and-monitoring.mdx
Original file line number Diff line number Diff line change
Expand Up @@ -348,6 +348,8 @@ We use the following standard dimensions

These metrics break down each outgoing subgraph request into its individual HTTP phases. They are collected per request using Go's `httptrace`, so unlike [Connection Metrics](#connection-metrics) they do not depend on the connection pool dialer. Use them to attribute subgraph latency to DNS resolution, connection setup, the TLS handshake, or the subgraph itself. This is useful for diagnosing issues such as slow DNS lookups.

The histograms record actual outgoing subgraph HTTP requests. When single-flight request deduplication coalesces fetches, only the fetch that sends the subgraph request produces samples. Followers do not independently write the request or consume the origin response body.

<CodeGroup>
```bash config.yaml
telemetry:
Expand All @@ -371,8 +373,12 @@ telemetry:

* `router.http.client.time_to_first_request_byte`: Histogram (ms) of the time from the start of the HTTP attempt to writing the first request byte to the subgraph. It includes acquiring the connection: pool wait, or DNS, TCP connect, and TLS handshake for new connections.

* `router.http.client.time_to_last_request_byte`: Histogram (ms) of the duration between the first request-header write callback and a successful request-complete callback from Go's HTTP transport. This approximates the time from the first to the last request byte. Recorded only when both callbacks are observed and the request-complete callback reports no error.

* `router.http.client.time_to_first_byte`: Histogram (ms) of the time from completing the request write to receiving the first response byte from the subgraph.

* `router.http.client.time_to_last_byte`: Histogram (ms) of the duration from receiving the first response byte to consuming the last response byte. Recorded only when a first response byte is observed and the full body is consumed, either to EOF or through the declared `Content-Length`. A response that cannot carry a body completes when its headers have been read.

## Custom Attributes

You can also add custom attributes to OTEL and Prometheus. Please refer to the [Custom Attributes](/router/open-telemetry/custom-attributes) section.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -219,6 +219,8 @@ You can find more examples here under [`Connection`](/router/metrics-and-monitor

These metrics break down each outgoing subgraph request into its individual HTTP phases, collected per request via Go's `httptrace`. Use them to attribute subgraph latency to DNS resolution, connection setup, the TLS handshake, or the subgraph itself.

The histograms record actual outgoing subgraph HTTP requests. When single-flight request deduplication coalesces fetches, only the fetch that sends the subgraph request produces samples. Followers do not independently write the request or consume the origin response body.

#### Enable Network Metrics

```yaml config.yaml
Expand All @@ -239,8 +241,12 @@ telemetry:

* `router_http_client_time_to_first_request_byte`: The time in ms from the start of the HTTP attempt to writing the first request byte to the subgraph. It includes acquiring the connection: pool wait, or DNS, TCP connect, and TLS handshake for new connections.

* `router_http_client_time_to_last_request_byte`: The duration in ms between the first request-header write callback and a successful request-complete callback from Go's HTTP transport. This approximates the time from the first to the last request byte. Recorded only when both callbacks are observed and the request-complete callback reports no error.

* `router_http_client_time_to_first_byte`: The time in ms from completing the request write to receiving the first response byte from the subgraph.

* `router_http_client_time_to_last_byte`: The duration in ms from receiving the first response byte to consuming the last response byte. Recorded only when a first response byte is observed and the full body is consumed, either to EOF or through the declared `Content-Length`. A response that cannot carry a body completes when its headers have been read.

### Go Runtime Metrics

These metrics help monitor application memory usage, concurrency, and garbage collection efficiency:
Expand Down
8 changes: 8 additions & 0 deletions router-tests/observability/prometheus_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -5341,10 +5341,18 @@ func TestFlakyPrometheusRouterConnectionMetrics(t *testing.T) {
require.NotNil(t, ttfb)
require.NotEmpty(t, ttfb.GetMetric())

ttlb := findMetricFamilyByName(mf, "router_http_client_time_to_last_byte")
require.NotNil(t, ttlb)
require.NotEmpty(t, ttlb.GetMetric())

firstRequestByte := findMetricFamilyByName(mf, "router_http_client_time_to_first_request_byte")
require.NotNil(t, firstRequestByte)
require.NotEmpty(t, firstRequestByte.GetMetric())

lastRequestByte := findMetricFamilyByName(mf, "router_http_client_time_to_last_request_byte")
require.NotNil(t, lastRequestByte)
require.NotEmpty(t, lastRequestByte.GetMetric())

tcpConnect := findMetricFamilyByName(mf, "router_http_client_tcp_connect_duration")
require.NotNil(t, tcpConnect)
require.NotEmpty(t, tcpConnect.GetMetric())
Expand Down
64 changes: 64 additions & 0 deletions router-tests/observability/structured_logging_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -3653,6 +3653,70 @@ func TestFlakyAccessLogs(t *testing.T) {
})
})

t.Run("verify timeToLastRequestByte value is attached", func(t *testing.T) {
t.Parallel()

testenv.Run(t, &testenv.Config{
SubgraphAccessLogsEnabled: true,
SubgraphAccessLogFields: []config.CustomAttribute{
{
Key: "time_to_last_request_byte",
ValueFrom: &config.CustomDynamicAttribute{
Expression: "subgraph.request.clientTrace.timeToLastRequestByte",
},
},
},
LogObservation: testenv.LogObservationConfig{
Enabled: true,
LogLevel: zapcore.InfoLevel,
},
}, func(t *testing.T, xEnv *testenv.Environment) {
xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{
Query: `query myQuery { employees { id } }`,
})
requestLog := xEnv.Observer().FilterMessage("/graphql")
requestLogAll := requestLog.All()
requestContextMap := requestLogAll[0].ContextMap()

timeToLastRequestByte, ok := requestContextMap["time_to_last_request_byte"].(time.Duration)
require.True(t, ok)

require.Greater(t, int(timeToLastRequestByte), 0)
})
})

t.Run("verify timeToLastByte value is attached", func(t *testing.T) {
t.Parallel()

testenv.Run(t, &testenv.Config{
SubgraphAccessLogsEnabled: true,
SubgraphAccessLogFields: []config.CustomAttribute{
{
Key: "time_to_last_byte",
ValueFrom: &config.CustomDynamicAttribute{
Expression: "subgraph.request.clientTrace.timeToLastByte",
},
},
},
LogObservation: testenv.LogObservationConfig{
Enabled: true,
LogLevel: zapcore.InfoLevel,
},
}, func(t *testing.T, xEnv *testenv.Environment) {
xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{
Query: `query myQuery { employees { id } }`,
})
requestLog := xEnv.Observer().FilterMessage("/graphql")
requestLogAll := requestLog.All()
requestContextMap := requestLogAll[0].ContextMap()

timeToLastByte, ok := requestContextMap["time_to_last_byte"].(time.Duration)
require.True(t, ok)

require.Greater(t, int(timeToLastByte), 0)
})
})

t.Run("verify connAcquireDuration value is attached for multiple subgraph calls", func(t *testing.T) {
t.Parallel()

Expand Down
73 changes: 73 additions & 0 deletions router-tests/telemetry/connection_metrics_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -154,6 +154,79 @@ func TestConnectionMetrics(t *testing.T) {
})
})

t.Run("validate transfer duration metrics are present when network metrics are enabled", func(t *testing.T) {
t.Parallel()

metricReader := metric.NewManualReader()
testenv.Run(t, &testenv.Config{
MetricReader: metricReader,
MetricOptions: testenv.MetricOptions{
EnableOTLPNetworkMetrics: true,
},
}, func(t *testing.T, xEnv *testenv.Environment) {
xEnv.MakeGraphQLRequestOK(testenv.GraphQLRequest{
Query: `query { employees { id } }`,
})

rm := metricdata.ResourceMetrics{}
err := metricReader.Collect(context.Background(), &rm)
require.NoError(t, err)

scopeMetric := testutils.GetMetricScopeByName(rm.ScopeMetrics, "cosmo.router.connections")
require.NotNil(t, scopeMetric)
excludePortFromMetrics(t, rm.ScopeMetrics)

expectedAttributes := attribute.NewSet(
otel.ServerAddress.String("127.0.0.1"),
otel.WgClientReusedConnection.Bool(false),
otel.WgSubgraphName.String("employees"),
)

tests := []struct {
name string
description string
}{
{
name: "router.http.client.time_to_last_request_byte",
description: "Time from the first request byte write event to the successful request write completion event for outgoing subgraph requests",
},
{
name: "router.http.client.time_to_last_byte",
description: "Time from the first response byte to the last response byte from subgraph",
},
}

for _, tc := range tests {
t.Run(tc.name, func(t *testing.T) {
actual := testutils.GetMetricByName(scopeMetric, tc.name)
require.NotNil(t, actual)

actualHistogram, ok := actual.Data.(metricdata.Histogram[float64])
require.True(t, ok)
require.Len(t, actualHistogram.DataPoints, 1)
require.Greater(t, actualHistogram.DataPoints[0].Count, uint64(0))
require.Greater(t, actualHistogram.DataPoints[0].Sum, 0.0)

expected := metricdata.Metrics{
Name: tc.name,
Description: tc.description,
Unit: "ms",
Data: metricdata.Histogram[float64]{
Temporality: metricdata.CumulativeTemporality,
DataPoints: []metricdata.HistogramDataPoint[float64]{
{
Attributes: expectedAttributes,
},
},
},
}

metricdatatest.AssertEqual(t, expected, *actual, metricdatatest.IgnoreTimestamp(), metricdatatest.IgnoreValue())
})
}
})
})

t.Run("verify custom subgraph transport configs", func(t *testing.T) {
t.Parallel()

Expand Down
2 changes: 2 additions & 0 deletions router/internal/expr/expr.go
Original file line number Diff line number Diff line change
Expand Up @@ -166,7 +166,9 @@ type ClientTrace struct {
TCPConnectDuration time.Duration `expr:"tcpConnectDuration"`
TLSHandshakeDuration time.Duration `expr:"tlsHandshakeDuration"`
TimeToFirstRequestByte time.Duration `expr:"timeToFirstRequestByte"`
TimeToLastRequestByte time.Duration `expr:"timeToLastRequestByte"`
TimeToFirstByte time.Duration `expr:"timeToFirstByte"`
TimeToLastByte time.Duration `expr:"timeToLastByte"`
}

// Subgraph Related
Expand Down
Loading
Loading