3

I have a query for which the explain plan indicates that the cost for using a seq scan is lower than the cost for using an index that I have set up. However the actual time for the query is 20 times higher when using a seq scan than when using the index.

As expected, postgres chooses the seq scan because of the cost calculations. I can get postgres to use the index if I set the random_page_cost to a value below the seq_page_cost, but I've read that this isn't recommended.

Any thoughts/recommendations on getting the cost to more closely reflect reality? I've pasted the query and explain plans with enable_seqscan turned on and off.

The query is

select count(distinct a.sxid) 
from entity_split_association esa 
inner join crm_entity ce on esa.crm_entity_id = ce.crm_entity_id 
inner join agreement a on esa.entity_split_id = a.entity_split_id 
inner join agreement_details ad on a.agreement_id = ad.agreement_id
where
ce.crm_entity_id='001190000032goiAAA'
and ce.tenant_cd='SX1'
and ad.agreement_state_id in (1, 2)
and ad.row_valid_to>='9999-12-31'

The explain analyze plan with enable_seqscan turned on is http://explain.depesz.com/s/RfE :

Aggregate  (cost=1897427.42..1897427.43 rows=1 width=20) (actual time=8790.232..8790.232 rows=1 loops=1)
->  Nested Loop  (cost=1670.74..1897300.69 rows=50692 width=20) (actual time=6.673..8775.254 rows=8028 loops=1)
  ->  Hash Join  (cost=1670.31..1423984.64 rows=57105 width=24) (actual time=6.644..8650.796 rows=8097 loops=1)
    Hash Cond: (a.entity_split_id = esa.entity_split_id)
    ->  Seq Scan on agreement a  (cost=0.00..403507.21 rows=19868021 width=32) (actual time=0.025..3678.511 rows=19867147 loops=1)
    ->  Hash  (cost=1660.96..1660.96 rows=748 width=4) (actual time=5.388..5.388 rows=876 loops=1)
      Buckets: 1024  Batches: 1  Memory Usage: 31kB
      ->  Nested Loop  (cost=22.64..1660.96 rows=748 width=4) (actual time=3.120..4.817 rows=876 loops=1)
        ->  Index Only Scan using crm_entity_tenant_cd_crm_entity_id_key on crm_entity ce  (cost=0.42..8.44 rows=1 width=11) (actual time=0.042..0.044 rows=1 loops=1)
            Index Cond: ((tenant_cd = 'SX1'::text) AND (crm_entity_id = '001190000032goiAAA'::text))
            Heap Fetches: 1
        ->  Bitmap Heap Scan on entity_split_association esa  (cost=22.22..1645.03 rows=748 width=15) (actual time=3.071..4.376 rows=876 loops=1)
            Recheck Cond: ((crm_entity_id)::text = '001190000032goiAAA'::text)
            ->  Bitmap Index Scan on entity_split_association_crm_ix  (cost=0.00..22.03 rows=748 width=0) (actual time=2.869..2.869 rows=876 loops=1)
                Index Cond: ((crm_entity_id)::text = '001190000032goiAAA'::text)
  ->  Index Scan using agreement_detail_agreement_idx on agreement_details ad  (cost=0.44..8.28 rows=1 width=4) (actual time=0.013..0.014 rows=1 loops=8097)
      Index Cond: (agreement_id = a.agreement_id)
      Filter: ((agreement_state_id = ANY ('{1,2}'::integer[])) AND (row_valid_to >= '9999-12-31 00:00:00'::timestamp without time zone))
      Rows Removed by Filter: 0
Total runtime: 8790.386 ms

The explain analyze plan with enable_seqscan turned off is http://explain.depesz.com/s/ej8J:

