sql: EXPLAIN ANALYZE (DEBUG) 4-12x slower for queries with large lookup joins

[michae2]

Queries that perform large lookup joins (tens of thousands of rows) are roughly 4-12x slower to EXPLAIN ANALYZE than to execute normally. This seems to be true on 21.2, 22.1, 22.2, and probably earlier releases as well. Here's a demonstration on 22.2.0:

CREATE TABLE t (a PRIMARY KEY, b) AS SELECT i, i FROM generate_series(0, 99999) s(i);
CREATE TABLE u (x PRIMARY KEY, y) AS SELECT * FROM t;
ANALYZE t;
ANALYZE u;
SELECT count(*) FROM t JOIN u@{NO_FULL_SCAN} ON x = b WHERE a >= 50000;
EXPLAIN ANALYZE SELECT count(*) FROM t JOIN u@{NO_FULL_SCAN} ON x = b WHERE a >= 50000;

On a one-node cockroach demo the normal execution takes 274 ms, and the EXPLAIN ANALYZE takes 3.29s:

[email protected]:26257/defaultdb> SELECT count(*) FROM t JOIN u@{NO_FULL_SCAN} ON x = b WHERE a >= 50000;
  count
---------
  50000
(1 row)


Time: 274ms total (execution 274ms / network 0ms)

[email protected]:26257/defaultdb> EXPLAIN ANALYZE SELECT count(*) FROM t JOIN u@{NO_FULL_SCAN} ON x = b WHERE a >= 50000;
                                            info
--------------------------------------------------------------------------------------------
  planning time: 1ms
  execution time: 3.3s
  distribution: full
  vectorized: true
  rows read from KV: 100,000 (2.4 MiB, 5 gRPC calls)
  cumulative time spent in KV: 3.2s
  maximum memory usage: 23 MiB
  network usage: 0 B (0 messages)
  regions: us-east1

  • group (scalar)
  │ nodes: n1
  │ regions: us-east1
  │ actual row count: 1
  │ estimated row count: 1
  │
  └── • lookup join
      │ nodes: n1
      │ regions: us-east1
      │ actual row count: 50,000
      │ KV time: 3.2s
      │ KV contention time: 0µs
      │ KV rows read: 50,000
      │ KV bytes read: 766 KiB
      │ KV gRPC calls: 4
      │ estimated max memory allocated: 22 MiB
      │ estimated row count: 50,067
      │ table: u@u_pkey
      │ equality: (b) = (x)
      │ equality cols are key
      │
      └── • scan
            nodes: n1
            regions: us-east1
            actual row count: 50,000
            KV time: 17ms
            KV contention time: 0µs
            KV rows read: 50,000
            KV bytes read: 1.6 MiB
            KV gRPC calls: 1
            estimated max memory allocated: 1.6 MiB
            estimated row count: 49,896 (50% of the table; stats collected 24 seconds ago)
            table: t@t_pkey
            spans: [/50000 - ]
(44 rows)


Time: 3.290s total (execution 3.289s / network 0.000s)

We record many events in the trace for each lookup of the lookup join, which happens 50k times for this query.

Jira issue: CRDB-20918

[michae2]

(Note that this is different from #80671 which was fixed in 21.2.)

[DrewKimball]

5-second cpu and heap profiles from running the explain analyze query repeatedly against a single-node cluster:
cpu-profile.pb.gz

heap-profile.pb.gz

[yuzefovich]

From the team meeting:

• fix the low hanging fruit of overhead of formatting the keys
• disable the highly verbose tracing if we only have EXPLAIN ANALYZE (as opposed to EXPLAIN ANALYZE (DEBUG)) done in sql: reduce the overhead of EXPLAIN ANALYZE #91117.