From: "Van Der Berg, Stefan" <SvanderBerg@fnb.co.za>
To: "pgsql-performance@postgresql.org" <pgsql-performance@postgresql.org>
Subject: Strange performance problem with query
Thread-Topic: Strange performance problem with query
Thread-Index: AQHP0MjP7/OiQ+FeB0WQIIZgU48jTg==
Date: Mon, 15 Sep 2014 09:38:30 +0000
Message-ID: <5416B396.1080200@fnb.co.za>
Accept-Language: en-US, en-ZA
Content-Language: en-US
user-agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:24.0) Gecko/20100101
 Thunderbird/24.1.0
Content-Type: text/plain; charset="iso-8859-1"
Content-ID: <8C7D7BCBFE1C204D9C8B065B2E43CC32@services.firstrand.net>
Content-Transfer-Encoding: quoted-printable
MIME-Version: 1.0
Precedence: bulk
Sender: pgsql-performance-owner@postgresql.org

Hi All,

Please see the output from the following query analysis :
=3D# explain analyze select count(1) from jbpmprocess.jbpm_taskinstance ti=
=20
join jbpmprocess.jbpm_task task on (ti.task_ =3D task.id_ ) join=20
jbpmprocess.jbpm_processinstance pi on ti.procinst_ =3D pi.id_ where=20
ti.isopen_ =3D true;
QUERY PLAN
---------------------------------------------------------------------------=
---------------------------------------------------------------------------=
------------------------
  Aggregate  (cost=3D47372.04..47372.05 rows=3D1 width=3D0) (actual=20
time=3D647.070..647.071 rows=3D1 loops=3D1)
    ->  Hash Join  (cost=3D44806.99..47336.72 rows=3D14127 width=3D0) (actu=
al=20
time=3D605.077..645.410 rows=3D20359 loops=3D1)
          Hash Cond: (ti.task_ =3D task.id_)
          ->  Hash Join  (cost=3D44779.80..47115.28 rows=3D14127 width=3D8)=
=20
(actual time=3D604.874..640.541 rows=3D20359 loops=3D1)
                Hash Cond: (ti.procinst_ =3D pi.id_)
                ->  Index Scan using idx_task_instance_isopen on=20
jbpm_taskinstance ti  (cost=3D0.00..1995.84 rows=3D22672 width=3D16) (actua=
l=20
time=3D0.011..16.606 rows=3D20359 loops=3D1)
                      Index Cond: (isopen_ =3D true)
                      Filter: isopen_
                ->  Hash  (cost=3D28274.91..28274.91 rows=3D1320391 width=
=3D8)=20
(actual time=3D604.601..604.601 rows=3D1320391 loops=3D1)
                      Buckets: 262144  Batches: 1  Memory Usage: 51578kB
                      ->  Seq Scan on jbpm_processinstance pi=20
(cost=3D0.00..28274.91 rows=3D1320391 width=3D8) (actual time=3D0.004..192.=
166=20
rows=3D1320391 loops=3D1)
          ->  Hash  (cost=3D18.75..18.75 rows=3D675 width=3D8) (actual=20
time=3D0.196..0.196 rows=3D675 loops=3D1)
                Buckets: 1024  Batches: 1  Memory Usage: 27kB
                ->  Seq Scan on jbpm_task task  (cost=3D0.00..18.75=20
rows=3D675 width=3D8) (actual time=3D0.003..0.106 rows=3D675 loops=3D1)
  Total runtime: 652.266 ms
(15 rows)


I'm not sure why the planner insists on doing the sequential scan on=20=20
jbpm_processinstance even though the 22672 rows from jbpm_taskinstance=20
it has to match it against, is only 1% of the number of rows in=20
jbpm_processinstance. So far I think it is because the values in=20
procinst_ of jbpm_taskinstance are not entirely unique.

The very strange thing though is the way the query plan changes if I=20
repeat the where clause :

explain analyze select count(1) from jbpmprocess.jbpm_taskinstance ti=20
join jbpmprocess.jbpm_task task on (ti.task_ =3D task.id_ ) join=20
jbpmprocess.jbpm_processinstance pi on ti.procinst_ =3D pi.id_ where=20
ti.isopen_ =3D true and ti.isopen_ =3D true;
QUERY PLAN
---------------------------------------------------------------------------=
---------------------------------------------------------------------------=
--------------------
  Aggregate  (cost=3D2074.61..2074.62 rows=3D1 width=3D0) (actual=20
time=3D80.126..80.126 rows=3D1 loops=3D1)
    ->  Hash Join  (cost=3D27.19..2074.24 rows=3D151 width=3D0) (actual=20
time=3D0.217..77.959 rows=3D20359 loops=3D1)
          Hash Cond: (ti.task_ =3D task.id_)
          ->  Nested Loop  (cost=3D0.00..2044.97 rows=3D151 width=3D8) (act=
ual=20
time=3D0.016..71.429 rows=3D20359 loops=3D1)
                ->  Index Scan using idx_task_instance_isopen on=20
jbpm_taskinstance ti  (cost=3D0.00..29.72 rows=3D243 width=3D16) (actual=20
time=3D0.012..16.928 rows=3D20359 loops=3D1)
                      Index Cond: ((isopen_ =3D true) AND (isopen_ =3D true=
))
                      Filter: (isopen_ AND isopen_)
                ->  Index Scan using jbpm_processinstance_pkey on=20
jbpm_processinstance pi  (cost=3D0.00..8.28 rows=3D1 width=3D8) (actual=20
time=3D0.002..0.002 rows=3D1 loops=3D20359)
                      Index Cond: (id_ =3D ti.procinst_)
          ->  Hash  (cost=3D18.75..18.75 rows=3D675 width=3D8) (actual=20
time=3D0.196..0.196 rows=3D675 loops=3D1)
                Buckets: 1024  Batches: 1  Memory Usage: 27kB
                ->  Seq Scan on jbpm_task task  (cost=3D0.00..18.75=20
rows=3D675 width=3D8) (actual time=3D0.002..0.107 rows=3D675 loops=3D1)
  Total runtime: 80.170 ms

I get a similar plan selected on the original query if I set=20
enable_seqscan to off. I much prefer the second result.
My questions are:
1. Why is this happening?
2. How can I encourage the behavior of the second query without changing=20
the original query? Is there some column level setting I can set?

(BTW the tables are analyzed, and I currently have no special=20
settings/attributes set for any of the tables.)

--=20
Kind Regards
Stefan

Cell : 072-380-1479
Desk : 087-577-7241
To read FirstRand Bank's Disclaimer for this email click on the following a=
ddress or copy into your Internet browser:=20
https://www.fnb.co.za/disclaimer.html=20

If you are unable to access the Disclaimer, send a blank e-mail to
firstrandbankdisclaimer@fnb.co.za and we will send you a copy of the Discla=
imer.


--=20
Sent via pgsql-performance mailing list (pgsql-performance@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-performance