## Summary `AutoExplain.record` runs at the end of every RSpec process in MR and default-branch pipelines. It takes about **37s per lane**, after the lane's last example has finished. Most of that time seems to go into parsing the JSON plan of every query execution in the job, only to keep about 1,000 distinct queries. Deduplicating on `query_id` before parsing the JSON should make it much cheaper. ## Problem The PostgreSQL service runs with `auto_explain.log_min_duration=0` and `log_destination=csvlog` ([`.gitlab/ci/global.gitlab-ci.yml`](https://gitlab.com/gitlab-org/gitlab/-/blob/96a7b1a80632303ff3228ff56f830c6667631e3d/.gitlab/ci/global.gitlab-ci.yml#L95-120)). It logs the JSON plan of every query execution in the job. In `after(:suite)`, [`AutoExplain.record`](https://gitlab.com/gitlab-org/gitlab/-/blob/96a7b1a80632303ff3228ff56f830c6667631e3d/spec/support/database/auto_explain.rb) reads that log through `file_fdw`, once per database. For every row it runs: ```sql SELECT m.message->>'Query Text' AS query, m.message->'Plan' AS plan, m.query_id FROM ( SELECT substring(message from '\{.*$')::jsonb AS message, query_id FROM pglog WHERE database_name = $1 AND message LIKE '%{%' ) m; ``` It then streams the result to Ruby, which drops rows with a `query_id` it has already seen. Timings from the `took` lines in 416 `rspec-ee unit pg17` lane logs (tier 3 MR pipelines, 2026-10-13/14, first RSpec process only): | Database | p10 | p50 | p90 | max | |---|---|---|---|---| | `main` (about 1,040 distinct entries at p50) | 23.0s | **28.9s** | 36.9s | 53.2s | | `ci` | 3.3s | 4.0s | 4.9s | 6.6s | | `sec` | 3.0s | 3.7s | 4.5s | 7.9s | | **Mean total per lane** | | **37.5s** | | | The `ci` and `sec` passes scan the same CSV file, which holds every database's rows, but they keep few rows. So reading and filtering the file costs about 4s. The roughly 25s extra for `main` is spent on `main` rows: 1. PostgreSQL extracts the JSON from each message and parses it as `jsonb`. 2. It then converts `Plan` back to text, for every execution. 3. Every row is sent to Ruby, which then throws away all but about 1,000 of them. The cost scales with how many queries the job runs, not with how many distinct queries it keeps. This adds about 37s to every lane of every RSpec job that uses this PostgreSQL service. For `rspec-ee unit pg17` alone, that's about 29 runner-minutes per pipeline, and the group finishes about 37s later. ## Proposal Return the raw message instead of parsing it in SQL, and only parse the JSON for rows Ruby hasn't seen yet: ```ruby pg.send_query_params(<<~SQL.squish, [connection.current_database]) SELECT query_id, message FROM pglog WHERE database_name = $1 AND message LIKE '%{%' SQL pg.set_single_row_mode pg.get_result.stream_each do |row| query_id = row['query_id'].to_i next if query_id != 0 && !seen_query_ids.add?(query_id) message = Gitlab::Json.parse(row['message'][/\{.*\z/m]) query = message['Query Text'] next if query_id == 0 && !seen_queries.add?(query) fingerprint = PgQuery.fingerprint(query) next unless fingerprints.add?(fingerprint) gz.puts Gitlab::Json.generate( query_id: query_id, query: query, plan: message['Plan'], fingerprint: fingerprint, normalized: PgQuery.normalize(query) ) end ``` - Rows with a `query_id` that was already seen are skipped after a string-to-integer conversion, with no JSON parsing in PostgreSQL or Ruby. - About the same amount of data crosses the connection as today, which already sends the query text and plan for every row. - The scan stays a plain stream with no `DISTINCT` or `ORDER BY`. The code comments say this is deliberate, to avoid filling the disk with temp files. - The output file has the same entries, so `scripts/merge-auto-explain-logs` and its consumers don't change. Rows with `query_id = 0` still need parsing to dedupe on the query text. If they turn out to be common, the query text can be pulled from the raw message more cheaply than parsing the whole JSON. ### First, confirm where the time goes The split above is inferred from the `ci`/`sec` timings, not profiled. Before changing anything, time the current query against the proposed one on a real lane, for example in a draft MR that logs both `took` values and compares the output files. If most of the time turns out to be in the transfer or in Ruby building rows, the fix would look different. ## Risks - **Memory:** unchanged. The Ruby sets already hold one entry per distinct `query_id` and per query text. - **Correctness:** compare the output files of the old and new versions on the same lane before switching. ## How to verify - In lane logs, `took` for `main` should drop from about 29s (p50) to close to the roughly 4s that `ci` and `sec` take. - Lane durations of balanced RSpec jobs should drop by about 25-30s. ## Related - gitlab-org/gitlab#633791: make the RSpec retry process cheaper. It includes skipping this step in the retry process, where it's pure duplication.