We have an Oracle 11g2 installation. I have a query which joins four tables of approx. 30,000 rows each. The join conditions mostly are simple equalities. There are some NOT LIKE on strings and some >= and <= on dates. The result is about 5,000 records.
When I run this query in one particular schema, the response either comes in 5 seconds, or takes over 1,000 seconds. It alternates back and forth between these two times, so if I run the query 20 times sequentially, four or five of the runs take 5 seconds and the others take a little more than 1,000 seconds.
Additionally, when the response takes 1,000 seconds, the first 1,000 records fetch in about 2 seconds, records 1,000-2,000 take about 30 seconds, 2,000-3,000 take about 90 seconds and so on.
The two NOT LIKEs are performed on the primary key column of one the tables in the join. If I instead do the same two NOT LIKEs on the referencing column, the query always takes 4 seconds. So SELECT a.id FROM a, b WHERE a.id=b.id AND a.id NOT LIKE 'ptn%' takes around 1,000 seconds, whereas SELECT a.id FROM a, b WHERE a.id=b.id AND b.id NOT LIKE 'ptn%' takes 4 seconds.
We have traced the execution, and noticed that Oracle is using two entirely different execution plans, one of them matching 4 seconds and one matching 1,000 seconds.
Can anyone give any advice what might cause an Oracle query to alternate seemingly randomly back and forth between execution times of 4 seconds and 1,000 seconds - and what can be done to avoid this?
The query that alternates between taking 4 seconds and 1,000 seconds:
select g.ucid, a.ucid
from account a, groups g, group_members gm, group_groups_flat ggf
where a.ucid = gm.ucid_member
and gm.ucid_group = ggf.ucid_member
and ggf.ucid_group = g.ucid
and a.status = 'active'
and g.unix_gid is not null
and (g.valid_to is null or g.valid_to > sysdate)
and g.sql is null
and gm.valid_from <= sysdate
and gm.valid_to >= sysdate
and g.ucid not like '$_%' escape '$'
and g.ucid not like 's$_%' escape '$'
and gm.ucid_group not like '_agreement_%'
and gm.ucid_group not like '_pdb_email_%'
and gm.ucid_group <> '_relation_others_grace'
[EDIT: removed a second query that worked, since it did not add value to the question but was confusing what the problem regarded. Also added the logging output with the two distinct execution plans]
Here is the log output when the query runs fast:
select g.ucid, a.ucid
from account a, groups g, group_members gm, group_groups_flat ggf
where a.ucid = gm.ucid_member
and gm.ucid_group = ggf.ucid_member
and ggf.ucid_group = g.ucid
and a.status = 'active'
and g.unix_gid is not null
and (g.valid_to is null or g.valid_to > sysdate)
and g.sql is null
and gm.valid_from <= sysdate
and gm.valid_to >= sysdate
and g.ucid not like '$_%' escape '$'
and g.ucid not like 's$_%' escape '$'
and gm.ucid_group not like '_agreement_%'
and gm.ucid_group not like '_pdb_email_%'
and gm.ucid_group <> '_relation_others_grace'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 111 0.45 1.01 10536 15663 0 5455
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 113 0.46 1.02 10536 15663 0 5455
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 88
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
5455 5455 5455 HASH JOIN (cr=15663 pr=10536 pw=0 time=855673 us cost=82273 size=2707430769293 card=14028138701)
79272 79272 79272 TABLE ACCESS FULL GROUPS (cr=1008 pr=0 pw=0 time=22154 us cost=277 size=10693 card=289)
385836 385836 385836 HASH JOIN (cr=14655 pr=10536 pw=0 time=1019103 us cost=15581 size=334082015904 card=2141551384)
36817 36817 36817 HASH JOIN (cr=10766 pr=10536 pw=0 time=203303 us cost=2921 size=1584289 card=17801)
6540 6540 6540 TABLE ACCESS FULL ACCOUNT (cr=630 pr=479 pw=0 time=19492 us cost=173 size=111180 card=6540)
163407 163407 163407 INDEX FAST FULL SCAN IDX_GROUP_MEMBERS (cr=10136 pr=10057 pw=0 time=1285634 us cost=2747 size=14434848 card=200484)(object id 118047)
375411 375411 375411 TABLE ACCESS FULL GROUP_GROUPS_FLAT (cr=3889 pr=0 pw=0 time=58535 us cost=1029 size=25152738 card=375414)
And from a slow run:
select g.ucid, a.ucid
from account a, groups g, group_members gm, group_groups_flat ggf
where a.ucid = gm.ucid_member
and gm.ucid_group = ggf.ucid_member
and ggf.ucid_group = g.ucid
and a.status = 'active'
and g.unix_gid is not null
and (g.valid_to is null or g.valid_to > sysdate)
and g.sql is null
and gm.valid_from <= sysdate
and gm.valid_to >= sysdate
and g.ucid not like '$_%' escape '$'
and g.ucid not like 's$_%' escape '$'
and gm.ucid_group not like '_agreement_%'
and gm.ucid_group not like '_pdb_email_%'
and gm.ucid_group <> '_relation_others_grace'
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 9 0.00 0.00 0 0 0 0
Execute 9 0.00 0.00 0 0 0 0
Fetch 1072 9440.36 9694.78 20406 141617 0 52699
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 1090 9440.37 9694.79 20406 141617 0 52699
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 88
Number of plan statistics captured: 3
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
5455 5455 5455 HASH JOIN (cr=15664 pr=0 pw=0 time=778178696 us cost=30838477 size=741611997206725 card=3842549208325)
375411 375411 375411 TABLE ACCESS FULL GROUP_GROUPS_FLAT (cr=3782 pr=0 pw=0 time=51533 us cost=1029 size=25152738 card=375414)
2918557224 55245693 2918557224 HASH JOIN (cr=11882 pr=0 pw=0 time=778554141 us cost=3430847 size=177798827178 card=1411101803)
163407 163407 163407 INDEX FAST FULL SCAN IDX_GROUP_MEMBERS (cr=10136 pr=0 pw=0 time=148427 us cost=2747 size=14434848 card=200484)(object id 118047)
518438880 518438880 518438880 MERGE JOIN CARTESIAN (cr=1746 pr=0 pw=0 time=142455288 us cost=1800499 size=27995699520 card=518438880)
6540 6540 6540 TABLE ACCESS FULL ACCOUNT (cr=738 pr=0 pw=0 time=49324 us cost=173 size=111180 card=6540)
518438880 518438880 518438880 BUFFER SORT (cr=1008 pr=0 pw=0 time=69843749 us cost=1800326 size=2933064 card=79272)
79272 79272 79272 TABLE ACCESS FULL GROUPS (cr=1008 pr=0 pw=0 time=25244 us cost=275 size=2933064 card=79272)
On 20 sequential runs, where I just restart an identical query, about 4 or 5 use the fast execution plan while the others use the slow one.
AND a.id NOT LIKE 'ptn%'query is slow, and theAND b.id NOT LIKE 'ptn%'is fast, have you checked that there is an equivalent index onathat already exists onb? – Phil Mar 30 '12 at 13:46NOT LIKEs against the groups table while the second doesNOT LIKESs against the group_groups_flat table. I realize that these are inner joined, but the query optimizer may be using them differently. Unfortunately that does not explain why your first query would alternate timings. – Leigh Riffel Mar 30 '12 at 15:36