strange slow query performance
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.
Ben Snaidero wrote:
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)
[...]
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)
[...]
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)
[...]
Planning time: 4.860 ms
Execution time: 16442.462 ms
(26 rows)
Not sure what is going on, but why don't you put the condition "WHERE ne.objectid=3161"
into the subselects? Then there should be at most one result row, and I can imagine
that things will become faster.
Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com
On Thu, Jan 17, 2019 at 9:19 AM Ben Snaidero <bensnaidero@geotab.com> wrote:
Any ideas as to why this is happening?
Not really, I would expect roughly double execution time, not an
exponential increase. Still not experienced enough to diagnose with
what has been provided but I will suggest you provide the version that
you are running these queries against and confirm that the results are
consistent across multiple runs to discount the possibility that
locking or other transient work is involved.
Curious if increasing work_mem helps but its mostly a trial-and-error
thing for me (I wouldn't expect it to)...
David J.
On Thu, Jan 17, 2019 at 4:13 PM David G. Johnston <
david.g.johnston@gmail.com> wrote:
On Thu, Jan 17, 2019 at 9:19 AM Ben Snaidero <bensnaidero@geotab.com>
wrote:Any ideas as to why this is happening?
Not really, I would expect roughly double execution time, not an
exponential increase. Still not experienced enough to diagnose with
what has been provided but I will suggest you provide the version that
you are running these queries against and confirm that the results are
consistent across multiple runs to discount the possibility that
locking or other transient work is involved.Curious if increasing work_mem helps but its mostly a trial-and-error
thing for me (I wouldn't expect it to)...David J.
Query was tested multiple times with similar results. I also tried
increasing work_mem with the same results as well. Memory did not increase
or even come close to the 10MB setting. Query does seem to occupy one full
cpu for the duration of the run though. Query is running on windows with
Postgres 9.6.7