Servers: Redhack 6.9 64 bit.
Postgres OLD Server version 9.5.6
Postgres New Server 9.6.6
Issues BIG difference in speed on the following SQL statement from 9.5 to 9.6 ...
EXPLAIN ANALYZE
select de_caseid, de_seqno, de_document_num, doc_link.dm_id as dm_id,
doc_link.dm_seq as dm_seq, doc_link.dm_dls_id as dm_dls_id,
doc_link.dm_restrict_view as dm_restrict_view, document_v.dm_type as dm_type,
document_v.dm_id as accessable
from dktentry left outer join doc_link on de_doc_id = doc_link.dm_id
left outer join document_v on doc_link.dm_id = document_v.dm_id
select de_caseid, de_seqno, de_document_num, doc_link.dm_id as dm_id,
doc_link.dm_seq as dm_seq, doc_link.dm_dls_id as dm_dls_id,
doc_link.dm_restrict_view as dm_restrict_view, document_v.dm_type as dm_type,
document_v.dm_id as accessable
from dktentry left outer join doc_link on de_doc_id = doc_link.dm_id
left outer join document_v on doc_link.dm_id = document_v.dm_id
and doc_link.dm_seq = document_v.dm_seq where de_caseid in (800)
;
;
Number of rows in table dktentry:
psql -x -c "select count(*) from dktentry;"
-[ RECORD 1 ]-
count | 376555
-[ RECORD 1 ]-
count | 376555
Number of Rows in table document_v:
psql -x -c "select count(*) from document_v;"
-[ RECORD 1 ]-
count | 931306
-[ RECORD 1 ]-
count | 931306
Number of rows in table doc_link:
psql -x -c "select count(*) from doc_link;"
-[ RECORD 1 ]--
count | 1329305
-[ RECORD 1 ]--
count | 1329305
We are migrating our current 9.5 batch of Postgres servers to a new batch of Postgres 9.6 servers.
We have tried using both pd_dump and pg dumpall to move the files across.
However , when executing the above statement on the 9.5 version, we get the following:
************* 9.5 Postgres
[postgres@sudb114 admintools]$ psql -x -f docittest.sql
-[ RECORD 1 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Nested Loop Left Join (cost=1.28..355.98 rows=104 width=32) (actual time=4.017..4.684 rows=6 loops=1)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | -> Nested Loop Left Join (cost=0.85..310.53 rows=39 width=26) (actual time=0.134..0.283 rows=6 loops=1)
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | -> Index Scan using u_dktentry_pkey on u_dktentry x0 (cost=0.42..60.94 rows=20 width=16) (actual time=0.093..0.131 rows=5 loops=1)
-[ RECORD 4 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Index Cond: (de_caseid = 800)
-[ RECORD 5 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Filter: ((de_restrict_view = 0) OR (may_access_docket((de_restrict_view)::integer, de_caseid, de_seqno, 0, 0) <> 0))
-[ RECORD 6 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | -> Index Scan using u_document_pkey on u_document x0_1 (cost=0.43..12.46 rows=2 width=14) (actual time=0.028..0.029 rows=1 loops=5)
-[ RECORD 7 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Index Cond: (x0.de_doc_id = dm_id)
-[ RECORD 8 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | -> Index Scan using u_document_pkey on u_document x0_2 (cost=0.43..1.16 rows=1 width=10) (actual time=0 .732..0.732 rows=0 loops=6)
-[ RECORD 9 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Index Cond: ((x0_1.dm_id = dm_id) AND (x0_1.dm_seq = dm_seq))
-[ RECORD 10 ]---------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Filter: ((dm_restrict_view = 0) OR (may_access_doc((dm_restrict_view)::integer, dm_id, dm_seq, dm_t ype) <> 0))
-[ RECORD 11 ]---------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Rows Removed by Filter: 1
-[ RECORD 12 ]---------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Planning time: 1.579 ms
-[ RECORD 13 ]---------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Execution time: 4.797 ms
-[ RECORD 1 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Nested Loop Left Join (cost=1.28..355.98 rows=104 width=32) (actual time=4.017..4.684 rows=6 loops=1)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | -> Nested Loop Left Join (cost=0.85..310.53 rows=39 width=26) (actual time=0.134..0.283 rows=6 loops=1)
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | -> Index Scan using u_dktentry_pkey on u_dktentry x0 (cost=0.42..60.94 rows=20 width=16) (actual time=0.093..0.131 rows=5 loops=1)
-[ RECORD 4 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Index Cond: (de_caseid = 800)
-[ RECORD 5 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Filter: ((de_restrict_view = 0) OR (may_access_docket((de_restrict_view)::integer, de_caseid, de_seqno, 0, 0) <> 0))
-[ RECORD 6 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | -> Index Scan using u_document_pkey on u_document x0_1 (cost=0.43..12.46 rows=2 width=14) (actual time=0.028..0.029 rows=1 loops=5)
-[ RECORD 7 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Index Cond: (x0.de_doc_id = dm_id)
-[ RECORD 8 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | -> Index Scan using u_document_pkey on u_document x0_2 (cost=0.43..1.16 rows=1 width=10) (actual time=0 .732..0.732 rows=0 loops=6)
-[ RECORD 9 ]----------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Index Cond: ((x0_1.dm_id = dm_id) AND (x0_1.dm_seq = dm_seq))
-[ RECORD 10 ]---------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Filter: ((dm_restrict_view = 0) OR (may_access_doc((dm_restrict_view)::integer, dm_id, dm_seq, dm_t ype) <> 0))
-[ RECORD 11 ]---------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Rows Removed by Filter: 1
-[ RECORD 12 ]---------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Planning time: 1.579 ms
-[ RECORD 13 ]---------------------------------------------------------------------------------------------------------- ----------------------------------
QUERY PLAN | Execution time: 4.797 ms
Which is pretty quick on the 9.5
******************* 9.6 Version
On the 9.6 servers we get the following:
-[ RECORD 1 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Merge Left Join (cost=878831.70..8759238.40 rows=473192005 width=38) (actual time=15035.085..16338.751 rows=6 loops=1)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Merge Cond: (x0.de_doc_id = x0_1.dm_id)
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Sort (cost=4770.34..4775.72 rows=2153 width=16) (actual time=0.157..0.159 rows=5 loops=1)
-[ RECORD 4 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Key: x0.de_doc_id
-[ RECORD 5 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Method: quicksort Memory: 25kB
-[ RECORD 6 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Bitmap Heap Scan on u_dktentry x0 (cost=41.19..4651.15 rows=2153 width=16) (actual time=0.075..0.130 rows=5 loops=1)
-[ RECORD 7 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Recheck Cond: (de_caseid = 800)
-[ RECORD 8 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Filter: ((de_restrict_view = 0) OR (may_access_docket((de_restrict_view)::integer, de_caseid, de_seqno, 0, 0) <> 0))
-[ RECORD 9 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Heap Blocks: exact=4
-[ RECORD 10 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Bitmap Index Scan on u_dktentry_pkey (cost=0.00..40.65 rows=2164 width=0) (actual time=0.052..0.052 rows=5 loops=1)
-[ RECORD 11 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Index Cond: (de_caseid = 800)
-[ RECORD 12 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Materialize (cost=874061.36..1766468.42 rows=43956527 width=26) (actual time=15024.172..16223.201 rows=1182655 loops=1)
RECORD 13 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Merge Left Join (cost=874061.36..1656577.10 rows=43956527 width=26) (actual time=15024.165..15990.605 rows=1182655 loops=1)
-[ RECORD 14 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Merge Cond: ((x0_1.dm_id = x0_2.dm_id) AND (x0_1.dm_seq = x0_2.dm_seq))
-[ RECORD 15 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Sort (cost=266298.76..269622.02 rows=1329305 width=14) (actual time=1119.467..1344.975 rows=1182655 loops=1)
-[ RECORD 16 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Key: x0_1.dm_id, x0_1.dm_seq
-[ RECORD 17 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Method: external merge Disk: 31168kB
-[ RECORD 18 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Seq Scan on u_document x0_1 (cost=0.00..108375.05 rows=1329305 width=14) (actual time=0.015..550.634 rows=1329305 loops=1)
-[ RECORD 19 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Materialize (cost=607762.60..614376.06 rows=1322692 width=16) (actual time=13904.690..14203.239 rows=833199 loops=1)
-[ RECORD 20 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Sort (cost=607762.60..611069.33 rows=1322692 width=16) (actual time=13904.688..14097.990 rows=833199 loops=1)
-[ RECORD 21 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Key: x0_2.dm_id, x0_2.dm_seq
-[ RECORD 22 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Method: external merge Disk: 19168kB
-[ RECORD 23 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Seq Scan on u_document x0_2 (cost=0.00..450671.09 rows=1322692 width=16) (actual time=3.134..13444.415 rows=931306 loops=1)
QUERY PLAN | Merge Left Join (cost=878831.70..8759238.40 rows=473192005 width=38) (actual time=15035.085..16338.751 rows=6 loops=1)
-[ RECORD 2 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Merge Cond: (x0.de_doc_id = x0_1.dm_id)
-[ RECORD 3 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Sort (cost=4770.34..4775.72 rows=2153 width=16) (actual time=0.157..0.159 rows=5 loops=1)
-[ RECORD 4 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Key: x0.de_doc_id
-[ RECORD 5 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Method: quicksort Memory: 25kB
-[ RECORD 6 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Bitmap Heap Scan on u_dktentry x0 (cost=41.19..4651.15 rows=2153 width=16) (actual time=0.075..0.130 rows=5 loops=1)
-[ RECORD 7 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Recheck Cond: (de_caseid = 800)
-[ RECORD 8 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Filter: ((de_restrict_view = 0) OR (may_access_docket((de_restrict_view)::integer, de_caseid, de_seqno, 0, 0) <> 0))
-[ RECORD 9 ]----------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Heap Blocks: exact=4
-[ RECORD 10 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Bitmap Index Scan on u_dktentry_pkey (cost=0.00..40.65 rows=2164 width=0) (actual time=0.052..0.052 rows=5 loops=1)
-[ RECORD 11 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Index Cond: (de_caseid = 800)
-[ RECORD 12 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Materialize (cost=874061.36..1766468.42 rows=43956527 width=26) (actual time=15024.172..16223.201 rows=1182655 loops=1)
RECORD 13 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Merge Left Join (cost=874061.36..1656577.10 rows=43956527 width=26) (actual time=15024.165..15990.605 rows=1182655 loops=1)
-[ RECORD 14 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Merge Cond: ((x0_1.dm_id = x0_2.dm_id) AND (x0_1.dm_seq = x0_2.dm_seq))
-[ RECORD 15 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Sort (cost=266298.76..269622.02 rows=1329305 width=14) (actual time=1119.467..1344.975 rows=1182655 loops=1)
-[ RECORD 16 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Key: x0_1.dm_id, x0_1.dm_seq
-[ RECORD 17 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Method: external merge Disk: 31168kB
-[ RECORD 18 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Seq Scan on u_document x0_1 (cost=0.00..108375.05 rows=1329305 width=14) (actual time=0.015..550.634 rows=1329305 loops=1)
-[ RECORD 19 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Materialize (cost=607762.60..614376.06 rows=1322692 width=16) (actual time=13904.690..14203.239 rows=833199 loops=1)
-[ RECORD 20 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Sort (cost=607762.60..611069.33 rows=1322692 width=16) (actual time=13904.688..14097.990 rows=833199 loops=1)
-[ RECORD 21 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Key: x0_2.dm_id, x0_2.dm_seq
-[ RECORD 22 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Sort Method: external merge Disk: 19168kB
-[ RECORD 23 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | -> Seq Scan on u_document x0_2 (cost=0.00..450671.09 rows=1322692 width=16) (actual time=3.134..13444.415 rows=931306 loops=1)
-[ RECORD 24 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Filter: ((dm_restrict_view = 0) OR (may_access_doc((dm_restrict_view)::integer, dm_id, dm_seq, dm_type) <> 0))
-[ RECORD 25 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Rows Removed by Filter: 397999
-[ RECORD 26 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Planning time: 1.567 ms
-[ RECORD 27 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Execution time: 16347.890 ms
QUERY PLAN | Filter: ((dm_restrict_view = 0) OR (may_access_doc((dm_restrict_view)::integer, dm_id, dm_seq, dm_type) <> 0))
-[ RECORD 25 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Rows Removed by Filter: 397999
-[ RECORD 26 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Planning time: 1.567 ms
-[ RECORD 27 ]---------------------------------------------------------------------------------------------------------------------------------------------------------
QUERY PLAN | Execution time: 16347.890 ms
Can anyoen explain WHY there is such a big difference? Is it the SQL statement or a bug in the pgdump ?
Ben Duncan - Business Network Solutions, Inc. 336 Elton Road Jackson MS, 39212
"Never attribute to malice, that which can be adequately explained by stupidity"
- Hanlon's Razor
"Never attribute to malice, that which can be adequately explained by stupidity"
- Hanlon's Razor
