ANSI JOINS versus , like JOINS

Поиск
Список
Период
Сортировка
От Herwig Goemans
Тема ANSI JOINS versus , like JOINS
Дата
Msg-id CAKaDz_EVOgNE7NkBeP=VUpnz5KEBzNgujGcqCBRehP945nXhOw@mail.gmail.com
обсуждение исходный текст
Ответы Re: ANSI JOINS versus , like JOINS  (Tom Lane <tgl@sss.pgh.pa.us>)
Список pgsql-sql
Hello,


I have two queries, identical except for the way the tables are joined. One version is a mixture of ANSI joins and 'old' , like join syntax, this is the 'mixed' query The other version is a completely ANSI JOIN syntax query,I will call it the ANSI query from now on. 
We are running postgres 9.5, PostgreSQL 9.5.3 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-4), 64-bit on CentOS 7: CentOS Linux release 7.2.1511 (Core)
It was installed from repository:

yum install postgresql95-server postgresql95-contrib --enablerepo=pgdg95

I prefer very much ANSI joins, simply because they are more readable and less error prone (like forgetting a join condition). However, the queries are generated via a JAVA application and the application, unfortunately, sends the mixed query to the database.  
Full details are give below but the interesting thing about these queries is that the execution plan is not the same. The performance of the mixed query is much worse. On a cold system, the ANSI query returns results(approx 8 rows) in approx 2s and with caching in effect, in less than 300ms. However the mixed query takes 45s, sometimes we get at 15s and by rewriting a little bit we get at 3-4s.
The other interesting thing is that the execution plan of the mixed query changes when xts_service_process_activity and tables below are added to the join list. Without these tables, the execution plan of both queries is the same. 
In query below, id_helper is norrmally a temporary table. For debugging purposes I have made it a permanent table with relevant data. 
In attach create statements and other info. 
Is there anyone who can help so that the mixed query has the same or equivalent execution plan (performance) as the ansi query ?
Thank you. 
Herwig

The server:Centos 7
Linux diana.ix.xplanation.com 3.10.0-327.18.2.el7.x86_64 #1 SMP Thu May 12 11:03:55 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux
cat /proc/meminfo |grep MemTotal
MemTotal:        8011216 kB

