strange slow query performance

From: Ben Snaidero <bensnaidero(at)geotab(dot)com>
To: pgsql-general(at)postgresql(dot)org
Subject: strange slow query performance
Date: 2019-01-17 16:19:31
Message-ID: CAEPE5bOdhQm41PEjvTeQK2mrUA5xeOnZ-Oe1Kw=AShvfEbAZpw@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

The following query runs as expected.

explain analyze SELECT MainTable.gid AS MainTable_gid,MainTable.datetime AS
MainTable_datetime,MainTable.objectid AS MainTable_objectid,MainTable.type
AS MainTable_type FROM MainTable
WHERE objectid = ANY(ARRAY(SELECT NE.objectid AS entityId FROM (
nodeobject NE INNER JOIN ( Node N1NE INNER JOIN Node N2NE ON
((N1NE.iLeft >= N2NE.iLeft) AND (N1NE.iLeft <= N2NE.iRight))) ON
NE.inodeid = N1NE.iId ) WHERE N2NE.iId = ANY(ARRAY[14438,10814])))
AND objectid=3161;

QUERY PLAN

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Index Scan using ix_MainTable_objectid_datetime on MainTable
(cost=3254.91..3264.39 rows=1 width=32) (actual time=33.094..33.094 rows=0
loops=1)
Index Cond: ((objectid = ANY ($3)) AND (objectid = 3161))
InitPlan 1 (returns $3)
-> Nested Loop (cost=1.10..3254.75 rows=16296 width=4) (actual
time=0.403..26.147 rows=19042 loops=1)
-> Nested Loop (cost=0.81..1784.15 rows=618 width=4) (actual
time=0.249..10.485 rows=2082 loops=1)
-> Index Scan using pk_node on node n2ne
(cost=0.41..16.80 rows=2 width=8) (actual time=0.103..0.233 rows=2 loops=1)
Index Cond: (iid = ANY ('{14438,10814}'::integer[]))
-> Index Only Scan using ix_node on node n1ne
(cost=0.41..880.59 rows=309 width=8) (actual time=0.074..5.022 rows=1041
loops=2)
Index Cond: ((ileft >= n2ne.ileft) AND (ileft <=
n2ne.iright))
Heap Fetches: 30
-> Index Only Scan using ix_nodeobject_inodeid_objectid on
nodeobject ne (cost=0.29..1.81 rows=57 width=8) (actual time=0.002..0.007
rows=9 loops=2082)
Index Cond: (inodeid = n1ne.iid)
Heap Fetches: 13973
Planning time: 5.693 ms
Execution time: 33.383 ms
(15 rows)

But when we add a second condition to the where clause it causes the query
performance to drop dramatically. Values in "any(array" do not make a
difference. In this example they are the same but even for different
values performance is still the poor. Any ideas as to why this is
happening?

explain analyze SELECT MainTable.gid AS MainTable_gid,MainTable.datetime AS
MainTable_datetime,MainTable.objectid AS MainTable_objectid,MainTable.type
AS MainTable_type FROM MainTable
WHERE objectid = ANY(ARRAY(SELECT NE.objectid AS entityId FROM (
nodeobject NE INNER JOIN ( Node N1NE INNER JOIN Node N2NE ON
((N1NE.iLeft >= N2NE.iLeft) AND (N1NE.iLeft <= N2NE.iRight))) ON
NE.inodeid = N1NE.iId ) WHERE N2NE.iId = ANY(ARRAY[14438,10814])))
AND objectid = ANY(ARRAY(SELECT NE.objectid AS entityId FROM (
nodeobject NE INNER JOIN ( Node N1NE INNER JOIN Node N2NE ON
((N1NE.iLeft >= N2NE.iLeft) AND (N1NE.iLeft <= N2NE.iRight))) ON
NE.inodeid = N1NE.iId ) WHERE N2NE.iId = ANY(ARRAY[14438,10814]))) AND
objectid=3161;

QUERY PLAN

--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-
Index Scan using ix_MainTable_objectid_datetime on MainTable
(cost=6509.66..6534.02 rows=1 width=32) (actual time=16442.004..16442.004
rows=0 loops=1)
Index Cond: ((objectid = ANY ($3)) AND (objectid = ANY ($7)) AND
(objectid = 3161))
InitPlan 1 (returns $3)
-> Nested Loop (cost=1.10..3254.75 rows=16296 width=4) (actual
time=0.438..28.484 rows=19042 loops=1)
-> Nested Loop (cost=0.81..1784.15 rows=618 width=4) (actual
time=0.172..7.141 rows=2082 loops=1)
-> Index Scan using pk_node on node n2ne
(cost=0.41..16.80 rows=2 width=8) (actual time=0.046..0.111 rows=2 loops=1)
Index Cond: (iid = ANY ('{14438,10814}'::integer[]))
-> Index Only Scan using ix_node on node n1ne
(cost=0.41..880.59 rows=309 width=8) (actual time=0.073..3.438 rows=1041
loops=2)
Index Cond: ((ileft >= n2ne.ileft) AND (ileft <=
n2ne.iright))
Heap Fetches: 30
-> Index Only Scan using ix_nodeobject_inodeid_objectid on
nodeobject ne (cost=0.29..1.81 rows=57 width=8) (actual time=0.003..0.010
rows=9 loops=2082)
Index Cond: (inodeid = n1ne.iid)
Heap Fetches: 13973
InitPlan 2 (returns $7)
-> Nested Loop (cost=1.10..3254.75 rows=16296 width=4) (actual
time=0.056..11.786 rows=19042 loops=1)
-> Nested Loop (cost=0.81..1784.15 rows=618 width=4) (actual
time=0.034..1.343 rows=2082 loops=1)
-> Index Scan using pk_node on node n2ne_1
(cost=0.41..16.80 rows=2 width=8) (actual time=0.007..0.016 rows=2 loops=1)
Index Cond: (iid = ANY ('{14438,10814}'::integer[]))
-> Index Only Scan using ix_node on node n1ne_1
(cost=0.41..880.59 rows=309 width=8) (actual time=0.012..0.581 rows=1041
loops=2)
Index Cond: ((ileft >= n2ne_1.ileft) AND (ileft <=
n2ne_1.iright))
Heap Fetches: 30
-> Index Only Scan using ix_nodeobject_inodeid_objectid on
nodeobject ne_1 (cost=0.29..1.81 rows=57 width=8) (actual
time=0.002..0.004 rows=9 loops=2082)
Index Cond: (inodeid = n1ne_1.iid)
Heap Fetches: 13973
Planning time: 4.860 ms
Execution time: 16442.462 ms
(26 rows)

Thanks in advance
Ben.

Responses

Browse pgsql-general by date

  From Date Subject
Next Message David G. Johnston 2019-01-17 16:23:40 Re: pgbouncer
Previous Message Nicola Contu 2019-01-17 16:15:13 Re: pgbouncer