Query runs really fast just after analyzing only for 1st attempt, but then slows down considerably in subsequent runs

by

I am using oracle DB and facing problem while executing the queries.
Query execution is very much slow, it takes nearly 10 mins to execute.

For solving this problem, I analyzed all the tables used in the query.
But I noticed that just after analyzing when I am running the query it executes fast, but it takes time in subsequent runs.

Basically, query execution is only fast just after analyzing all the tables.
I also checked the explain plan of query for both the cases and noticed that there is no difference in the explain plan as well.

I am not understanding what is going wrong, can anyone please help me with this?

Explain plan for query working slow:

Plan hash value: 2934657597

Id Operation Name Rows Bytes Cost (%CPU) Time
0 SELECT STATEMENT 1 392 58565 (2) 00:00:03
* 1 TABLE ACCESS FULL QM_LOCATION_MAP 1 22 8 (0) 00:00:01
2 SORT AGGREGATE 1 31
* 3 TABLE ACCESS BY INDEX ROWID BATCHED QM_ACTION_HISTORY 1 31 4 (0) 00:00:01
* 4 INDEX RANGE SCAN I_AHI_PK_OID 3 3 (0) 00:00:01
5 SORT UNIQUE 1 392 58564 (2) 00:00:03
6 NESTED LOOPS OUTER 1 392 58551 (2) 00:00:03
7 NESTED LOOPS 1 364 58544 (2) 00:00:03
8 NESTED LOOPS 209 71269 56035 (2) 00:00:03
9 NESTED LOOPS 163 48248 55593 (2) 00:00:03
* 10 HASH JOIN 163 40913 55267 (2) 00:00:03
11 TABLE ACCESS FULL QM_STEEL_GRADE 224 3584 4 (0) 00:00:01
12 NESTED LOOPS 164 38540 55263 (2) 00:00:03
13 NESTED LOOPS 196 38540 55263 (2) 00:00:03
14 NESTED LOOPS 196 33320 54903 (2) 00:00:03
15 NESTED LOOPS 194 25220 54321 (2) 00:00:03
* 16 HASH JOIN 181 19910 53778 (2) 00:00:03
* 17 HASH JOIN 181 14661 53774 (2) 00:00:03
* 18 TABLE ACCESS FULL QM_PROCESS 10666 614K 48811 (2) 00:00:02
19 TABLE ACCESS FULL QM_STORAGEPROCESS 3319K 69M 4952 (1) 00:00:01
20 TABLE ACCESS FULL QM_SLAB_STACK 1093 31697 4 (0) 00:00:01
21 TABLE ACCESS BY INDEX ROWID BATCHED QM_PROCESS_HISTORY 1 20 3 (0) 00:00:01
* 22 INDEX RANGE SCAN I_PHI_PROCESS_OID 1 2 (0) 00:00:01
23 TABLE ACCESS BY INDEX ROWID BATCHED QM_ITEM 1 40 3 (0) 00:00:01
* 24 INDEX RANGE SCAN I_ITM_PROCESS_HISTORY_OID 1 2 (0) 00:00:01
* 25 INDEX UNIQUE SCAN QM_SLAB_PK 1 1 (0) 00:00:01
26 TABLE ACCESS BY INDEX ROWID QM_SLAB 1 65 2 (0) 00:00:01
27 TABLE ACCESS BY INDEX ROWID QM_READYFORROLLINGDATA 1 45 2 (0) 00:00:01
* 28 INDEX UNIQUE SCAN QM_READYFORROLLINGDATA_PK 1 1 (0) 00:00:01
29 TABLE ACCESS BY INDEX ROWID BATCHED QM_READYFORROLLINGDATA_HISTORY 1 45 3 (0) 00:00:01
* 30 INDEX RANGE SCAN RFRHIST_I 2 2 (0) 00:00:01
* 31 VIEW PUSHED PREDICATE 1 23 12 (9) 00:00:01
* 32 FILTER
33 SORT AGGREGATE 1 34
34 VIEW 2 68 12 (9) 00:00:01
35 SORT UNIQUE 2 164 12 (9) 00:00:01
36 UNION-ALL
37 NESTED LOOPS 1 41 5 (0) 00:00:01
* 38 TABLE ACCESS BY INDEX ROWID QM_READYFORROLLINGDATA 1 31 3 (0) 00:00:01
* 39 INDEX UNIQUE SCAN QM_READYFORROLLINGDATA_PK 1 2 (0) 00:00:01
* 40 INDEX RANGE SCAN I_SLB_READY_FOR_ROLLING_OID 1 10 2 (0) 00:00:01
41 NESTED LOOPS 1 41 6 (0) 00:00:01
42 NESTED LOOPS 1 41 6 (0) 00:00:01
* 43 INDEX RANGE SCAN I_SLB_READY_FOR_ROLLING_OID 1 10 3 (0) 00:00:01
* 44 INDEX RANGE SCAN RFRHIST_I 1 2 (0) 00:00:01
* 45 TABLE ACCESS BY INDEX ROWID QM_READYFORROLLINGDATA_HISTORY 1 31 3 (0) 00:00:01
* 46 VIEW PUSHED PREDICATE 1 28 7 (15) 00:00:01
47 WINDOW SORT 1 36 7 (15) 00:00:01
* 48 TABLE ACCESS BY INDEX ROWID BATCHED QM_WEIGHT_HISTORY 1 36 6 (0) 00:00:01
* 49 INDEX RANGE SCAN I_WHI_PK_OID 4 3 (0) 00:00:01

