Search code examples
postgresqlindexinggenerated-columns

Postgres index on GENERATED column slow


I've a datetime column in my postgres 13 database that's stored without a timezone (my mistake). In a view, it's converted but that makes queries slow as Postgres does a full table scan, ignoring the index on the original column.

I created a new column 'realstart' and just set the value to be the calculation I was using in the view using UPDATE. Then indexed. Query really fast, but a pain to maintain.

I added a 2nd column using GENERATED ALWAYS AS ... STORED. Same definition. Added an index, query performance back to where it was to start with. Oddly, EXPLAIN insists that it's using the index.

Each column has both a BRIN index and a BTREE. The BRIN index is used when the first column is used, the BTREE for the generated. Dropping the BTREE index on the generated index leads to a table scan.

Reindexed the table, still nothing.

What am I missing? I assume I'm not understanding something to do with generated columns.

Editing following comments: Query:

SELECT org."organisation", app."start", app."end", cr."forename", cr."surname", cl."forename", cl."surname", app."identifier", cr."region", csf."invoicedminutes", csf."invoice", csf."payment", csf."mileage", cr."identifier", cl."identifier", cs."shadow", cr."regions", csf."appointmentid", ct."caregroup", ct."caretype", app."cancelled", app."invoiceAdjustment", app."timesheetAdjustment"
 FROM   "v_orgname" org 
 INNER JOIN "v_appointment" app ON org."orgname"=app."orgname" 
 INNER JOIN "v_careslot_finance2" csf ON app."orgname"=csf."orgname" AND app."identifier"=csf."appointmentid" 
 LEFT OUTER JOIN "v_caretype" ct ON app."careTypeName"=ct."caretype" 
 INNER JOIN "v_client" cl ON csf."orgname"=cl."orgname" AND csf."client"=cl."identifier" 
 INNER JOIN "v_carer" cr ON csf."orgname"=cr."orgname" AND csf."carer"=cr."identifier" 
 INNER JOIN "v_care_slot" cs ON csf."orgname"=cs."orgname" AND csf."careslot"=cs."carerSlotEntity"
 WHERE  ((ct."caregroup" IS  NULL ) OR (ct."caregroup"='care')) AND cs."shadow"='0' AND cl."surname"<>'team' AND (app."start">='2022-09-01 00:00:00'::timestamp AND app."start"< '2022-10-01 00:00:00'::timestamp)

Indexes on the timestamps:

CREATE INDEX IF NOT EXISTS ix_brin_realstart
    ON public.appointment USING brin
    (realstart)
    TABLESPACE pg_default;

CREATE INDEX IF NOT EXISTS ix_brin_realstart2
    ON public.appointment USING brin
    (realstart2)
    TABLESPACE pg_default;

