Update
Though I am still not happy with the row estimates, I found the root issue. The student_snapshot table used text for student_id while the other two used citext. We recently updated student_snapshot to also be citext so that they all matched. I don't understand why it used a better query plan back when they mismatched but in comparing query plans I saw that it was doing snp.student_id = t.student_id::text. When I altered the query to snp.student_id::text = t.student_id::text it became fast again. Seems a bit counterintuitive since the conversion should be less efficient, but it led to a much better query plan even though the row estimate was still terribly off. It uses a Parallel Hash Join instead of a Nested Loop. Sorry I didn't provide enough context for this earlier.
Update
Though I am still not happy with the row estimates, I found the root issue. The student_snapshot table used text for student_id while the other two used citext. We recently updated student_snapshot to also be citext so that they all matched. I don't understand why it used a better query plan back when they mismatched but in comparing query plans I saw that it was doing snp.student_id = t.student_id::text. When I altered the query to snp.student_id::text = t.student_id::text it became fast again. Seems a bit counterintuitive since the conversion should be less efficient, but it led to a much better query plan even though the row estimate was still terribly off. It uses a Parallel Hash Join instead of a Nested Loop. Sorry I didn't provide enough context for this earlier.
The query is more complex than this but I can create a minimal reproducible example from the essenseessence of these three tables:
select rt.*, st.grade_id as current_grade_id, snp.grade_id as snapshot_grade_id
from student st
join ratingtest rt
on rt.student_id = st.student_id
join student_snapshot snp
on snp.student_id = rt.student_id
and snp.created_at = rt.student_snapshot_date
The query was taking < 1s but can now take upwards of 2hrs after a recent infusion of data into the database (~50% increase). The performance did not degrade linearly as the volume increased. It appears to have changed the normal query plan which now uses a Nested Loop. It appears to be making this choice because it expects the row count to be 2 when it is really closer to 90k. I find it interesting that when I leave off the and snp.created_at = rt.student_snapshot_date condition that the query plan has a reasonable expectation of the number of rows returned and does not choose a Nested Loop.
QUERY PLAN |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
Nested Loop (cost=2044.29..6432.12 rows=2 width=10) (actual time=65.097..1904659.897 rows=72902 loops=1) |
Output: st.student_id |
Buffers: shared hit=34879380 |
-> Hash Join (cost=2043.88..5769.94 rows=2 width=20) (actual time=41.050..955.542 rows=90631 loops=1) |
Output: rt.student_id, snp.student_id |
Hash Cond: ((rt.student_id = snp.student_id) AND (rt.student_snapshot_date = snp.created_at)) |
Buffers: shared hit=3015 |
-> Seq Scan on public."rating""test" rt (cost=0.00..3046.31 rows=90631 width=18) (actual time=0.010..169.664 rows=90631 loops=1) |
Output: rt.id, r.program_id, r.organization_id, r.assessment_type_id, r.rater_type_id, r.t_score, r.created_at, r.duration, r.rater_email, r.assignment_period, rt.student_id, r.student_snapshot_date, r.descriptive_range_id, rt.language_code|student_snapshot_date|
Buffers: shared hit=2140 |
-> Hash (cost=1342.55..1342.55 rows=46755 width=18) (actual time=39.342..39.343 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at |
Buckets: 65536 Batches: 1 Memory Usage: 3069kB |
Buffers: shared hit=875 |
-> Seq Scan on public."student_snapshot" snp (cost=0.00..1342.55 rows=46755 width=18) (actual time=0.018..13.942 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at |
Buffers: shared hit=875 |
-> Index Only Scan using "student_key" on public."student" st (cost=0.41..331.08 rows=1 width=10) (actual time=12.086..21.000 rows=1 loops=90631) |
Output: st.program_id, st.organization_id, st.student_id |
Index Cond: (st.student_id = rt.student_id) |
Heap Fetches: 74061 |
Buffers: shared hit=34876365 |
Planning: |
Buffers: shared hit=40 |
Planning Time: 1.063 ms |
Execution Time: 1904722.476 ms |
QUERY PLAN |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
Hash Join (cost=4254.08..8568.10 rows=92784 width=10) (actual time=114.921..219.856 rows=74332 loops=1) |
Output: st.student_id |
Hash Cond: (rt.student_id = st.student_id) |
Buffers: shared hit=3744 |
-> Seq Scan on public."rating""test" rt (cost=0.00..3046.31 rows=90631 width=10) (actual time=0.010..12.670 rows=90631 loops=1) |
Output: rt.id, r.program_id, r.organization_id, r.assessment_type_id, r.rater_type_id, r.t_score, r.created_at, r.duration, r.rater_email, r.assignment_period, rt.student_id, r.student_snapshot_date, r.descriptive_range_id, rt.language_code|student_snapshot_date|
Buffers: shared hit=2140 |
-> Hash (cost=3689.98..3689.98 rows=45128 width=20) (actual time=114.737..114.739 rows=36995 loops=1) |
Output: st.student_id, snp.student_id |
Buckets: 65536 Batches: 1 Memory Usage: 2391kB |
Buffers: shared hit=1604 |
-> Hash Join (cost=1720.82..3689.98 rows=45128 width=20) (actual time=33.975..95.906 rows=36995 loops=1) |
Output: st.student_id, snp.student_id |
Hash Cond: (snp.student_id = st.student_id) |
Buffers: shared hit=1604 |
-> Seq Scan on public."student_snapshot" snp (cost=0.00..1342.55 rows=46755 width=10) (actual time=0.030..13.741 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at, snp.program_id, snp.organization_id, snp.first_name, snp.last_name, snp.gender_id, snp.grade_id, snp.date_of_birth, snp.race, snp.academic, snp.zip, snp.state_id |
Buffers: shared hit=875 |
-> Hash (cost=1169.81..1169.81 rows=44081 width=10) (actual time=31.513..31.514 rows=43262 loops=1) |
Output: st.student_id |
Buckets: 65536 Batches: 1 Memory Usage: 2287kB |
Buffers: shared hit=729 |
-> Seq Scan on public."student" st (cost=0.00..1169.81 rows=44081 width=10) (actual time=0.015..10.926 rows=43262 loops=1) |
Output: st.student_id |
Buffers: shared hit=729 |
Planning: |
Buffers: shared hit=40 |
Planning Time: 1.042 ms |
Execution Time: 223.517 ms |
CREATE STATISTICS "rating_st_snp_pk""test_st_snp_pk" ON student_id, student_snapshot_date FROM "rating";"test";
CREATE STATISTICS "st_snp_pk" ON student_id, created_at FROM "student_snapshot";
alter table "rating""test" alter student_id set statistics 500;
alter table "rating""test" alter student_snapshot_date set statistics 500;
alter table "student_snapshot" alter student_id set statistics 500;
alter table "student_snapshot" alter created_at set statistics 500;
I tried clustering on a parallel indexes for ratingtest and student_snapshot to see if it would find more hits if they were sorted the same:
cluster "rating""test" using "rating__student_id_student_snapshot_date_idx";"test_student_id_student_snapshot_date_idx";
cluster "student_snapshot" using "student_snapshot_pkey";
with rating_w_snaptest_w_snap as materialized (
select rt.*, snp.grade_id
from ratingtest rt
join student_snapshot snp
on snp.student_id = rt.student_id
and snp.created_at = rt.student_snapshot_date
)
select rt.*, st.grade_id as current_grade_id, rt.grade_id as snapshot_grade_id
from student st
join rating_w_snaptest_w_snap rt
on rt.student_id = st.student_id
The query is more complex than this but I can create a minimal reproducible example from the essense of these three tables:
select r.*, st.grade_id as current_grade_id, snp.grade_id as snapshot_grade_id
from student st
join rating r
on r.student_id = st.student_id
join student_snapshot snp
on snp.student_id = r.student_id
and snp.created_at = r.student_snapshot_date
The query was taking < 1s but can now take upwards of 2hrs after a recent infusion of data into the database (~50% increase). The performance did not degrade linearly as the volume increased. It appears to have changed the normal query plan which now uses a Nested Loop. It appears to be making this choice because it expects the row count to be 2 when it is really closer to 90k. I find it interesting that when I leave off the and snp.created_at = r.student_snapshot_date condition that the query plan has a reasonable expectation of the number of rows returned and does not choose a Nested Loop.
QUERY PLAN |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
Nested Loop (cost=2044.29..6432.12 rows=2 width=10) (actual time=65.097..1904659.897 rows=72902 loops=1) |
Output: st.student_id |
Buffers: shared hit=34879380 |
-> Hash Join (cost=2043.88..5769.94 rows=2 width=20) (actual time=41.050..955.542 rows=90631 loops=1) |
Output: r.student_id, snp.student_id |
Hash Cond: ((r.student_id = snp.student_id) AND (r.student_snapshot_date = snp.created_at)) |
Buffers: shared hit=3015 |
-> Seq Scan on public."rating" r (cost=0.00..3046.31 rows=90631 width=18) (actual time=0.010..169.664 rows=90631 loops=1) |
Output: r.id, r.program_id, r.organization_id, r.assessment_type_id, r.rater_type_id, r.t_score, r.created_at, r.duration, r.rater_email, r.assignment_period, r.student_id, r.student_snapshot_date, r.descriptive_range_id, r.language_code|
Buffers: shared hit=2140 |
-> Hash (cost=1342.55..1342.55 rows=46755 width=18) (actual time=39.342..39.343 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at |
Buckets: 65536 Batches: 1 Memory Usage: 3069kB |
Buffers: shared hit=875 |
-> Seq Scan on public."student_snapshot" snp (cost=0.00..1342.55 rows=46755 width=18) (actual time=0.018..13.942 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at |
Buffers: shared hit=875 |
-> Index Only Scan using "student_key" on public."student" st (cost=0.41..331.08 rows=1 width=10) (actual time=12.086..21.000 rows=1 loops=90631) |
Output: st.program_id, st.organization_id, st.student_id |
Index Cond: (st.student_id = r.student_id) |
Heap Fetches: 74061 |
Buffers: shared hit=34876365 |
Planning: |
Buffers: shared hit=40 |
Planning Time: 1.063 ms |
Execution Time: 1904722.476 ms |
QUERY PLAN |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
Hash Join (cost=4254.08..8568.10 rows=92784 width=10) (actual time=114.921..219.856 rows=74332 loops=1) |
Output: st.student_id |
Hash Cond: (r.student_id = st.student_id) |
Buffers: shared hit=3744 |
-> Seq Scan on public."rating" r (cost=0.00..3046.31 rows=90631 width=10) (actual time=0.010..12.670 rows=90631 loops=1) |
Output: r.id, r.program_id, r.organization_id, r.assessment_type_id, r.rater_type_id, r.t_score, r.created_at, r.duration, r.rater_email, r.assignment_period, r.student_id, r.student_snapshot_date, r.descriptive_range_id, r.language_code|
Buffers: shared hit=2140 |
-> Hash (cost=3689.98..3689.98 rows=45128 width=20) (actual time=114.737..114.739 rows=36995 loops=1) |
Output: st.student_id, snp.student_id |
Buckets: 65536 Batches: 1 Memory Usage: 2391kB |
Buffers: shared hit=1604 |
-> Hash Join (cost=1720.82..3689.98 rows=45128 width=20) (actual time=33.975..95.906 rows=36995 loops=1) |
Output: st.student_id, snp.student_id |
Hash Cond: (snp.student_id = st.student_id) |
Buffers: shared hit=1604 |
-> Seq Scan on public."student_snapshot" snp (cost=0.00..1342.55 rows=46755 width=10) (actual time=0.030..13.741 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at, snp.program_id, snp.organization_id, snp.first_name, snp.last_name, snp.gender_id, snp.grade_id, snp.date_of_birth, snp.race, snp.academic, snp.zip, snp.state_id |
Buffers: shared hit=875 |
-> Hash (cost=1169.81..1169.81 rows=44081 width=10) (actual time=31.513..31.514 rows=43262 loops=1) |
Output: st.student_id |
Buckets: 65536 Batches: 1 Memory Usage: 2287kB |
Buffers: shared hit=729 |
-> Seq Scan on public."student" st (cost=0.00..1169.81 rows=44081 width=10) (actual time=0.015..10.926 rows=43262 loops=1) |
Output: st.student_id |
Buffers: shared hit=729 |
Planning: |
Buffers: shared hit=40 |
Planning Time: 1.042 ms |
Execution Time: 223.517 ms |
CREATE STATISTICS "rating_st_snp_pk" ON student_id, student_snapshot_date FROM "rating";
CREATE STATISTICS "st_snp_pk" ON student_id, created_at FROM "student_snapshot";
alter table "rating" alter student_id set statistics 500;
alter table "rating" alter student_snapshot_date set statistics 500;
alter table "student_snapshot" alter student_id set statistics 500;
alter table "student_snapshot" alter created_at set statistics 500;
I tried clustering on a parallel indexes for rating and student_snapshot to see if it would find more hits if they were sorted the same:
cluster "rating" using "rating__student_id_student_snapshot_date_idx";
cluster "student_snapshot" using "student_snapshot_pkey";
with rating_w_snap as materialized (
select r.*, snp.grade_id
from rating r
join student_snapshot snp
on snp.student_id = r.student_id
and snp.created_at = r.student_snapshot_date
)
select r.*, st.grade_id as current_grade_id, r.grade_id as snapshot_grade_id
from student st
join rating_w_snap r
on r.student_id = st.student_id
The query is more complex than this but I can create a minimal reproducible example from the essence of these three tables:
select t.*, st.grade_id as current_grade_id, snp.grade_id as snapshot_grade_id
from student st
join test t
on t.student_id = st.student_id
join student_snapshot snp
on snp.student_id = t.student_id
and snp.created_at = t.student_snapshot_date
The query was taking < 1s but can now take upwards of 2hrs after a recent infusion of data into the database (~50% increase). The performance did not degrade linearly as the volume increased. It appears to have changed the normal query plan which now uses a Nested Loop. It appears to be making this choice because it expects the row count to be 2 when it is really closer to 90k. I find it interesting that when I leave off the and snp.created_at = t.student_snapshot_date condition that the query plan has a reasonable expectation of the number of rows returned and does not choose a Nested Loop.
QUERY PLAN |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
Nested Loop (cost=2044.29..6432.12 rows=2 width=10) (actual time=65.097..1904659.897 rows=72902 loops=1) |
Output: st.student_id |
Buffers: shared hit=34879380 |
-> Hash Join (cost=2043.88..5769.94 rows=2 width=20) (actual time=41.050..955.542 rows=90631 loops=1) |
Output: t.student_id, snp.student_id |
Hash Cond: ((t.student_id = snp.student_id) AND (t.student_snapshot_date = snp.created_at)) |
Buffers: shared hit=3015 |
-> Seq Scan on public."test" t (cost=0.00..3046.31 rows=90631 width=18) (actual time=0.010..169.664 rows=90631 loops=1) |
Output: t.id, t.student_id, t.student_snapshot_date|
Buffers: shared hit=2140 |
-> Hash (cost=1342.55..1342.55 rows=46755 width=18) (actual time=39.342..39.343 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at |
Buckets: 65536 Batches: 1 Memory Usage: 3069kB |
Buffers: shared hit=875 |
-> Seq Scan on public."student_snapshot" snp (cost=0.00..1342.55 rows=46755 width=18) (actual time=0.018..13.942 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at |
Buffers: shared hit=875 |
-> Index Only Scan using "student_key" on public."student" st (cost=0.41..331.08 rows=1 width=10) (actual time=12.086..21.000 rows=1 loops=90631) |
Output: st.program_id, st.organization_id, st.student_id |
Index Cond: (st.student_id = t.student_id) |
Heap Fetches: 74061 |
Buffers: shared hit=34876365 |
Planning: |
Buffers: shared hit=40 |
Planning Time: 1.063 ms |
Execution Time: 1904722.476 ms |
QUERY PLAN |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
Hash Join (cost=4254.08..8568.10 rows=92784 width=10) (actual time=114.921..219.856 rows=74332 loops=1) |
Output: st.student_id |
Hash Cond: (t.student_id = st.student_id) |
Buffers: shared hit=3744 |
-> Seq Scan on public."test" t (cost=0.00..3046.31 rows=90631 width=10) (actual time=0.010..12.670 rows=90631 loops=1) |
Output: t.id, t.student_id, t.student_snapshot_date|
Buffers: shared hit=2140 |
-> Hash (cost=3689.98..3689.98 rows=45128 width=20) (actual time=114.737..114.739 rows=36995 loops=1) |
Output: st.student_id, snp.student_id |
Buckets: 65536 Batches: 1 Memory Usage: 2391kB |
Buffers: shared hit=1604 |
-> Hash Join (cost=1720.82..3689.98 rows=45128 width=20) (actual time=33.975..95.906 rows=36995 loops=1) |
Output: st.student_id, snp.student_id |
Hash Cond: (snp.student_id = st.student_id) |
Buffers: shared hit=1604 |
-> Seq Scan on public."student_snapshot" snp (cost=0.00..1342.55 rows=46755 width=10) (actual time=0.030..13.741 rows=46755 loops=1) |
Output: snp.student_id, snp.created_at, snp.program_id, snp.organization_id, snp.first_name, snp.last_name, snp.gender_id, snp.grade_id, snp.date_of_birth, snp.race, snp.academic, snp.zip, snp.state_id |
Buffers: shared hit=875 |
-> Hash (cost=1169.81..1169.81 rows=44081 width=10) (actual time=31.513..31.514 rows=43262 loops=1) |
Output: st.student_id |
Buckets: 65536 Batches: 1 Memory Usage: 2287kB |
Buffers: shared hit=729 |
-> Seq Scan on public."student" st (cost=0.00..1169.81 rows=44081 width=10) (actual time=0.015..10.926 rows=43262 loops=1) |
Output: st.student_id |
Buffers: shared hit=729 |
Planning: |
Buffers: shared hit=40 |
Planning Time: 1.042 ms |
Execution Time: 223.517 ms |
CREATE STATISTICS "test_st_snp_pk" ON student_id, student_snapshot_date FROM "test";
CREATE STATISTICS "st_snp_pk" ON student_id, created_at FROM "student_snapshot";
alter table "test" alter student_id set statistics 500;
alter table "test" alter student_snapshot_date set statistics 500;
alter table "student_snapshot" alter student_id set statistics 500;
alter table "student_snapshot" alter created_at set statistics 500;
I tried clustering on a parallel indexes for test and student_snapshot to see if it would find more hits if they were sorted the same:
cluster "test" using "test_student_id_student_snapshot_date_idx";
cluster "student_snapshot" using "student_snapshot_pkey";
with test_w_snap as materialized (
select t.*, snp.grade_id
from test t
join student_snapshot snp
on snp.student_id = t.student_id
and snp.created_at = t.student_snapshot_date
)
select t.*, st.grade_id as current_grade_id, t.grade_id as snapshot_grade_id
from student st
join test_w_snap t
on t.student_id = st.student_id
The only thing I have done that has worked is to materialize part of the query but that isn't as efficient as it should be. But even that failed when I started adding back in the peripheral tables that were part of the more complex query.
The only thing I have done that has worked is to materialize part of the query but that isn't as efficient as it should be.
The only thing I have done that has worked is to materialize part of the query but that isn't as efficient as it should be. But even that failed when I started adding back in the peripheral tables that were part of the more complex query.
lang-sql