Обсуждение: 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.typeAS MainTable_type FROM MainTable
> WHERE objectid = ANY(ARRAY(SELECT NE.objectid AS entityId FROM ( nodeobject NE INNER JOIN ( Node N1NE INNER
JOINNode 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.094rows=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
stillthe 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.typeAS MainTable_type FROM MainTable
> WHERE objectid = ANY(ARRAY(SELECT NE.objectid AS entityId FROM ( nodeobject NE INNER JOIN ( Node N1NE INNER
JOINNode 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
JOINNode 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.004rows=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