CREATE INDEX IF NOT EXISTS ix_realend
    ON public.appointment USING btree
    (realend ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX IF NOT EXISTS ix_realend2
    ON public.appointment USING btree
    (realend2 ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX IF NOT EXISTS ix_realstart
    ON public.appointment USING btree
    (realstart ASC NULLS LAST)
    TABLESPACE pg_default;

CREATE INDEX IF NOT EXISTS ix_realstart2
    ON public.appointment USING btree
    (realstart2 ASC NULLS LAST)
    TABLESPACE pg_default;

The generated timestamp columns:

   realstart timestamp with time zone, --Populated using UPDATE and same calc as below
    realend timestamp with time zone,
    realstart2 timestamp with time zone GENERATED ALWAYS AS (timezone('UTC'::text, start)) STORED,
    realend2 timestamp with time zone GENERATED ALWAYS AS (timezone('UTC'::text, "end")) STORED,

The view is edited to return either realstart or realstart2.

Query plan with realstart (the one that works quickly):

'Nested Loop  (cost=1770.12..61589.21 rows=1 width=934) (actual time=1137.045..60216.711 rows=103114 loops=1)'
'  Join Filter: (((orgname.orgname)::text = (carer.orgname)::text) AND ((v_careslot_finance.carer)::text = (carer.identifier)::text))'
'  Rows Removed by Join Filter: 290749910'
'  Buffers: shared hit=1304142'
'  ->  Hash Left Join  (cost=726.80..940.83 rows=2744 width=123) (actual time=3.314..33.042 rows=2744 loops=1)'
'        Hash Cond: (((carer.orgname)::text = (m_v_carer_phone_numbers_2.orgname)::text) AND ((carer.identifier)::text = (m_v_carer_phone_numbers_2.identifier)::text))'
'        Buffers: shared hit=617'
'        ->  Hash Left Join  (cost=600.39..771.93 rows=2744 width=123) (actual time=2.886..26.981 rows=2744 loops=1)'
'              Hash Cond: (((carer.orgname)::text = (m_v_carer_phone_numbers_1.orgname)::text) AND ((carer.identifier)::text = (m_v_carer_phone_numbers_1.identifier)::text))'
'              Buffers: shared hit=547'
'              ->  Hash Right Join  (cost=475.60..604.86 rows=2744 width=123) (actual time=2.369..21.191 rows=2744 loops=1)'
'                    Hash Cond: (((m_v_carer_phone_numbers.orgname)::text = (carer.orgname)::text) AND ((m_v_carer_phone_numbers.identifier)::text = (carer.identifier)::text))'
'                    Buffers: shared hit=477'
'                    ->  Seq Scan on m_v_carer_phone_numbers  (cost=0.00..116.31 rows=2467 width=46) (actual time=0.003..9.639 rows=2467 loops=1)'
'                          Filter: (phone_type = ''mobile_number''::text)'
'                          Rows Removed by Filter: 1238'
'                          Buffers: shared hit=70'
'                    ->  Hash  (cost=434.44..434.44 rows=2744 width=123) (actual time=2.344..2.346 rows=2744 loops=1)'
'                          Buckets: 4096  Batches: 1  Memory Usage: 451kB'
'                          Buffers: shared hit=407'
'                          ->  Seq Scan on carer  (cost=0.00..434.44 rows=2744 width=123) (actual time=0.005..1.583 rows=2744 loops=1)'
'                                Buffers: shared hit=407'
'              ->  Hash  (cost=116.31..116.31 rows=565 width=46) (actual time=0.514..0.514 rows=565 loops=1)'
'                    Buckets: 1024  Batches: 1  Memory Usage: 52kB'
'                    Buffers: shared hit=70'
'                    ->  Seq Scan on m_v_carer_phone_numbers m_v_carer_phone_numbers_1  (cost=0.00..116.31 rows=565 width=46) (actual time=0.002..0.412 rows=565 loops=1)'
'                          Filter: (phone_type = ''landline_number''::text)'
'                          Rows Removed by Filter: 3140'
'                          Buffers: shared hit=70'
'        ->  Hash  (cost=116.31..116.31 rows=673 width=46) (actual time=0.422..0.423 rows=673 loops=1)'
'              Buckets: 1024  Batches: 1  Memory Usage: 59kB'
'              Buffers: shared hit=70'
'              ->  Seq Scan on m_v_carer_phone_numbers m_v_carer_phone_numbers_2  (cost=0.00..116.31 rows=673 width=46) (actual time=0.001..0.306 rows=673 loops=1)'
'                    Filter: (phone_type = ''personal_phone_number''::text)'
'                    Rows Removed by Filter: 3032'
'                    Buffers: shared hit=70'
'  ->  Materialize  (cost=1043.33..60408.26 rows=5 width=864) (actual time=0.002..5.081 rows=105996 loops=2744)'
'        Buffers: shared hit=1303525'
'        ->  Nested Loop  (cost=1043.33..60408.24 rows=5 width=864) (actual time=3.624..1167.405 rows=105996 loops=1)'
'              Join Filter: ((orgname.orgname)::text = ("carerSlot".orgname)::text)'
'              Buffers: shared hit=1303525'
'              ->  Nested Loop  (cost=1042.77..60378.80 rows=36 width=891) (actual time=3.607..661.943 rows=107033 loops=1)'
'                    Join Filter: ((appointment.orgname)::text = (orgname.orgname)::text)'
'                    Rows Removed by Join Filter: 642198'
'                    Buffers: shared hit=768360'
'                    ->  Index Scan using orgname_pkey on orgname  (cost=0.13..12.24 rows=7 width=476) (actual time=0.007..0.013 rows=7 loops=1)'
'                          Buffers: shared hit=2'
'                    ->  Materialize  (cost=1042.64..60360.82 rows=56 width=415) (actual time=0.365..79.038 rows=107033 loops=7)'
'                          Buffers: shared hit=768358'
'                          ->  Gather  (cost=1042.64..60360.54 rows=56 width=415) (actual time=2.547..458.169 rows=107033 loops=1)'
'                                Workers Planned: 2'
'                                Workers Launched: 2'
'                                Buffers: shared hit=768358'
'                                ->  Nested Loop  (cost=42.64..59354.94 rows=23 width=415) (actual time=0.886..522.738 rows=35678 loops=3)'
'                                      Join Filter: ((appointment.orgname)::text = (client.orgname)::text)'
'                                      Buffers: shared hit=768358'
'                                      ->  Nested Loop  (cost=42.36..59310.63 rows=139 width=391) (actual time=0.870..367.685 rows=35678 loops=3)'
'                                            Buffers: shared hit=447257'
'                                            ->  Hash Left Join  (cost=41.80..57181.56 rows=585 width=204) (actual time=0.824..32.449 rows=28097 loops=3)'
'                                                  Hash Cond: ((appointment."careTypeName")::text = (caretype.caretype)::text)'
'                                                  Filter: ((((COALESCE(caretype.caregroup, ''care''::character varying))::character varying(50)) IS NULL) OR ((((COALESCE(caretype.caregroup, ''care''::character varying))::character varying(50)))::text = ''care''::text))'
'                                                  Rows Removed by Filter: 542'
'                                                  Buffers: shared hit=3054'
'                                                  ->  Parallel Bitmap Heap Scan on appointment  (cost=38.65..57080.55 rows=35309 width=77) (actual time=0.674..18.763 rows=28639 loops=3)'
'                                                        Recheck Cond: ((realstart >= ''2022-09-01 00:00:00''::timestamp without time zone) AND (realstart < ''2022-10-01 00:00:00''::timestamp without time zone))'
'                                                        Rows Removed by Index Recheck: 1312'
'                                                        Heap Blocks: lossy=1138'
'                                                        Buffers: shared hit=2947'
'                                                        ->  Bitmap Index Scan on ix_brin_realstart  (cost=0.00..17.47 rows=178223 width=0) (actual time=0.405..0.406 rows=29440 loops=1)'
'                                                              Index Cond: ((realstart >= ''2022-09-01 00:00:00''::timestamp without time zone) AND (realstart < ''2022-10-01 00:00:00''::timestamp without time zone))'
'                                                              Buffers: shared hit=3'
'                                                  ->  Hash  (cost=2.08..2.08 rows=86 width=133) (actual time=0.046..0.046 rows=86 loops=3)'
'                                                        Buckets: 1024  Batches: 1  Memory Usage: 13kB'
'                                                        Buffers: shared hit=3'
'                                                        ->  Seq Scan on caretype  (cost=0.00..2.08 rows=86 width=133) (actual time=0.013..0.024 rows=86 loops=3)'
'                                                              Buffers: shared hit=3'
'                                            ->  Index Scan using ix_org_app_finance on v_careslot_finance  (cost=0.56..3.63 rows=1 width=187) (actual time=0.010..0.011 rows=1 loops=84292)'
'                                                  Index Cond: (((orgname)::text = (appointment.orgname)::text) AND ((appointmentid)::text = (appointment.identifier)::text))'
'                                                  Buffers: shared hit=444203'
'                                      ->  Index Scan using ix_org_client on client  (cost=0.28..0.31 rows=1 width=61) (actual time=0.004..0.004 rows=1 loops=107033)'
'                                            Index Cond: (((orgname)::text = (v_careslot_finance.orgname)::text) AND ((identifier)::text = (v_careslot_finance.client)::text))'
'                                            Filter: ((surname)::text <> ''team''::text)'
'                                            Buffers: shared hit=321101'
'              ->  Index Scan using ix_care_slot_entity on "carerSlot"  (cost=0.56..0.81 rows=1 width=47) (actual time=0.004..0.004 rows=1 loops=107033)'
'                    Index Cond: (("carerSlotEntity")::text = (v_careslot_finance.careslot)::text)'
'                    Filter: ((NOT shadow) AND ((v_careslot_finance.orgname)::text = (orgname)::text))'
'                    Rows Removed by Filter: 0'
'                    Buffers: shared hit=535165'
'Planning:'
'  Buffers: shared hit=62'
'Planning Time: 4.223 ms'
'Execution Time: 60229.758 ms'

Query plan with realstart2 (slow one):

'Nested Loop  (cost=731.77..33869.85 rows=1 width=934) (actual time=4.172..239971.871 rows=103114 loops=1)'
'  Join Filter: (((orgname.orgname)::text = (carer.orgname)::text) AND ((v_careslot_finance.carer)::text = (carer.identifier)::text))'
'  Rows Removed by Join Filter: 290749910'
'  Buffers: shared hit=8723641'
'  ->  Nested Loop  (cost=4.97..32887.83 rows=1 width=864) (actual time=0.091..2514.977 rows=105996 loops=1)'
'        Join Filter: ((orgname.orgname)::text = ("carerSlot".orgname)::text)'
'        Buffers: shared hit=1303374'
'        ->  Nested Loop  (cost=4.42..32884.56 rows=4 width=891) (actual time=0.083..1793.299 rows=107033 loops=1)'
'              Join Filter: ((orgname.orgname)::text = (client.orgname)::text)'
'              Buffers: shared hit=768209'
'              ->  Nested Loop  (cost=4.13..32876.59 rows=25 width=867) (actual time=0.076..1244.741 rows=107033 loops=1)'
'                    Join Filter: ((appointment.orgname)::text = (orgname.orgname)::text)'
'                    Rows Removed by Join Filter: 301180'
'                    Buffers: shared hit=447110'
'                    ->  Nested Loop  (cost=4.13..32872.43 rows=33 width=391) (actual time=0.069..1147.582 rows=107033 loops=1)'
'                          Buffers: shared hit=447109'
'                          ->  Hash Left Join  (cost=3.58..31821.02 rows=141 width=204) (actual time=0.054..127.125 rows=84292 loops=1)'
'                                Hash Cond: ((appointment."careTypeName")::text = (caretype.caretype)::text)'
'                                Filter: ((((COALESCE(caretype.caregroup, ''care''::character varying))::character varying(50)) IS NULL) OR ((((COALESCE(caretype.caregroup, ''care''::character varying))::character varying(50)))::text = ''care''::text))'
'                                Rows Removed by Filter: 1625'
'                                Buffers: shared hit=2908'
'                                ->  Index Scan using ix_realstart2 on appointment  (cost=0.43..31794.33 rows=8495 width=77) (actual time=0.020..41.985 rows=85917 loops=1)'
'                                      Index Cond: ((realstart2 >= ''2022-09-01 00:00:00''::timestamp without time zone) AND (realstart2 < ''2022-10-01 00:00:00''::timestamp without time zone))'
'                                      Buffers: shared hit=2907'
'                                ->  Hash  (cost=2.08..2.08 rows=86 width=133) (actual time=0.029..0.030 rows=86 loops=1)'
'                                      Buckets: 1024  Batches: 1  Memory Usage: 13kB'
'                                      Buffers: shared hit=1'
'                                      ->  Seq Scan on caretype  (cost=0.00..2.08 rows=86 width=133) (actual time=0.007..0.015 rows=86 loops=1)'
'                                            Buffers: shared hit=1'
'                          ->  Index Scan using ix_org_app_finance on v_careslot_finance  (cost=0.56..7.45 rows=1 width=187) (actual time=0.010..0.011 rows=1 loops=84292)'
'                                Index Cond: (((orgname)::text = (appointment.orgname)::text) AND ((appointmentid)::text = (appointment.identifier)::text))'
'                                Buffers: shared hit=444201'
'                    ->  Materialize  (cost=0.00..1.10 rows=7 width=476) (actual time=0.000..0.000 rows=4 loops=107033)'
'                          Buffers: shared hit=1'
'                          ->  Seq Scan on orgname  (cost=0.00..1.07 rows=7 width=476) (actual time=0.002..0.003 rows=7 loops=1)'
'                                Buffers: shared hit=1'
'              ->  Index Scan using ix_org_client on client  (cost=0.28..0.31 rows=1 width=61) (actual time=0.004..0.004 rows=1 loops=107033)'
'                    Index Cond: (((orgname)::text = (v_careslot_finance.orgname)::text) AND ((identifier)::text = (v_careslot_finance.client)::text))'
'                    Filter: ((surname)::text <> ''team''::text)'
'                    Buffers: shared hit=321099'
'        ->  Index Scan using ix_care_slot_entity on "carerSlot"  (cost=0.56..0.81 rows=1 width=47) (actual time=0.006..0.006 rows=1 loops=107033)'
'              Index Cond: (("carerSlotEntity")::text = (v_careslot_finance.careslot)::text)'
'              Filter: ((NOT shadow) AND ((v_careslot_finance.orgname)::text = (orgname)::text))'
'              Rows Removed by Filter: 0'
'              Buffers: shared hit=535165'
'  ->  Hash Left Join  (cost=726.80..940.83 rows=2744 width=123) (actual time=0.002..2.055 rows=2744 loops=105996)'
'        Hash Cond: (((carer.orgname)::text = (m_v_carer_phone_numbers_2.orgname)::text) AND ((carer.identifier)::text = (m_v_carer_phone_numbers_2.identifier)::text))'
'        Buffers: shared hit=7420267'
'        ->  Hash Left Join  (cost=600.39..771.93 rows=2744 width=123) (actual time=0.001..1.582 rows=2744 loops=105996)'
'              Hash Cond: (((carer.orgname)::text = (m_v_carer_phone_numbers_1.orgname)::text) AND ((carer.identifier)::text = (m_v_carer_phone_numbers_1.identifier)::text))'
'              Buffers: shared hit=7420197'
'              ->  Hash Right Join  (cost=475.60..604.86 rows=2744 width=123) (actual time=0.001..1.070 rows=2744 loops=105996)'
'                    Hash Cond: (((m_v_carer_phone_numbers.orgname)::text = (carer.orgname)::text) AND ((m_v_carer_phone_numbers.identifier)::text = (carer.identifier)::text))'
'                    Buffers: shared hit=7420127'
'                    ->  Seq Scan on m_v_carer_phone_numbers  (cost=0.00..116.31 rows=2467 width=46) (actual time=0.001..0.376 rows=2467 loops=105996)'
'                          Filter: (phone_type = ''mobile_number''::text)'
'                          Rows Removed by Filter: 1238'
'                          Buffers: shared hit=7419720'
'                    ->  Hash  (cost=434.44..434.44 rows=2744 width=123) (actual time=2.306..2.307 rows=2744 loops=1)'
'                          Buckets: 4096  Batches: 1  Memory Usage: 451kB'
'                          Buffers: shared hit=407'
'                          ->  Seq Scan on carer  (cost=0.00..434.44 rows=2744 width=123) (actual time=0.002..1.666 rows=2744 loops=1)'
'                                Buffers: shared hit=407'
'              ->  Hash  (cost=116.31..116.31 rows=565 width=46) (actual time=0.480..0.481 rows=565 loops=1)'
'                    Buckets: 1024  Batches: 1  Memory Usage: 52kB'
'                    Buffers: shared hit=70'
'                    ->  Seq Scan on m_v_carer_phone_numbers m_v_carer_phone_numbers_1  (cost=0.00..116.31 rows=565 width=46) (actual time=0.002..0.394 rows=565 loops=1)'
'                          Filter: (phone_type = ''landline_number''::text)'
'                          Rows Removed by Filter: 3140'
'                          Buffers: shared hit=70'
'        ->  Hash  (cost=116.31..116.31 rows=673 width=46) (actual time=0.414..0.415 rows=673 loops=1)'
'              Buckets: 1024  Batches: 1  Memory Usage: 59kB'
'              Buffers: shared hit=70'
'              ->  Seq Scan on m_v_carer_phone_numbers m_v_carer_phone_numbers_2  (cost=0.00..116.31 rows=673 width=46) (actual time=0.001..0.313 rows=673 loops=1)'
'                    Filter: (phone_type = ''personal_phone_number''::text)'
'                    Rows Removed by Filter: 3032'
'                    Buffers: shared hit=70'
'Planning:'
'  Buffers: shared hit=62'
'Planning Time: 4.046 ms'
'Execution Time: 239982.455 ms'

Many thanks for taking a look.


Solution

  • Looks like I was barking up the wrong tree.

    My v_carer has a left join to another table. For some odd reason, even if I don't select those extra columns, it still does the joins. I don't understand why it would be different, I'll post another question relating to it.