diff --git a/docs/clickhouse.md b/docs/clickhouse.md index 68cb2f01..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, 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 15c37961..3581a2cf 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 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, 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. 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) - **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..ba11cad1 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 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" => "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,32 @@ 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). + # 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, + 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, + 60_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 +786,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 +827,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 +1185,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..2d9a35bd 100644 --- a/test/smolquery/telemetry_test.exs +++ b/test/smolquery/telemetry_test.exs @@ -176,6 +176,81 @@ defmodule Smolquery.TelemetryTest do assert value("smolquery_api_requests_total", ~s({class="2xx"})) == before_class + 3 end + 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, + 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, + 60_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"