Aggregate  (cost=2953411.58..2953411.59 rows=1 width=20) (actual time=411.253..411.253 rows=1 loops=1)
->  Nested Loop  (cost=20.30..2953284.85 rows=50692 width=20) (actual time=0.587..397.750 rows=8028 loops=1)
  ->  Nested Loop  (cost=19.87..2479968.81 rows=57105 width=24) (actual time=0.557..278.758 rows=8097 loops=1)
    ->  Nested Loop  (cost=0.84..16814.03 rows=748 width=4) (actual time=0.510..211.393 rows=876 loops=1)
      ->  Index Scan using entity_split_association_es_ix on entity_split_association esa  (cost=0.42..16796.24 rows=748 width=15) (actual time=0.466..210.423 rows=876 loops=1)
          Filter: ((crm_entity_id)::text = '001190000032goiAAA'::text)
          Rows Removed by Filter: 392140
      ->  Materialize  (cost=0.42..8.45 rows=1 width=11) (actual time=0.000..0.000 rows=1 loops=876)
        ->  Index Only Scan using crm_entity_tenant_cd_crm_entity_id_key on crm_entity ce  (cost=0.42..8.44 rows=1 width=11) (actual time=0.038..0.039 rows=1 loops=1)
            Index Cond: ((tenant_cd = 'SX1'::text) AND (crm_entity_id = '001190000032goiAAA'::text))
            Heap Fetches: 1
    ->  Bitmap Heap Scan on agreement a  (cost=19.02..3284.24 rows=875 width=32) (actual time=0.022..0.070 rows=9 loops=876)
        Recheck Cond: (entity_split_id = esa.entity_split_id)
        ->  Bitmap Index Scan on agreement_entity_split_idx  (cost=0.00..18.80 rows=875 width=0) (actual time=0.014..0.014 rows=9 loops=876)
            Index Cond: (entity_split_id = esa.entity_split_id)
  ->  Index Scan using agreement_detail_agreement_idx on agreement_details ad  (cost=0.44..8.28 rows=1 width=4) (actual time=0.013..0.014 rows=1 loops=8097)
      Index Cond: (agreement_id = a.agreement_id)
      Filter: ((agreement_state_id = ANY ('{1,2}'::integer[])) AND (row_valid_to >= '9999-12-31 00:00:00'::timestamp without time zone))
      Rows Removed by Filter: 0
Total runtime: 411.380 ms

Added the following as per hans (note that I don't have 10 reputation, so I can't post additional links to the nice depesz site):

With costs=true, analyze=true, buffers=true and seq_page_cost=1, random_page_cost=4, the explain plan is

Aggregate  (cost=1997007.48..1997007.49 rows=1 width=20) (actual time=11552.800..11552.801 rows=1 loops=1)
  Buffers: shared hit=26269 read=211706
  ->  Nested Loop  (cost=2056.70..1996835.11 rows=68948 width=20) (actual time=7.709..11536.616 rows=8022 loops=1)
      Buffers: shared hit=26269 read=211706
      ->  Hash Join  (cost=2056.26..1424678.99 rows=68948 width=28) (actual time=7.671..11393.632 rows=8093 loops=1)
          Hash Cond: (a.entity_split_id = esa.entity_split_id)
          Buffers: shared hit=1707 read=203906
          ->  Seq Scan on agreement a  (cost=0.00..403613.53 rows=19869653 width=36) (actual time=0.434..5772.481 rows=19799986 loops=1)
              Buffers: shared hit=1704 read=203213
          ->  Hash  (cost=2045.12..2045.12 rows=891 width=8) (actual time=6.526..6.526 rows=876 loops=1)
              Buckets: 1024  Batches: 1  Memory Usage: 35kB
              Buffers: shared hit=3 read=693
              ->  Nested Loop  (cost=27.75..2045.12 rows=891 width=8) (actual time=0.488..6.017 rows=876 loops=1)
                  Buffers: shared hit=3 read=693
                  ->  Index Only Scan using crm_entity_tenant_cd_crm_entity_id_key on crm_entity ce  (cost=0.42..8.44 rows=1 width=11) (actual time=0.036..0.039 rows=1 loops=1)
                      Index Cond: ((tenant_cd = 'SX1'::text) AND (crm_entity_id = '001190000032goiAAA'::text))
                      Heap Fetches: 1
                      Buffers: shared hit=2 read=2
                  ->  Bitmap Heap Scan on entity_split_association esa  (cost=27.33..2027.77 rows=891 width=19) (actual time=0.448..5.537 rows=876 loops=1)
                      Recheck Cond: ((crm_entity_id)::text = '001190000032goiAAA'::text)
                      Buffers: shared hit=1 read=691
                      ->  Bitmap Index Scan on entity_split_association_crm_ix  (cost=0.00..27.11 rows=891 width=0) (actual time=0.330..0.330 rows=876 loops=1)
                          Index Cond: ((crm_entity_id)::text = '001190000032goiAAA'::text)
                          Buffers: shared read=10
      ->  Index Scan using agreement_detail_agreement_idx on agreement_details ad  (cost=0.44..8.29 rows=1 width=8) (actual time=0.015..0.016 rows=1 loops=8093)
          Index Cond: (agreement_id = a.agreement_id)
          Filter: ((agreement_state_id = ANY ('{1,2}'::integer[])) AND (row_valid_to >= '9999-12-31 00:00:00'::timestamp without time zone))
          Buffers: shared hit=24562 read=7800