Explian plan for query working fast:

Plan hash value: 2934657597

Id Operation Name Rows Bytes Cost (%CPU) Time
0 SELECT STATEMENT 1 392 58565 (2) 00:00:03
* 1 TABLE ACCESS FULL QM_LOCATION_MAP 1 22 8 (0) 00:00:01
2 SORT AGGREGATE 1 31
* 3 TABLE ACCESS BY INDEX ROWID BATCHED QM_ACTION_HISTORY 1 31 4 (0) 00:00:01
* 4 INDEX RANGE SCAN I_AHI_PK_OID 3 3 (0) 00:00:01
5 SORT UNIQUE 1 392 58564 (2) 00:00:03
6 NESTED LOOPS OUTER 1 392 58551 (2) 00:00:03
7 NESTED LOOPS 1 364 58544 (2) 00:00:03
8 NESTED LOOPS 209 71269 56035 (2) 00:00:03
9 NESTED LOOPS 163 48248 55593 (2) 00:00:03
* 10 HASH JOIN 163 40913 55267 (2) 00:00:03
11 TABLE ACCESS FULL QM_STEEL_GRADE 224 3584 4 (0) 00:00:01
12 NESTED LOOPS 164 38540 55263 (2) 00:00:03
13 NESTED LOOPS 196 38540 55263 (2) 00:00:03
14 NESTED LOOPS 196 33320 54903 (2) 00:00:03
15 NESTED LOOPS 194 25220 54321 (2) 00:00:03
* 16 HASH JOIN 181 19910 53778 (2) 00:00:03
* 17 HASH JOIN 181 14661 53774 (2) 00:00:03
* 18 TABLE ACCESS FULL QM_PROCESS 10665 614K 48811 (2) 00:00:02
19 TABLE ACCESS FULL QM_STORAGEPROCESS 3319K 69M 4952 (1) 00:00:01
20 TABLE ACCESS FULL QM_SLAB_STACK 1093 31697 4 (0) 00:00:01
21 TABLE ACCESS BY INDEX ROWID BATCHED QM_PROCESS_HISTORY 1 20 3 (0) 00:00:01
* 22 INDEX RANGE SCAN I_PHI_PROCESS_OID 1 2 (0) 00:00:01
23 TABLE ACCESS BY INDEX ROWID BATCHED QM_ITEM 1 40 3 (0) 00:00:01
* 24 INDEX RANGE SCAN I_ITM_PROCESS_HISTORY_OID 1 2 (0) 00:00:01
* 25 INDEX UNIQUE SCAN QM_SLAB_PK 1 1 (0) 00:00:01
26 TABLE ACCESS BY INDEX ROWID QM_SLAB 1 65 2 (0) 00:00:01
27 TABLE ACCESS BY INDEX ROWID QM_READYFORROLLINGDATA 1 45 2 (0) 00:00:01
* 28 INDEX UNIQUE SCAN QM_READYFORROLLINGDATA_PK 1 1 (0) 00:00:01
29 TABLE ACCESS BY INDEX ROWID BATCHED QM_READYFORROLLINGDATA_HISTORY 1 45 3 (0) 00:00:01
* 30 INDEX RANGE SCAN RFRHIST_I 2 2 (0) 00:00:01
* 31 VIEW PUSHED PREDICATE 1 23 12 (9) 00:00:01
* 32 FILTER
33 SORT AGGREGATE 1 34
34 VIEW 2 68 12 (9) 00:00:01
35 SORT UNIQUE 2 164 12 (9) 00:00:01
36 UNION-ALL
37 NESTED LOOPS 1 41 5 (0) 00:00:01
* 38 TABLE ACCESS BY INDEX ROWID QM_READYFORROLLINGDATA 1 31 3 (0) 00:00:01
* 39 INDEX UNIQUE SCAN QM_READYFORROLLINGDATA_PK 1 2 (0) 00:00:01
* 40 INDEX RANGE SCAN I_SLB_READY_FOR_ROLLING_OID 1 10 2 (0) 00:00:01
41 NESTED LOOPS 1 41 6 (0) 00:00:01
42 NESTED LOOPS 1 41 6 (0) 00:00:01
* 43 INDEX RANGE SCAN I_SLB_READY_FOR_ROLLING_OID 1 10 3 (0) 00:00:01
* 44 INDEX RANGE SCAN RFRHIST_I 1 2 (0) 00:00:01
* 45 TABLE ACCESS BY INDEX ROWID QM_READYFORROLLINGDATA_HISTORY 1 31 3 (0) 00:00:01
* 46 VIEW PUSHED PREDICATE 1 28 7 (15) 00:00:01
47 WINDOW SORT 1 36 7 (15) 00:00:01
* 48 TABLE ACCESS BY INDEX ROWID BATCHED QM_WEIGHT_HISTORY 1 36 6 (0) 00:00:01
* 49 INDEX RANGE SCAN I_WHI_PK_OID 4 3 (0) 00:00:01

  • 1

    Regenerate the explain plans using the package DBMS_XPLAN and update the question with that output. For example, run queries like explain plan for select ... and select * from table(dbms_xplan.display), or use a query like select * from table(dbms_xplan.display_cursor(sql_id => 'your sql_id here')); The DBMS_XPLAN package formats the data better and it includes the important “Note” section at the bottom. That section may explain why the plans change. For example, if the plan is adaptive or uses cardinality feedback, the “Note” section will mention it.

    – 

  • It would also be helpful to compare the plans and indicate where any differences occur. Are the “subsequent runs” done immediately after the first run? Are there large differences in the number/ distribution of the data in the underlying tables (i.e. is there some process that may be doing a large load into one of the tables or is there some table that is supposed to have transient data)/

    – 

  • Also, although the explain plan hash is static, the adaptive plan might change. If your query has an adaptive plan, gather the actual execution plan numbers along with the active adaptive plans. You can do that with queries like select /*+ gather_plan_statistics */ ... and then select * from table(dbms_xplan.display_cursor(format => 'adaptive allstats last'));. Gathering the right information for complex performance problems can be way more complicated than clicking a button in an IDE. You might need to spend some time reading about some of the DBMS_XPLAN features and relevant hints.

    – 

  • @JonHeller I got this explain plan using queries explain plan for select … and select * from table(dbms_xplan.display), but I don’t see any note section. Also, as per my understanding both explain plans are same. So, I am not getting if explain plan for both the cases are same then why is one query running fast and other one is taking too long.

    – 

Leave a Comment