slow count queries - what are we doing wrong?

Question

Using Postgresql 9.6.14, running the following query:

SELECT COUNT(*) AS "__count"  
  FROM "crm_client"  
  INNER JOIN "crm_role"  
      ON ("crm_client"."role_ptr_id" = "crm_role"."id")  
  INNER JOIN "tcauth_user"  
      ON ("crm_role"."user_id" = "tcauth_user"."id")  
  WHERE ("tcauth_user"."branch_id" = ?  
          AND "tcauth_user"."is_deleted" = false)
result -> ~3500

Seems so simple, yet is very slow. I get the following output from explain analyze ...:

Finalize Aggregate  (cost=24741.60..24741.60 rows=1 width=8) (actual time=429.478..429.478 rows=1 loops=1)
  ->  Gather  (cost=24741.49..24741.60 rows=1 width=8) (actual time=429.204..445.027 rows=2 loops=1)
        Workers Planned: 1
        Workers Launched: 1
        ->  Partial Aggregate  (cost=23741.49..23741.50 rows=1 width=8) (actual time=420.130..420.130 rows=1 loops=2)
              ->  Nested Loop  (cost=15134.68..23739.67 rows=3640 width=0) (actual time=89.982..419.729 rows=1729 loops=2)
                    ->  Hash Join  (cost=15134.60..22918.76 rows=8621 width=4) (actual time=89.440..367.009 rows=7892 loops=2)
                          Hash Cond: (crm_role.user_id = tcauth_user.id)
                          ->  Parallel Seq Scan on crm_role  (cost=0.00..7519.84 rows=317948 width=8) (actual time=0.015..180.495 rows=271204 loops=2)
                          ->  Hash  (cost=15085.97..15085.97 rows=13894 width=4) (actual time=89.225..89.225 rows=15655 loops=2)
                                Buckets: 16384  Batches: 1  Memory Usage: 679kB
                                ->  Bitmap Heap Scan on tcauth_user  (cost=149.43..15085.97 rows=13894 width=4) (actual time=6.147..78.915 rows=15655 loops=2)
                                      Recheck Cond: (branch_id = ?)
                                      Filter: (NOT is_deleted)
                                      Rows Removed by Filter: 253
                                      Heap Blocks: exact=4844
                                      ->  Bitmap Index Scan on tcauth_user_09fd5b13  (cost=0.00..148.73 rows=15100 width=0) (actual time=5.176..5.176 rows=15914
                                            Index Cond: (branch_id = ?)
                    ->  Index Only Scan using crm_client_pkey on crm_client  (cost=0.08..0.09 rows=1 width=4) (actual time=0.006..0.006 rows=0 loops=15784)
                          Index Cond: (role_ptr_id = crm_role.id)
                          Heap Fetches: 73
Planning time: 2.769 ms
Execution time: 445.225 ms

Why is this query so slow? I'm concerned about the nested loop, but not sure if that's really the culprit. The expected costs of some steps are very different from the actual although the row counts are not that different, is this causing a poor query plan?

What can we do to improve the performance of this query (excluding increasing server specs.)? Would another index type help?

Would upgrading from pg 9.6 to 11 improve this?

Schema looks roughly like this:

CREATE TABLE tcauth_user (
  id SERIAL PRIMARY KEY,
  is_deleted BOOLEAN DEFAULT TRUE,
  branch_id INT NOT NULL REFERENCES branches,
  ...
);
CREATE TABLE crm_role (
  id SERIAL PRIMARY KEY,
  user_id INT NOT NULL REFERENCES tcauth_user,
  ...
);
CREATE TABLE crm_client (
  id SERIAL PRIMARY KEY,
  role_ptr_id INT NOT NULL REFERENCES crm_role,
  ...
);

All fields in joins and the where clause have btree indexes. Obviously all tables have other fields not included here for brevity.

---

Update: (to add information requested by @jjanes below)

> explain (analyze, buffers) select count(*) from crm_role
Aggregate  (cost=8465.40..8465.40 rows=1 width=8) (actual time=111.896..111.896 rows=1 loops=1)
  Buffers: shared hit=6566
  ->  Seq Scan on crm_role  (cost=0.00..8194.06 rows=542685 width=0) (actual time=0.022..72.772 rows=542726 loops=1)
        Buffers: shared hit=6566
Planning time: 0.346 ms
Execution time: 111.976 ms

I'm running the query on the production database to get real results, unfortunately since it's on Heroku, it's not easy to enable track_io_timing. The database is Heroku's "Standard 3" database.

Answer 1

How fast do you expect this to be? It is taking about the amount of time I would expect (a little slower, but that is probably your hardware). The query may be simple to specify, but it handles a large amount of data.

Most of the time of the nested loop is taken up by waiting for its first child (the hash join) to returns its results. The nested loop itself is not the culprit. Anything else using that child node would take about the same time.

The expected costs of some steps are very different from the actual

The expected cost does not have the same units as the measured times do. So there is no reason to expect them be very similar. They should be roughly proportional, but that is only very rough. The planner has no way of knowing how much of the data it will need for a specific execution will be found in cache, it just make generic assumptions. Since reading data from disk (or even from ssd) when that needs to happen can completely dominate the run time, this means there is only so accurate the estimated costs can be.

is this causing a poor query plan?

We don't know that the query plan is poor. At least, you haven't shown a better one. You could try doing set enable_hashjoin=off to see what that gets you, and also set enable_nestedloop=off (after turning hashjoin back on) to see what it produces. If they give better plans, then you have to ponder if they would really be better under different levels of cache hotness.

Would upgrading from pg 9.6 to 11 improve this?

I would not expect it to make a big difference for this particular query and execution plan. Your biggest bottleneck is already being parallelized (the seq scan on crm_role). The upgrade could also parallelize the Bitmap Heap Scan on tcauth_user, but there is only so much that that can help.

Why is the seq scan so slow? What do you get with explain (analyze, buffers) select count(*) from crm_role? Preferably, turn track_io_timing on before running that.