Total runtime: 11552.923 ms

With costs=true, analyze=true, buffers=true and seq_page_cost=1, random_page_cost=0.5, the explain plan is

Aggregate  (cost=511126.64..511126.65 rows=1 width=20) (actual time=215.661..215.662 rows=1 loops=1)
Buffers: shared hit=23988 read=19763 written=1291
->  Nested Loop  (cost=1.72..510954.27 rows=68948 width=20) (actual time=0.220..202.242 rows=8022 loops=1)
    Buffers: shared hit=23988 read=19763 written=1291
    ->  Nested Loop  (cost=1.28..410929.06 rows=68948 width=28) (actual time=0.197..73.651 rows=8093 loops=1)
        Buffers: shared hit=1967 read=9422 written=700
        ->  Nested Loop  (cost=0.84..464.20 rows=891 width=8) (actual time=0.079..6.825 rows=876 loops=1)
            Buffers: shared hit=8 read=694 written=140
            ->  Index Only Scan using crm_entity_tenant_cd_crm_entity_id_key on crm_entity ce  (cost=0.42..1.44 rows=1 width=11) (actual time=0.043..0.044 rows=1 loops=1)
                Index Cond: ((tenant_cd = 'SX1'::text) AND (crm_entity_id = '001190000032goiAAA'::text))
                Heap Fetches: 1
                Buffers: shared hit=1 read=3
            ->  Index Scan using entity_split_association_crm_ix on entity_split_association esa  (cost=0.42..453.85 rows=891 width=19) (actual time=0.033..6.313 rows=876 loops=1)
                Index Cond: ((crm_entity_id)::text = '001190000032goiAAA'::text)
                Buffers: shared hit=7 read=691 written=140
        ->  Index Scan using agreement_entity_split_idx on agreement a  (cost=0.44..451.85 rows=883 width=36) (actual time=0.020..0.071 rows=9 loops=876)
            Index Cond: (entity_split_id = esa.entity_split_id)
            Buffers: shared hit=1959 read=8728 written=560
    ->  Index Scan using agreement_detail_agreement_idx on agreement_details ad  (cost=0.44..1.44 rows=1 width=8) (actual time=0.014..0.015 rows=1 loops=8093)
        Index Cond: (agreement_id = a.agreement_id)
        Filter: ((agreement_state_id = ANY ('{1,2}'::integer[])) AND (row_valid_to >= '9999-12-31 00:00:00'::timestamp without time zone))
        Buffers: shared hit=22021 read=10341 written=591

Total runtime: 215.761 ms

  • What're the current values of seq_page_cost and random_page_cost? Also, PostgreSQL version? Show SELECT version(). – Craig Ringer Oct 8 '14 at 23:54
  • Rowcount estimates look sane, within an order of magnitude. No one node is an obvious cost center, either. Interesting. I'm somewhat surprised that the second plan with three nested loops is faster, actually. – Craig Ringer Oct 8 '14 at 23:57
  • @CraigRinger I was using the defaults for seq_page_cost (1) and random_page_cost (4). In order to get postgres to use the index, I had to set the random_page_cost=0.5 which I know is not recommended. Version is PostgreSQL 9.3.4 on x86_64-apple-darwin, compiled by i686-apple-darwin11-llvm-gcc-4.2 (GCC) 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.9.00), 64-bit. – Jay Oct 22 '14 at 22:22
  • there is also one more important thing: run explain like this: explain (costs true, analyze true, buffers true) SELECT ... maybe it is related to caching behavior or so. can you post that as well? many thanks, hans – Hans-Jürgen Schönig Oct 27 '14 at 12:46
  • Added the explain plan with buffers true as you suggested – Jay Oct 28 '14 at 15:59

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.