Give the edges' query latency series buckets up to 60 s (T-625)

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
 

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.

lib/smolquery/telemetry.ex

@@ -302,16 +302,18 @@ 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" =>
       "Time spent answering ClickHouse HTTP edge requests, by kind: insert, query, ping or " <>
         "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

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"