Log ClickHouse query statistics in the structured request and Sidekiq logs

Issue: #637712 (closed)

What does this MR do and why?

ClickHouse::Client already instruments every query as a sql.click_house notification and puts the statistics ClickHouse returns on the payload: the JSON statistics object on select (rows_read, bytes_read, elapsed) and the X-ClickHouse-Summary header on execute and insert_csv (read_rows, read_bytes, elapsed_ns, as strings). Only the performance bar subscribed to it, so the structured logs carried no indication of how much data a request read from ClickHouse.

This MR adds Gitlab::Metrics::Subscribers::ClickHouse, which attaches to sql.click_house and accumulates per-request totals in Gitlab::SafeRequestStore, accepting either key naming, the way ExternalHttp and Ldap keep their counters. Gitlab::InstrumentationHelper.add_instrumentation_data merges its payload into the request payload the same way it does for Gitaly, Redis, Elasticsearch and OpenBao; payload is an empty hash when no query ran. The ClickHouse initializer loads the subscriber after boot, so it is attached before the first query even where classes are not eager loaded (development, test). The four fields land in production_json.log, api_json.log and the Sidekiq job logs:

• clickhouse_queries_count
• clickhouse_rows_read
• clickhouse_bytes_read
• clickhouse_duration_s

The keys are only added when at least one ClickHouse query ran, so requests that never touch ClickHouse log exactly what they log today. A query whose response has no statistics (the header is absent, or the body has no statistics object) is still counted and contributes zero rows and bytes; so is a query that raises inside the instrumented block, since the client raises before it can set the statistics. clickhouse_duration_s is the client-side round trip measured by ActiveSupport::Notifications, consistent with gitaly_duration_s and redis_duration_s, rather than the server-side elapsed.

The issue also suggests putting the per-query values on the existing clickhouse.log line. The gem writes that line before it sends the request (configuration.logger.info(log_proc.call(query)) runs ahead of the instrument block), so the statistics do not exist at that point and the change belongs in the click_house-client gem, not here. Left out of this MR.

No feature flag: the change only adds fields to log lines.

Business impact

The structured logs record that a request ran ClickHouse queries, not what they cost. When a dashboard is slow or the shared cluster is saturated, nothing in Kibana says which endpoint, user or job made ClickHouse read billions of rows; each Bulkhead investigation (#636117, #636113, #636121) had to reproduce the query locally.

With this MR every request or Sidekiq job that ran at least one ClickHouse query logs clickhouse_queries_count, clickhouse_rows_read, clickhouse_bytes_read and clickhouse_duration_s. Nothing else changes: no limit is enforced, no flag is needed, requests that do not touch ClickHouse log what they log today. The fields are the baseline the later Bulkhead thresholds are set from.

Queries this change generates

None added. The subscriber reads the statistics ClickHouse already returns with each response.

Example log line

Captured on GDK with rails runner -e development, inside Gitlab::SafeRequestStore.ensure_request_store, after ClickHouse::Client.select('SELECT 1', :main) and ClickHouse::Client.select('SELECT number FROM system.numbers LIMIT 1000', :main), printing the ClickHouse keys of Gitlab::InstrumentationHelper.add_instrumentation_data({}). These keys are added to the regular request fields of the line.

{"clickhouse_queries_count":2,"clickhouse_rows_read":1001,"clickhouse_bytes_read":8001,"clickhouse_duration_s":0.088442}

Verification

• spec/lib/gitlab/metrics/subscribers/click_house_spec.rb: totals accumulate across events with both key namings, missing statistics count the query with zeros, payload is empty when nothing ran or the request store is inactive, the duration is rounded to the instrumentation precision; a real sql.click_house notification whose payload is filled inside the block reaches the counters; a block that raises is counted with zero rows and bytes; and a :click_house example drives ClickHouse::Client.select('SELECT 1', :main) against the server and checks count, rows and duration.
• spec/lib/gitlab/instrumentation_helper_spec.rb: the four keys appear after a ClickHouse query and are absent otherwise.

bundle exec rspec on the two files: 83 examples, 0 failures (spec/lib/gitlab/metrics/subscribers/click_house_spec.rb 10 examples, spec/lib/gitlab/instrumentation_helper_spec.rb 73 examples), run against a local ClickHouse 26.8.

ActiveSupport::Notifications.notifier.listeners_for('sql.click_house') in rails runner -e development (no eager loading) lists Gitlab::Metrics::Subscribers::ClickHouse next to the Peek proc at boot.

bundle exec rubocop --force-exclusion on the changed Ruby files: 4 files inspected, no offenses detected.

MR acceptance checklist

Evaluate this MR against the MR acceptance checklist. It helps you analyze changes to reduce risks in quality, performance, reliability, security, and maintainability.

Related to #637712 (closed)