From 90a58fcd5ee93be3ea556e75f9e5db41473265c6 Mon Sep 17 00:00:00 2001 From: Chase Granberry Date: Fri, 2 Oct 2026 22:46:05 +0000 Subject: [PATCH 1/2] Give the edges' query latency series buckets up to 30 s (T-625) The HTTP edges share one set of latency bounds, tuned for insert acks: 5 ms to 10 s, with only 2.5 s and 10 s above 1 s. A query runs up to max_query_duration_ms (30 s), so histogram_quantile read any query tail past 2.5 s as about 9.7 s and nothing past 10 s at all. On the sandbox the VictoriaMetrics edge's p99 sat at 8.4-9.8 s whether the tail was at 3 s or near 10 s. The query series now take their own bounds: route=query on the API, and kind=query on the ClickHouse and VictoriaMetrics edges. They are 50, 100, 250, 500 and 750 ms, 1, 1.5, 2, 3, 5, 7.5, 10, 15, 20 and 30 s. Every other route and kind keeps the insert bounds. timed/4 takes the bounds from its caller, which picks them by route or kind. A test drives a 3.4 s request through each query series and checks that it lands at 5 s and above, that no query series emits the old 2.5 s bound, and that insert and write keep theirs. docs/deployment.md has the upgrade note (seven more le values per query series; old and new bounds mix in a sum while a roll is in progress). --- docs/clickhouse.md | 2 +- docs/deployment.md | 8 ++++ lib/smolquery/telemetry.ex | 64 +++++++++++++++++++++----- test/smolquery/telemetry_test.exs | 74 +++++++++++++++++++++++++++++++ 4 files changed, 136 insertions(+), 12 deletions(-) diff --git a/docs/clickhouse.md b/docs/clickhouse.md index 68cb2f01..d7714118 100644 --- a/docs/clickhouse.md +++ b/docs/clickhouse.md @@ -27,7 +27,7 @@ curl -sS "http://127.0.0.1:8123/" \ - **Health checks.** `GET /` and `GET /ping` answer `Ok.` without a password, as ClickHouse does. - **Refused before the body.** A missing or wrong password is a 401 with code 516 `AUTHENTICATION_FAILED`, on every path. An insert is then counted against the in-flight limit before its body is read, as the API's insert is. Over the limit is a 429 with code 202 and `retry-after: 1`. - **Paths.** Everything happens on `/`. Any other path but `/ping` is a 404. -- **Metrics.** Requests are counted in `smolquery_clickhouse_requests_total`, by status class, and timed in `smolquery_clickhouse_request_microseconds_total` and `smolquery_clickhouse_request_microseconds_bucket` by `kind` (`insert`, `query`, `ping`, `other`): cumulative `le` counters at 5 ms to 10 s, whose `le="+Inf"` is the kind's request count (T-546). +- **Metrics.** Requests are counted in `smolquery_clickhouse_requests_total`, by status class, and timed in `smolquery_clickhouse_request_microseconds_total` and `smolquery_clickhouse_request_microseconds_bucket` by `kind` (`insert`, `query`, `ping`, `other`): cumulative `le` counters at 5 ms to 10 s, and at 50 ms to 30 s for `query` (T-625), whose `le="+Inf"` is the kind's request count (T-546). ## The insert diff --git a/docs/deployment.md b/docs/deployment.md index 15c37961..ec9de072 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -127,6 +127,14 @@ answers nothing at the TCP level. One note per release, newest first. +### 0.22.0: query latency buckets reach 30 s (T-625) + +The query series of the HTTP edges' latency counters now use their own `le` bounds: `smolquery_api_request_microseconds_bucket{route="query"}` and the ClickHouse and VictoriaMetrics `..._request_microseconds_bucket{kind="query"}`. The bounds are 50, 100, 250, 500 and 750 ms, 1, 1.5, 2, 3, 5, 7.5, 10, 15, 20 and 30 s. + +- **Why:** the old bounds had only 2.5 s and 10 s above 1 s, so `histogram_quantile(0.99, ...)` read any query tail past 2.5 s as about 9.7 s, and nothing past 10 s at all. Queries run up to `max_query_duration_ms` (30 s). +- **Series:** each query series gains 7 `le` values (15 bounds instead of 8). Every other route and kind keeps 5 ms to 10 s. +- **Dashboards:** `histogram_quantile` over `sum by (le)` keeps working. While old and new pods both report, and for one rate window after the last old pod is gone, a `sum by (le)` mixes the two bound sets, and a quantile over it is rough. + ### 0.22.0: sockets to a replaced pod close in seconds (T-613, T-614) - **gen_rpc:** a node's clients to a peer are killed when distribution reports the peer down, and a channel that times out is probed and redialed if it is dead (T-613). Nothing to configure. diff --git a/lib/smolquery/telemetry.ex b/lib/smolquery/telemetry.ex index 3b7b8239..58fd1735 100644 --- a/lib/smolquery/telemetry.ex +++ b/lib/smolquery/telemetry.ex @@ -302,8 +302,9 @@ defmodule Smolquery.Telemetry do "smolquery_api_requests_total" => "HTTP requests answered, by status class.", "smolquery_api_request_microseconds_bucket" => "HTTP requests by duration, by route, cumulative in le at 5 ms, 25 ms, 100 ms, 250 ms, " <> - "500 ms, 1 s, 2.5 s and 10 s; counters, not a histogram. le=\"+Inf\" is the route's " <> - "request count, so _microseconds_total over it is the route's mean (T-546).", + "500 ms, 1 s, 2.5 s and 10 s, and for route=query at 50 ms to 30 s (T-625); counters, " <> + "not a histogram. le=\"+Inf\" is the route's request count, so _microseconds_total " <> + "over it is the route's mean (T-546).", "smolquery_clickhouse_requests_total" => "ClickHouse HTTP edge requests answered, by status class.", "smolquery_clickhouse_request_microseconds_total" => @@ -311,7 +312,8 @@ defmodule Smolquery.Telemetry do "other (T-546).", "smolquery_clickhouse_request_microseconds_bucket" => "ClickHouse HTTP edge requests by duration, by kind, cumulative in le at the API's " <> - "bounds; counters, not a histogram. le=\"+Inf\" is the kind's request count (T-546).", + "bounds, the query bounds for kind=query (T-625); counters, not a histogram. " <> + "le=\"+Inf\" is the kind's request count (T-546).", "smolquery_clickhouse_unanswered_total" => "Statements the ClickHouse HTTP edge could not answer for a reason that is the dialect's, by ClickHouse error code.", "smolquery_clickhouse_catalog_refreshes_total" => @@ -327,7 +329,8 @@ defmodule Smolquery.Telemetry do "Time spent answering VictoriaMetrics edge requests, by kind: write, query, labels, health or other.", "smolquery_victoriametrics_request_microseconds_bucket" => "VictoriaMetrics edge requests by duration, by kind, cumulative in le at the API's " <> - "bounds; counters, not a histogram. le=\"+Inf\" is the kind's request count.", + "bounds, the query bounds for kind=query (T-625); counters, not a histogram. " <> + "le=\"+Inf\" is the kind's request count.", "smolquery_victoriametrics_samples_total" => "Remote-write samples by result: written, or dropped as nan, histogram or exemplar, " <> "or refused with the block that carried them (PL-70).", @@ -580,6 +583,29 @@ defmodule Smolquery.Telemetry do 10_000_000 ] + # Bounds for the query series of the same families: the API's `query` + # route and the ClickHouse and VictoriaMetrics edges' `query` kind (T-625). + # A query runs up to `max_query_duration_ms` (30 s), and with only 2.5 s + # and 10 s between 1 s and the cap, `histogram_quantile` read every tail + # past 2.5 s as about 9.7 s and none past 10 s at all. + @query_latency_buckets [ + 50_000, + 100_000, + 250_000, + 500_000, + 750_000, + 1_000_000, + 1_500_000, + 2_000_000, + 3_000_000, + 5_000_000, + 7_500_000, + 10_000_000, + 15_000_000, + 20_000_000, + 30_000_000 + ] + # The API's routes by the controller that serves them: a closed set, so a # path parameter can never become a label. A controller not listed is # `other`, and so is a request no route matched. @@ -757,16 +783,26 @@ defmodule Smolquery.Telemetry do def handle_event([:smolquery, :api, :stop], measurements, %{conn: conn}, nil) do bump({"smolquery_api_requests_total", [class: status_class(conn.status)]}, 1) - timed("smolquery_api_request_microseconds", [route: api_route(conn)], measurements) + route = api_route(conn) + + timed( + "smolquery_api_request_microseconds", + [route: route], + measurements, + latency_buckets(route) + ) end def handle_event([:smolquery, :clickhouse, :stop], measurements, %{conn: conn}, nil) do bump({"smolquery_clickhouse_requests_total", [class: status_class(conn.status)]}, 1) + kind = clickhouse_kind(conn) + timed( "smolquery_clickhouse_request_microseconds", - [kind: clickhouse_kind(conn)], - measurements + [kind: kind], + measurements, + latency_buckets(kind) ) end @@ -788,10 +824,13 @@ defmodule Smolquery.Telemetry do def handle_event([:smolquery, :victoriametrics, :stop], measurements, %{conn: conn}, nil) do bump({"smolquery_victoriametrics_requests_total", [class: status_class(conn.status)]}, 1) + kind = victoriametrics_kind(conn) + timed( "smolquery_victoriametrics_request_microseconds", - [kind: victoriametrics_kind(conn)], - measurements + [kind: kind], + measurements, + latency_buckets(kind) ) end @@ -1143,14 +1182,17 @@ defmodule Smolquery.Telemetry do # Plug.Telemetry measures in native units; the counters are microseconds so # they divide against the other spans without a unit lookup at read time. - defp timed(family, labels, measurements) do + defp timed(family, labels, measurements, bounds) do duration_us = System.convert_time_unit(Map.get(measurements, :duration, 0), :native, :microsecond) bump({family <> "_total", labels}, duration_us) - bucket(family <> "_bucket", labels, @http_latency_buckets, duration_us) + bucket(family <> "_bucket", labels, bounds, duration_us) end + defp latency_buckets(:query), do: @query_latency_buckets + defp latency_buckets(_route_or_kind), do: @http_latency_buckets + defp api_route(%{private: %{phoenix_controller: controller}}) when is_atom(controller) do Map.get(@api_routes, controller |> Module.split() |> List.last(), :other) end diff --git a/test/smolquery/telemetry_test.exs b/test/smolquery/telemetry_test.exs index 2842afa7..97f59f55 100644 --- a/test/smolquery/telemetry_test.exs +++ b/test/smolquery/telemetry_test.exs @@ -176,6 +176,80 @@ defmodule Smolquery.TelemetryTest do assert value("smolquery_api_requests_total", ~s({class="2xx"})) == before_class + 3 end + test "query series take the query bounds, between 1 s and 30 s; the others keep theirs (T-625)" do + query_bounds = [ + 50_000, + 100_000, + 250_000, + 500_000, + 750_000, + 1_000_000, + 1_500_000, + 2_000_000, + 3_000_000, + 5_000_000, + 7_500_000, + 10_000_000, + 15_000_000, + 20_000_000, + 30_000_000 + ] + + cases = [ + {[:smolquery, :api, :stop], %{phoenix_controller: SmolqueryApi.QueryController}, + "smolquery_api_request_microseconds_bucket", ~s(route="query")}, + {[:smolquery, :clickhouse, :stop], %{smolquery_clickhouse_kind: :query}, + "smolquery_clickhouse_request_microseconds_bucket", ~s(kind="query")}, + {[:smolquery, :victoriametrics, :stop], %{smolquery_victoriametrics_kind: :query}, + "smolquery_victoriametrics_request_microseconds_bucket", ~s(kind="query")} + ] + + for {event, private, family, label} <- cases do + series = fn le -> "{#{label},le=\"#{le}\"}" end + before = Map.new(query_bounds ++ ["+Inf"], &{&1, value(family, series.(&1))}) + + stopped(event, private, 200, 3_400_000) + + moved = Map.new(before, fn {le, was} -> {le, value(family, series.(le)) - was} end) + + assert moved == + Map.new( + query_bounds ++ ["+Inf"], + &{&1, if(&1 == "+Inf" or &1 >= 5_000_000, do: 1, else: 0)} + ), + family + + refute Telemetry.render() =~ "#{family}#{series.(2_500_000)}", family + end + + insert = ~s({route="insert",le="2500000"}) + was = value("smolquery_api_request_microseconds_bucket", insert) + + stopped( + [:smolquery, :api, :stop], + %{phoenix_controller: SmolqueryApi.InsertController}, + 200, + 2_000_000 + ) + + assert value("smolquery_api_request_microseconds_bucket", insert) == was + 1 + + refute Telemetry.render() =~ + ~s(smolquery_api_request_microseconds_bucket{route="insert",le="3000000"}) + + write = ~s({kind="write",le="2500000"}) + was = value("smolquery_victoriametrics_request_microseconds_bucket", write) + + stopped( + [:smolquery, :victoriametrics, :stop], + %{smolquery_victoriametrics_kind: :write}, + 204, + 2_000_000 + ) + + assert value("smolquery_victoriametrics_request_microseconds_bucket", write) == was + 1 + end + test "a route is its controller's, a closed set: a path is never a label" do inf = fn route -> ~s({route="#{route}",le="+Inf"}) end family = "smolquery_api_request_microseconds_bucket" From 1bc5af70276586ac3b60f2ff7a11c5476a70b650 Mon Sep 17 00:00:00 2001 From: Chase Granberry Date: Fri, 2 Oct 2026 22:52:31 +0000 Subject: [PATCH 2/2] Review of T-625: a 60 s top bound, and the caps and mixing stated right Fable review of PR 449. - 30 s is only the VictoriaMetrics edge's max_query_duration_ms. An API query runs to its timeoutMs, 60 s by default, so one that took 30-60 s read as 30 s. The query bounds gain 60 s; the comment and the upgrade note name each edge's cap, and say a ClickHouse query past 60 s counts only in +Inf. - The upgrade note said old and new bounds mix only during a roll. A sum by (le) across routes or kinds now mixes them for good; the note says to filter or group by route or kind first. - The test's title said the bounds start at 1 s; they start at 50 ms. --- docs/clickhouse.md | 2 +- docs/deployment.md | 10 +++++----- lib/smolquery/telemetry.ex | 13 ++++++++----- test/smolquery/telemetry_test.exs | 5 +++-- 4 files changed, 17 insertions(+), 13 deletions(-) diff --git a/docs/clickhouse.md b/docs/clickhouse.md index d7714118..1f6b269a 100644 --- a/docs/clickhouse.md +++ b/docs/clickhouse.md @@ -27,7 +27,7 @@ curl -sS "http://127.0.0.1:8123/" \ - **Health checks.** `GET /` and `GET /ping` answer `Ok.` without a password, as ClickHouse does. - **Refused before the body.** A missing or wrong password is a 401 with code 516 `AUTHENTICATION_FAILED`, on every path. An insert is then counted against the in-flight limit before its body is read, as the API's insert is. Over the limit is a 429 with code 202 and `retry-after: 1`. - **Paths.** Everything happens on `/`. Any other path but `/ping` is a 404. -- **Metrics.** Requests are counted in `smolquery_clickhouse_requests_total`, by status class, and timed in `smolquery_clickhouse_request_microseconds_total` and `smolquery_clickhouse_request_microseconds_bucket` by `kind` (`insert`, `query`, `ping`, `other`): cumulative `le` counters at 5 ms to 10 s, and at 50 ms to 30 s for `query` (T-625), whose `le="+Inf"` is the kind's request count (T-546). +- **Metrics.** Requests are counted in `smolquery_clickhouse_requests_total`, by status class, and timed in `smolquery_clickhouse_request_microseconds_total` and `smolquery_clickhouse_request_microseconds_bucket` by `kind` (`insert`, `query`, `ping`, `other`): cumulative `le` counters at 5 ms to 10 s, and at 50 ms to 60 s for `query` (T-625), whose `le="+Inf"` is the kind's request count (T-546). ## The insert diff --git a/docs/deployment.md b/docs/deployment.md index ec9de072..3581a2cf 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -127,13 +127,13 @@ answers nothing at the TCP level. One note per release, newest first. -### 0.22.0: query latency buckets reach 30 s (T-625) +### 0.22.0: query latency buckets reach 60 s (T-625) -The query series of the HTTP edges' latency counters now use their own `le` bounds: `smolquery_api_request_microseconds_bucket{route="query"}` and the ClickHouse and VictoriaMetrics `..._request_microseconds_bucket{kind="query"}`. The bounds are 50, 100, 250, 500 and 750 ms, 1, 1.5, 2, 3, 5, 7.5, 10, 15, 20 and 30 s. +The query series of the HTTP edges' latency counters now use their own `le` bounds: `smolquery_api_request_microseconds_bucket{route="query"}` and the ClickHouse and VictoriaMetrics `..._request_microseconds_bucket{kind="query"}`. The bounds are 50, 100, 250, 500 and 750 ms, 1, 1.5, 2, 3, 5, 7.5, 10, 15, 20, 30 and 60 s. -- **Why:** the old bounds had only 2.5 s and 10 s above 1 s, so `histogram_quantile(0.99, ...)` read any query tail past 2.5 s as about 9.7 s, and nothing past 10 s at all. Queries run up to `max_query_duration_ms` (30 s). -- **Series:** each query series gains 7 `le` values (15 bounds instead of 8). Every other route and kind keeps 5 ms to 10 s. -- **Dashboards:** `histogram_quantile` over `sum by (le)` keeps working. While old and new pods both report, and for one rate window after the last old pod is gone, a `sum by (le)` mixes the two bound sets, and a quantile over it is rough. +- **Why:** the old bounds had only 2.5 s and 10 s above 1 s, so `histogram_quantile(0.99, ...)` read any query tail past 2.5 s as about 9.7 s, and nothing past 10 s at all. A VictoriaMetrics query stops at `max_query_duration_ms` (30 s), and an API query runs to its `timeoutMs`, 60 s by default. A ClickHouse query past 60 s counts only in `+Inf`, so a quantile reads it as 60 s. +- **Series:** each query series gains 8 `le` values (16 bounds instead of 8). Every other route and kind keeps 5 ms to 10 s. +- **Dashboards:** `histogram_quantile` over `sum by (le)` keeps working for one route or kind. Filter or group by `route` or `kind` first: a `sum by (le)` across them now mixes the two bound sets for good, and its quantile is rough. While old and new pods both report, and for one rate window after the last old pod is gone, a `sum by (le)` mixes the two bound sets, and a quantile over it is rough. ### 0.22.0: sockets to a replaced pod close in seconds (T-613, T-614) diff --git a/lib/smolquery/telemetry.ex b/lib/smolquery/telemetry.ex index 58fd1735..ba11cad1 100644 --- a/lib/smolquery/telemetry.ex +++ b/lib/smolquery/telemetry.ex @@ -302,7 +302,7 @@ defmodule Smolquery.Telemetry do "smolquery_api_requests_total" => "HTTP requests answered, by status class.", "smolquery_api_request_microseconds_bucket" => "HTTP requests by duration, by route, cumulative in le at 5 ms, 25 ms, 100 ms, 250 ms, " <> - "500 ms, 1 s, 2.5 s and 10 s, and for route=query at 50 ms to 30 s (T-625); counters, " <> + "500 ms, 1 s, 2.5 s and 10 s, and for route=query at 50 ms to 60 s (T-625); counters, " <> "not a histogram. le=\"+Inf\" is the route's request count, so _microseconds_total " <> "over it is the route's mean (T-546).", "smolquery_clickhouse_requests_total" => @@ -585,9 +585,11 @@ defmodule Smolquery.Telemetry do # Bounds for the query series of the same families: the API's `query` # route and the ClickHouse and VictoriaMetrics edges' `query` kind (T-625). - # A query runs up to `max_query_duration_ms` (30 s), and with only 2.5 s - # and 10 s between 1 s and the cap, `histogram_quantile` read every tail - # past 2.5 s as about 9.7 s and none past 10 s at all. + # With only 2.5 s and 10 s above 1 s, `histogram_quantile` read every query + # tail past 2.5 s as about 9.7 s and none past 10 s at all. The top bounds + # follow the caps: the VictoriaMetrics edge stops a query at + # `max_query_duration_ms` (30 s), and an API query runs to its `timeoutMs`, + # 60 s by default. A ClickHouse query past 60 s counts only in `+Inf`. @query_latency_buckets [ 50_000, 100_000, @@ -603,7 +605,8 @@ defmodule Smolquery.Telemetry do 10_000_000, 15_000_000, 20_000_000, - 30_000_000 + 30_000_000, + 60_000_000 ] # The API's routes by the controller that serves them: a closed set, so a diff --git a/test/smolquery/telemetry_test.exs b/test/smolquery/telemetry_test.exs index 97f59f55..2d9a35bd 100644 --- a/test/smolquery/telemetry_test.exs +++ b/test/smolquery/telemetry_test.exs @@ -176,7 +176,7 @@ defmodule Smolquery.TelemetryTest do assert value("smolquery_api_requests_total", ~s({class="2xx"})) == before_class + 3 end - test "query series take the query bounds, between 1 s and 30 s; the others keep theirs (T-625)" do + test "query series take the query bounds, 50 ms to 60 s; the others keep theirs (T-625)" do query_bounds = [ 50_000, 100_000, @@ -192,7 +192,8 @@ defmodule Smolquery.TelemetryTest do 10_000_000, 15_000_000, 20_000_000, - 30_000_000 + 30_000_000, + 60_000_000 ] cases = [