This is the mixed query:
explain (analyze, buffers) 
select  sqlxtsjoba0_.ID as col_0_0_ 
from  TSTREAM.XTS_JOB_ACTIVITY sqlxtsjoba0_ 
inner join TSTREAM.XTS_ACT_IN_JOB xtsactinjo1_ on sqlxtsjoba0_.ID=xtsactinjo1_.XTJA_ID 
,  id_helper3 sqlidhelpe3_
, TSTREAM.XTS_JOB_PROCESS sqlxtsjobp4_ 
, TSTREAM.XTS_JOB sqlxtsjob5_ 
, TSTREAM.XTS_STATUS sqlxtsstat6_ 
, TSTREAM.XTS_STATUS sqlxtsstat7_ 
, TSTREAM.XTS_CUSTOMER_ACTIVITY sqlxtscust8_ 
, TSTREAM.XTS_SERVICE_PROCESS_ACTIVITY sqlxtsserv9_
, TSTREAM.XTS_PROCESS_ACTIVITY sqlxtsproc10_
, TSTREAM.XTS_ACTIVITY sqlxtsacti11_ 
where set_id = 0
and sqlxtsjoba0_.ID = sqlidhelpe3_.reference_ID
and sqlxtsstat6_.CODE='RUN'
and sqlxtsstat7_.CODE='RUN' 
and xtsactinjo1_.XTJP_ID=sqlxtsjobp4_.ID
and sqlxtsjobp4_.XTJO_ID=sqlxtsjob5_.ID
and sqlxtsjob5_.XPRS_ID=sqlxtsstat6_.ID 
and sqlxtsjoba0_.XPRS_ID=sqlxtsstat7_.ID
and sqlxtsjoba0_.XTCA_ID=sqlxtscust8_.ID
and sqlxtscust8_.XSPA_ID=sqlxtsserv9_.ID 
and sqlxtsserv9_.XPRA_ID=sqlxtsproc10_.ID 
and sqlxtsproc10_.XTAC_ID=sqlxtsacti11_.ID 
and sqlxtsacti11_.HANDLER='FinalDeliveryCheckHandlerSession'
order by 1;
And ii's plan:
"QUERY PLAN"
"Nested Loop  (cost=19764.93..1720710.10 rows=1 width=4) (actual time=49834.078..55288.833 rows=7 loops=1)"
"  Buffers: shared hit=520154 read=376691"
"  I/O Timings: read=4084.273"
"  ->  Nested Loop  (cost=19764.79..1720709.92 rows=1 width=12) (actual time=42345.312..55288.671 rows=17 loops=1)"
"        Buffers: shared hit=520120 read=376691"
"        I/O Timings: read=4084.273"
"        ->  Nested Loop  (cost=19764.36..1720709.36 rows=1 width=12) (actual time=42336.880..55236.649 rows=17 loops=1)"
"              Buffers: shared hit=520073 read=376670"
"              I/O Timings: read=4032.574"
"              ->  Nested Loop  (cost=19763.93..1720708.91 rows=1 width=12) (actual time=42323.227..55164.778 rows=17 loops=1)"
"                    Join Filter: (sqlxtsserv9_.id = sqlxtscust8_.xspa_id)"
"                    Rows Removed by Join Filter: 823"
"                    Buffers: shared hit=520025 read=376650"
"                    I/O Timings: read=3961.004"
"                    ->  Nested Loop  (cost=19762.19..1720701.77 rows=18 width=20) (actual time=42323.133..55152.950 rows=21 loops=1)"
"                          Buffers: shared hit=520016 read=376649"
"                          I/O Timings: read=3950.217"
"                          ->  Nested Loop  (cost=19761.76..1720693.58 rows=18 width=20) (actual time=42292.470..55029.761 rows=21 loops=1)"
"                                Join Filter: (sqlxtsjoba0_.xprs_id = sqlxtsstat7_.id)"
"                                Rows Removed by Join Filter: 1579"
"                                Buffers: shared hit=519951 read=376630"
"                                I/O Timings: read=3827.494"
"                                ->  Merge Join  (cost=19761.76..1720666.95 rows=392 width=28) (actual time=42292.368..55027.679 rows=400 loops=1)"
"                                      Merge Cond: (sqlxtsjoba0_.id = sqlidhelpe3_.reference_id)"
"                                      Buffers: shared hit=519949 read=376630"
"                                      I/O Timings: read=3827.494"
"                                      ->  Merge Join  (cost=9187.27..1671024.74 rows=19628192 width=36) (actual time=220.994..47852.677 rows=18610377 loops=1)"
"                                            Merge Cond: (sqlxtsjoba0_.id = xtsactinjo1_.xtja_id)"
"                                            Buffers: shared hit=519948 read=376624"
"                                            I/O Timings: read=3827.471"
"                                            ->  Index Scan using xts_job_activity_pkey on xts_job_activity sqlxtsjoba0_  (cost=0.44..744709.37 rows=17843875 width=20) (actual time=0.010..10119.665 rows=17079648 loops=1)"
"                                                  Buffers: shared hit=72557 read=250737"
"                                                  I/O Timings: read=1234.731"
"                                            ->  Index Scan using xaij_xtja on xts_act_in_job xtsactinjo1_  (cost=0.44..636358.07 rows=19628192 width=16) (actual time=0.008..12174.828 rows=18610377 loops=1)"
"                                                  Buffers: shared hit=447391 read=125887"
"                                                  I/O Timings: read=2592.740"
"                                      ->  Sort  (cost=565.85..566.74 rows=356 width=4) (actual time=0.450..0.658 rows=400 loops=1)"
"                                            Sort Key: sqlidhelpe3_.reference_id"
"                                            Sort Method: quicksort  Memory: 43kB"
"                                            Buffers: shared hit=1 read=6"
"                                            I/O Timings: read=0.023"
"                                            ->  Bitmap Heap Scan on id_helper3 sqlidhelpe3_  (cost=7.18..550.76 rows=356 width=4) (actual time=0.065..0.248 rows=400 loops=1)"
"                                                  Recheck Cond: (set_id = 0)"
"                                                  Heap Blocks: exact=4"
"                                                  Buffers: shared hit=1 read=6"
"                                                  I/O Timings: read=0.023"
"                                                  ->  Bitmap Index Scan on id_helper_set  (cost=0.00..7.09 rows=356 width=0) (actual time=0.054..0.054 rows=400 loops=1)"
"                                                        Index Cond: (set_id = 0)"
"                                                        Buffers: shared read=3"
"                                                        I/O Timings: read=0.013"
"                                ->  Materialize  (cost=0.00..3.12 rows=4 width=4) (actual time=0.001..0.002 rows=4 loops=400)"
"                                      Buffers: shared hit=2"
"                                      ->  Seq Scan on xts_status sqlxtsstat7_  (cost=0.00..3.10 rows=4 width=4) (actual time=0.020..0.037 rows=4 loops=1)"
"                                            Filter: ((code)::text = 'RUN'::text)"
"                                            Rows Removed by Filter: 84"
"                                            Buffers: shared hit=2"
"                          ->  Index Scan using xts_customer_activity_pkey on xts_customer_activity sqlxtscust8_  (cost=0.42..0.44 rows=1 width=12) (actual time=5.860..5.861 rows=1 loops=21)"
"                                Index Cond: (id = sqlxtsjoba0_.xtca_id)"
"                                Buffers: shared hit=65 read=19"
"                                I/O Timings: read=122.723"
"                    ->  Materialize  (cost=1.74..5.80 rows=5 width=4) (actual time=0.005..0.544 rows=40 loops=21)"
"                          Buffers: shared hit=9 read=1"
"                          I/O Timings: read=10.787"
"                          ->  Nested Loop  (cost=1.74..5.78 rows=5 width=4) (actual time=0.085..11.064 rows=40 loops=1)"
"                                Buffers: shared hit=9 read=1"
"                                I/O Timings: read=10.787"
"                                ->  Hash Join  (cost=1.60..4.97 rows=2 width=4) (actual time=0.070..0.161 rows=3 loops=1)"
"                                      Hash Cond: (sqlxtsproc10_.xtac_id = sqlxtsacti11_.id)"
"                                      Buffers: shared hit=3"
"                                      ->  Seq Scan on xts_process_activity sqlxtsproc10_  (cost=0.00..2.98 rows=98 width=12) (actual time=0.007..0.065 rows=98 loops=1)"
"                                            Buffers: shared hit=2"
"                                      ->  Hash  (cost=1.59..1.59 rows=1 width=4) (actual time=0.022..0.022 rows=1 loops=1)"
"                                            Buckets: 1024  Batches: 1  Memory Usage: 9kB"
"                                            Buffers: shared hit=1"
"                                            ->  Seq Scan on xts_activity sqlxtsacti11_  (cost=0.00..1.59 rows=1 width=4) (actual time=0.014..0.018 rows=1 loops=1)"
"                                                  Filter: ((handler)::text = 'FinalDeliveryCheckHandlerSession'::text)"
"                                                  Rows Removed by Filter: 46"
"                                                  Buffers: shared hit=1"
"                                ->  Index Scan using xspa_xpra on xts_service_process_activity sqlxtsserv9_  (cost=0.14..0.38 rows=2 width=12) (actual time=0.009..3.617 rows=13 loops=3)"
"                                      Index Cond: (xpra_id = sqlxtsproc10_.id)"
"                                      Buffers: shared hit=6 read=1"
"                                      I/O Timings: read=10.787"
"              ->  Index Scan using xts_job_process_pkey on xts_job_process sqlxtsjobp4_  (cost=0.43..0.45 rows=1 width=12) (actual time=4.223..4.224 rows=1 loops=17)"
"                    Index Cond: (id = xtsactinjo1_.xtjp_id)"
"                    Buffers: shared hit=48 read=20"
"                    I/O Timings: read=71.570"
"        ->  Index Scan using xts_job_pkey on xts_job sqlxtsjob5_  (cost=0.43..0.55 rows=1 width=12) (actual time=3.054..3.055 rows=1 loops=17)"
"              Index Cond: (id = sqlxtsjobp4_.xtjo_id)"
"              Buffers: shared hit=47 read=21"
"              I/O Timings: read=51.699"
"  ->  Index Scan using xts_status_pkey on xts_status sqlxtsstat6_  (cost=0.14..0.16 rows=1 width=4) (actual time=0.006..0.007 rows=0 loops=17)"
"        Index Cond: (id = sqlxtsjob5_.xprs_id)"
"        Filter: ((code)::text = 'RUN'::text)"
"        Rows Removed by Filter: 1"
"        Buffers: shared hit=34"
"Planning time: 7.273 ms"
"Execution time: 55288.986 ms"


Then the ANSI Query:
explain (analyze, buffers) select sqlxtsjoba0_.ID as col_0_0_ 
  from TSTREAM.XTS_JOB_ACTIVITY sqlxtsjoba0_ 
inner join TSTREAM.XTS_ACT_IN_JOB xtsactinjo1_ on sqlxtsjoba0_.ID=xtsactinjo1_.XTJA_ID 
join id_helper3 sqlidhelpe3_ on sqlxtsjoba0_.ID = sqlidhelpe3_.reference_ID and set_id = 0
join TSTREAM.XTS_JOB_PROCESS sqlxtsjobp4_ on xtsactinjo1_.XTJP_ID=sqlxtsjobp4_.ID
join TSTREAM.XTS_JOB sqlxtsjob5_ on sqlxtsjobp4_.XTJO_ID=sqlxtsjob5_.ID
join TSTREAM.XTS_STATUS sqlxtsstat6_ on sqlxtsjob5_.XPRS_ID=sqlxtsstat6_.ID 
join TSTREAM.XTS_STATUS sqlxtsstat7_ on sqlxtsjoba0_.XPRS_ID=sqlxtsstat7_.ID
join TSTREAM.XTS_CUSTOMER_ACTIVITY sqlxtscust8_ on sqlxtsjoba0_.XTCA_ID=sqlxtscust8_.ID
join TSTREAM.XTS_SERVICE_PROCESS_ACTIVITY sqlxtsserv9_ on sqlxtscust8_.XSPA_ID=sqlxtsserv9_.ID 
join TSTREAM.XTS_PROCESS_ACTIVITY sqlxtsproc10_ on sqlxtsserv9_.XPRA_ID=sqlxtsproc10_.ID 
join TSTREAM.XTS_ACTIVITY sqlxtsacti11_ on sqlxtsproc10_.XTAC_ID=sqlxtsacti11_.ID 
where sqlxtsstat6_.CODE='RUN'
  and sqlxtsstat7_.CODE='RUN' 
  and sqlxtsacti11_.HANDLER='FinalDeliveryCheckHandlerSession'
order by 1;


"QUERY PLAN"
"Sort  (cost=3630.62..3630.63 rows=1 width=4) (actual time=7.467..7.470 rows=7 loops=1)"
"  Sort Key: sqlxtsjoba0_.id"
"  Sort Method: quicksort  Memory: 25kB"
"  Buffers: shared hit=1965"
"  ->  Nested Loop  (cost=9.33..3630.61 rows=1 width=4) (actual time=1.418..7.451 rows=7 loops=1)"
"        Join Filter: (sqlxtsproc10_.xtac_id = sqlxtsacti11_.id)"
"        Rows Removed by Join Filter: 3"
"        Buffers: shared hit=1965"
"        ->  Nested Loop  (cost=9.33..3629.01 rows=1 width=12) (actual time=1.408..7.353 rows=10 loops=1)"
"              Join Filter: (sqlxtsserv9_.xpra_id = sqlxtsproc10_.id)"
"              Rows Removed by Join Filter: 970"
"              Buffers: shared hit=1955"
"              ->  Nested Loop  (cost=9.33..3624.81 rows=1 width=12) (actual time=1.360..6.556 rows=10 loops=1)"
"                    Join Filter: (sqlxtscust8_.xspa_id = sqlxtsserv9_.id)"
"                    Rows Removed by Join Filter: 2440"
"                    Buffers: shared hit=1935"
"                    ->  Nested Loop  (cost=9.33..3616.29 rows=1 width=12) (actual time=1.224..4.589 rows=10 loops=1)"
"                          Buffers: shared hit=1905"
"                          ->  Nested Loop  (cost=8.91..3615.84 rows=1 width=12) (actual time=1.213..4.517 rows=10 loops=1)"
"                                Join Filter: (sqlxtsjob5_.xprs_id = sqlxtsstat6_.id)"
"                                Rows Removed by Join Filter: 74"
"                                Buffers: shared hit=1865"
"                                ->  Nested Loop  (cost=8.91..3611.65 rows=18 width=20) (actual time=0.197..4.394 rows=21 loops=1)"
"                                      Buffers: shared hit=1863"
"                                      ->  Nested Loop  (cost=8.48..3601.60 rows=18 width=20) (actual time=0.187..4.219 rows=21 loops=1)"
"                                            Buffers: shared hit=1779"
"                                            ->  Nested Loop  (cost=8.05..3593.34 rows=18 width=20) (actual time=0.172..4.037 rows=21 loops=1)"
"                                                  Buffers: shared hit=1695"
"                                                  ->  Nested Loop  (cost=7.62..3584.77 rows=16 width=16) (actual time=0.154..3.841 rows=21 loops=1)"
"                                                        Join Filter: (sqlxtsjoba0_.xprs_id = sqlxtsstat7_.id)"
"                                                        Rows Removed by Join Filter: 1579"
"                                                        Buffers: shared hit=1611"
"                                                        ->  Nested Loop  (cost=7.62..3560.30 rows=356 width=24) (actual time=0.087..2.154 rows=400 loops=1)"
"                                                              Buffers: shared hit=1609"
"                                                              ->  Bitmap Heap Scan on id_helper3 sqlidhelpe3_  (cost=7.18..550.76 rows=356 width=4) (actual time=0.075..0.233 rows=400 loops=1)"
"                                                                    Recheck Cond: (set_id = 0)"
"                                                                    Heap Blocks: exact=4"
"                                                                    Buffers: shared hit=7"
"                                                                    ->  Bitmap Index Scan on id_helper_set  (cost=0.00..7.09 rows=356 width=0) (actual time=0.065..0.065 rows=400 loops=1)"
"                                                                          Index Cond: (set_id = 0)"
"                                                                          Buffers: shared hit=3"
"                                                              ->  Index Scan using xts_job_activity_pkey on xts_job_activity sqlxtsjoba0_  (cost=0.44..8.44 rows=1 width=20) (actual time=0.003..0.003 rows=1 loops=400)"
"                                                                    Index Cond: (id = sqlidhelpe3_.reference_id)"
"                                                                    Buffers: shared hit=1602"
"                                                        ->  Materialize  (cost=0.00..3.12 rows=4 width=4) (actual time=0.000..0.002 rows=4 loops=400)"
"                                                              Buffers: shared hit=2"
"                                                              ->  Seq Scan on xts_status sqlxtsstat7_  (cost=0.00..3.10 rows=4 width=4) (actual time=0.007..0.016 rows=4 loops=1)"
"                                                                    Filter: ((code)::text = 'RUN'::text)"
"                                                                    Rows Removed by Filter: 84"
"                                                                    Buffers: shared hit=2"
"                                                  ->  Index Scan using xaij_xtja on xts_act_in_job xtsactinjo1_  (cost=0.44..0.52 rows=2 width=16) (actual time=0.007..0.008 rows=1 loops=21)"
"                                                        Index Cond: (xtja_id = sqlxtsjoba0_.id)"
"                                                        Buffers: shared hit=84"
"                                            ->  Index Scan using xts_job_process_pkey on xts_job_process sqlxtsjobp4_  (cost=0.43..0.45 rows=1 width=12) (actual time=0.006..0.007 rows=1 loops=21)"
"                                                  Index Cond: (id = xtsactinjo1_.xtjp_id)"
"                                                  Buffers: shared hit=84"
"                                      ->  Index Scan using xts_job_pkey on xts_job sqlxtsjob5_  (cost=0.43..0.55 rows=1 width=12) (actual time=0.006..0.006 rows=1 loops=21)"
"                                            Index Cond: (id = sqlxtsjobp4_.xtjo_id)"
"                                            Buffers: shared hit=84"
"                                ->  Materialize  (cost=0.00..3.12 rows=4 width=4) (actual time=0.001..0.003 rows=4 loops=21)"
"                                      Buffers: shared hit=2"
"                                      ->  Seq Scan on xts_status sqlxtsstat6_  (cost=0.00..3.10 rows=4 width=4) (actual time=0.014..0.024 rows=4 loops=1)"
"                                            Filter: ((code)::text = 'RUN'::text)"
"                                            Rows Removed by Filter: 84"
"                                            Buffers: shared hit=2"
"                          ->  Index Scan using xts_customer_activity_pkey on xts_customer_activity sqlxtscust8_  (cost=0.42..0.44 rows=1 width=12) (actual time=0.005..0.005 rows=1 loops=10)"
"                                Index Cond: (id = sqlxtsjoba0_.xtca_id)"
"                                Buffers: shared hit=40"
"                    ->  Seq Scan on xts_service_process_activity sqlxtsserv9_  (cost=0.00..5.45 rows=245 width=12) (actual time=0.002..0.093 rows=245 loops=10)"
"                          Buffers: shared hit=30"
"              ->  Seq Scan on xts_process_activity sqlxtsproc10_  (cost=0.00..2.98 rows=98 width=12) (actual time=0.002..0.034 rows=98 loops=10)"
"                    Buffers: shared hit=20"
"        ->  Seq Scan on xts_activity sqlxtsacti11_  (cost=0.00..1.59 rows=1 width=4) (actual time=0.004..0.008 rows=1 loops=10)"
"              Filter: ((handler)::text = 'FinalDeliveryCheckHandlerSession'::text)"
"              Rows Removed by Filter: 46"
"              Buffers: shared hit=10"
"Planning time: 8.361 ms"
"Execution time: 7.669 ms"

Вложения

В списке pgsql-sql по дате отправления:

Предыдущее
От: Mohd Hazmin Zailan
Дата:
Сообщение: Re: Subquery with multiple rows
Следующее
От: Tom Lane
Дата:
Сообщение: Re: ANSI JOINS versus , like JOINS