Oracle execution plan changes result in high database load resolution

Database Host Load


This obviously shows that the system load is high, and is still rising; in the top process, CPU is planned 100%


top-16:25:39 up 123 days, 1:42, 4 users, Load average:46.19, 45.08, 43.93


tasks:1469 Total, running, 1439 sleeping, 0 stopped, 2 zombie


Cpu (s): 45.9%us, 1.1%sy, 0.0%ni, 47.1%id, 5.2%wa, 0.1%hi, 0.6%si, 0.0%st


mem:264253752k Total, 262605260k used, 1648492k free, 413408k buffers


swap:33554424k Total, 458684k used, 33095740k free, 67110504k cached





PID userpr NI virt RES SHR S%cpu%mem time+ COMMAND


2622 Oracle 0 150g 34m 28m R 100.0 0.0 11:58.21 oracleq9db1 (local=no)


15881 Oracle 0 150g 35m 28m R 100.0 0.0 72:14.20 oracleq9db1 (local=no)


17214 Oracle 0 150g 38m 32m R 100.0 0.0 20:47.44 oracleq9db1 (local=no)


17705 Oracle 0 150g 34m 28m R 100.0 0.0 27:33.00 oracleq9db1 (local=no)


6110 Oracle 0 150g 34m 28m R 99.8 0.0 12:33.34 oracleq9db1 (local=no)


6876 Oracle 0 150g 34m 27m R 99.5 0.0 12:43.90 oracleq9db1 (local=no)


17205 Oracle 0 150g 34m 27m R 99.5 0.0 21:37.18 oracleq9db1 (local=no)


24629 Oracle 0 150g 35m 29m R 99.5 0.0 28:10.62 oracleq9db1 (local=no)


26959 Oracle 0 150g 34m 27m R 99.5 0.0 47:17.87 oracleq9db1 (local=no)


7655 Oracle 0 150g 30m 25m R 98.5 0.0 2:28.45 oracleq9db1 (local=no)


16377 Oracle 0 150g 34m 28m R 98.5 0.0 36:07.11 oracleq9db1 (local=no)


24637 Oracle 0 150g 37m 30m R 98.2 0.0 26:39.15 oracleq9db1 (local=no)


6106 Oracle 0 150g 40m 33m R 97.2 0.0 11:37.75 oracleq9db1 (local=no)


28785 Oracle 0 150g 34m 28m R 96.9 0.0 24:03.29 oracleq9db1 (local=no)


24278 Oracle 0 150g 31m 26m S 96.5 0.0 3:15.51 oracleq9db1 (local=no)


24283 Oracle 0 150g 33m 28m S 96.5 0.0 6:25.26 oracleq9db1 (local=no)


7098 Oracle 0 150g 32m 27m R 94.6 0.0 2:20.22 oracleq9db1 (local=no)


6874 Oracle 0 150g 34m 28m R 87.0 0.0 12:02.92 oracleq9db1 (local=no)


18206 Oracle 0 150g 34m 27m R 86.1 0.0 16:11.28 oracleq9db1 (local=no)


7096 Oracle 0 150g 29m 24m R 85.4 0.0 3:01.72 oracleq9db1 (local=no)


Database Wait Event


SID EVENT


---------- ----------------------------------------------------------------


183 GC CR Request


185 Latch:cache Buffers Chains


239 db file Sequential read


292 GC CR Request


406 GC CR request


410 DB file Sequential read


463 GC Current request


572 GC Buffer Busy acquire


575 GC Buffer Busy acquire


577 Latch:cache Buffers Chains


629 db file Sequential read


747 GC CR request


919 Latch:cache Buffers Chains


974 GC CR Request


1033 Log File Sync


1141 db file Parallel write


1153 GC CR request


1199 DB file Sequential read


1378 db file Sequential read


1495 GC CR request


1540 DB file Parallel write


1547 GC Buffer Busy acquire


1662 GC CR request


1715 GC Buffer Busy acquire


1770 Sql*net message to Client


1830 Latch:cache Buffers Chains


1884 GC CR request


2113 db file Sequential read


2173 db file Sequential read


2229 RDBMS IPC reply


2292 db file Sequential read


2341 db file Sequential read


2348 GC CR request


2460 GC CR request


2632 GC CR request


2684 GC CR request


2687 db file Sequential read


2749 db file Sequential read


2913 GC CR request


2967 db file Sequential read


3038 GC CR request


3087 sql*net message to Client


3089 GC CR request


3194 db file Sequential read


3195 db file Sequential read


3309 Latch:cache buffers Chains


3371 GC CR request


3485 GC CR request


3535 GC CR request


There can be a lot of GC CR request waiting and cache buffers chains waiting, the first reaction is that it is very likely that a system of SQL execution plan incorrectly results in a sharp increase in logical reading.

Analysis of AWR reports
the logical reading of the top SQL at the time of failure can see that CDWJDD67X27MH SQL logic reads abnormally large

Analysis of CDWJDD67X27MH logical reading in normal time point AWR report

By comparison, we can find that the number of CDWJDD67X27MH statements in the two awr is almost the same, but the single logical reads from 800 to 34,000, and 40 times more.

CDWJDD67X27MH Statement Analysis


Execution plan


17:36:08 Sys@q9db>select * FROM table (Dbms_xplan.display_awr (' cdwjdd67x27mh '));





Plan_table_output


--------------------------------------------------------------------------------------------------------------- --------------------------------------------------


sql_id CDWJDD67X27MH


--------------------


SELECT * FROM (SELECT * FROM Ge_taobao_bill o


WHERE 1=1 and


O.created_time >=: 1 and O.created_time <: 2


and o.rec_site_id =: 3


and o.status_id =: 4


and O.service_type =: 5 where rownum


<= 36000





Plan Hash value:647855111





--------------------------------------------------------------------------------------------------------------- -------------------


| Id | Operation | Name | Rows | Bytes | Cost (%CPU) | Time | Pstart| Pstop |


--------------------------------------------------------------------------------------------------------------- -------------------


| 0 |                           SELECT STATEMENT |       |       |     |          5 (100) |        | |


|  1 |                           COUNT Stopkey |       |       |            |          |        | |


|   2 |                           FILTER |       |       |            |          |        | |


|    3 |                           PARTITION RANGE Iterator |     |   1 |     455 | 5 (0) |   00:00:01 |   KEY | KEY |


|     4 | TABLE ACCESS by local INDEX rowid|     Ge_taobao_bill |   1 |     455 | 5 (0) |   00:00:01 |   KEY | KEY |


|      5 | INDEX RANGE SCAN |     idx_taobao_bill_cr_isdp_s |       1 |     | 4 (0) |   00:00:01 |   KEY | KEY |


--------------------------------------------------------------------------------------------------------------- -------------------





sql_id CDWJDD67X27MH


--------------------


SELECT * FROM (SELECT * FROM Ge_taobao_bill o


WHERE 1=1 and


O.created_time >=: 1 and O.created_time <: 2


and o.rec_site_id =: 3


and o.status_id =: 4


and O.service_type =: 5 where rownum


<= 36000





Plan Hash value:2979024279





--------------------------------------------------------------------------------------------------------------- ------------------


| Id | Operation | Name | Rows | Bytes | Cost (%CPU) | Time | Pstart| Pstop |


--------------------------------------------------------------------------------------------------------------- ------------------


| 0 |                          SELECT STATEMENT |       |       |    |          13 (100) |       | ||


|  1 |                          COUNT Stopkey |       |       |            |          |       | ||


|   2 |                          FILTER |       |       |            |          |       | ||


|    3 |                          PARTITION RANGE Iterator |     |   1 |    455 | 13 (0) |   00:00:01 |   KEY | KEY |


|     4 | TABLE ACCESS by local INDEX rowid|     Ge_taobao_bill |   1 |    455 | 13 (0) |   00:00:01 |   KEY | KEY |


|      5 | INDEX RANGE SCAN |     idx_taobao_bill_cr_rec_s |       4 |     | 9 (0) |   00:00:01 |   KEY | KEY |


--------------------------------------------------------------------------------------------------------------- ------------------


Here you can find that CDWJDD67X27MH has two execution plans in the database

Through AWR data to see the changes in the implementation plan


10:50:29 Sys@q9db>select A.instance_number,a.snap_id,a.sql_id,a.plan_hash_value,b.begin_interval_time


10:50:30 2 from Dba_hist_sqlstat A, dba_hist_snapshot b


10:50:30 3 where sql_id = ' cdwjdd67x27mh '


10:50:30 4 and a.snap_id = b.snap_id


10:50:30 5 ORDER BY instance_number,begin_interval_time Desc;





Instance_number snap_id sql_id Plan_hash_value begin_interval_time


--------------- ---------- ------------- --------------- ----------------------------------------


1 20719 cdwjdd67x27mh 2979024279 12-may-14 05.00.12.753 PM


1 20719 cdwjdd67x27mh 647855111 12-may-14 05.00.12.753 PM


1 20719 cdwjdd67x27mh 2979024279 12-may-14 05.00.12.702 PM


1 20719 cdwjdd67x27mh 647855111 12-may-14 05.00.12.702 PM


1 20718 cdwjdd67x27mh 647855111 12-may-14 04.00.24.197 PM


1 20718 cdwjdd67x27mh 2979024279 12-may-14 04.00.24.197 PM


1 20718 cdwjdd67x27mh 647855111 12-may-14 04.00.24.172 PM


1 20718 cdwjdd67x27mh 2979024279 12-may-14 04.00.24.172 PM


1 20717 cdwjdd67x27mh 647855111 12-may-14 03.11.22.251 PM


1 20717 cdwjdd67x27mh 2979024279 12-may-14 03.11.22.251 PM


1 20717 cdwjdd67x27mh 647855111 12-may-14 03.11.22.188 PM


1 20717 cdwjdd67x27mh 2979024279 12-may-14 03.11.22.188 PM


..................


1 20696 cdwjdd67x27mh 2979024279 11-may-14 07.00.07.142 PM


1 20696 cdwjdd67x27mh 2979024279 11-may-14 07.00.07.105 PM


1 20695 cdwjdd67x27mh 2979024279 11-may-14 06.00.12.771 PM


1 20695 cdwjdd67x27mh 2979024279 11-may-14 06.00.12.707 PM


1 20694 cdwjdd67x27mh 2979024279 11-may-14 05.00.48.249 PM


1 20694 cdwjdd67x27mh 2979024279 11-may-14 05.00.48.170 PM


1 20693 cdwjdd67x27mh 2979024279 11-may-14 04.00.37.841 PM


............


2 20719 cdwjdd67x27mh 2979024279 12-may-14 05.00.12.753 PM


2 20719 cdwjdd67x27mh 2979024279 12-may-14 05.00.12.702 PM


2 20718 cdwjdd67x27mh 2979024279 12-may-14 04.00.24.197 PM


2 20718 cdwjdd67x27mh 2979024279 12-may-14 04.00.24.172 PM


2 20717 cdwjdd67x27mh 2979024279 12-may-14 03.11.22.251 PM


2 20717 cdwjdd67x27mh 2979024279 12-may-14 03.11.22.188 PM


As you can see clearly, the execution plan is choppy in 1 nodes (two of the execution plans have a choice), looking at the two execution plans carefully, you will find that the index is different for the query and continue to analyze two index


idx_taobao_bill_cr_isdp_s Created_time 1


idx_taobao_bill_cr_isdp_s Is_dispart 2


idx_taobao_bill_cr_isdp_s status_id 3





idx_taobao_bill_cr_rec_s rec_site_id 1


idx_taobao_bill_cr_rec_s Created_time 2


idx_taobao_bill_cr_rec_s status_id 3


Analyze data distribution (other columns omitted)


TABLE_NAME column_name NUM_DISTINCT last_anal


------------------------------ ------------------------------ ------------ ---------


Ge_taobao_bill created_time 287080448 05-may-14


Ge_taobao_bill rec_site_id 13176 05-may-14


Ge_taobao_bill Is_dispart 2 05-may-14


Ge_taobao_bill status_id 7 05-may-14


Here you can see that the database in the normal use of idx_taobao_bill_cr_rec_s no problem, but in some cases choose to use idx_taobao_bill_cr_isdp_s This is a problem, resulting in high logic reading, in fact, for the SQL statement, Because the idx_taobao_bill_cr_rec_s index is unreasonable, if you create a created_time,rec_site_id,status_id, you do not use idx_taobao_bill_cr_ because of a different range of values for the transfer isdp_s the situation. For this scenario, because the table is very large and the index cannot be modified for a short time, you can only consider using the SQL profile fixed execution plan

SQL Profile Fix Plan


sql> @coe. SQL CDWJDD67X27MH





Parameter 1:


SQL_ID (required)











Plan_hash_value Avg_et_secs


--------------- -----------


2979024279.011


647855111 5.164





Parameter 2:


Plan_hash_value (required)





Enter value for 2:2,979,024,279





Values passed:


~~~~~~~~~~~~~


sql_id: "CDWJDD67X27MH"


Plan_hash_value: "2979024279"








Execute Coe_xfr_sql_profile_cdwjdd67x27mh_2979024279.sql


On TARGET system in order to create a custom SQL profile


With the plan 2979024279 linked to adjusted sql_text.








Coe_xfr_sql_profile completed.


sql> @coe_xfr_sql_profile_cdwjdd67x27mh_2979024279. sql


Sql>declare


2 Sql_txt CLOB;


3 h SYS. sqlprof_attr;


4 BEGIN


5 Sql_txt: = Q ' [


6 SELECT * FROM (SELECT


7 *


8


9 from


10


One Ge_taobao_bill


12


O


14


WHERE 1=1


16


17


18


19


20


21st


22


23


24


25


26


O.created_time >=: 1


28


29


O.created_time <: 2


31


32


o.rec_site_id =: 3


34


35


36


37


38


39


40


41


42


43


44


45


46


47


48


o.status_id =: 4


50


51


52


53


54


55


56


57


58


59


60


61


62


63


O.service_type =: 5 where rownum <= 36000


65] ';


H: = SYS. Sqlprof_attr (


Q ' [Begin_outline_data] ',


Q ' [ignore_optim_embedded_hints] ',


Q ' [Optimizer_features_enable (' 11.2.0.3 ')] ',


Q ' [Db_version (' 11.2.0.3 ')] ',


Q ' [First_rows] ',


Q ' [Outline_leaf (@ "sel$f5bb74e1")] ',


Q ' [MERGE (@ "sel$2"]] ',


Q ' [OUTLINE (@ "sel$1")] ',


Q ' [OUTLINE (@ "sel$2")] ',


Q ' [Index_rs_asc (@ "sel$f5bb74e1" "O" @ "sel$2" ("Ge_taobao_bill"). rec_site_id "" Ge_taobao_bill "." Created_time "" Ge_taobao_bill "." STATUS_ID ")]] ',


Q ' [End_outline_data] ');


78:signature: = Dbms_sqltune. Sqltext_to_signature (Sql_txt);


Dbms_sqltune. Import_sql_profile (


Sql_text => Sql_txt,


Bayi profile => H,


The name => ' coe_cdwjdd67x27mh_2979024279 ',


Description => ' Coe cdwjdd67x27mh 2979024279 ' | |:signature| | ',


Category => ' DEFAULT ',


Validate => TRUE,


The Replace => TRUE,


Force_match => FALSE/* True:force (match even when different literals in SQL). False:exact (similar to cursor_sharing) * *);


The end;


89/





Pl/sql procedure successfully completed.





Sql>whenever SQLERROR CONTINUE


Sql>set ECHO off;





SIGNATURE


---------------------


18414135509058398362








... manual custom SQL profile has been created








COE_XFR_SQL_PROFILE_CDWJDD67X27MH_2979024279 completed


System load returns to normal after fixed execution of plan


Load restored to normal, single process takes CPU as well


top-18:25:29 up 123 days, 4:25, 3 users, Load average:17.59, 16.72, 16.10


tasks:1559 Total, 6 running, 1551 sleeping, 0 stopped, 2 zombie


Cpu (s): 6.2%us, 1.2%sy, 0.0%ni, 84.3%id, 7.4%wa, 0.1%hi, 0.9%si, 0.0%st


mem:264253752k Total, 262395300k used, 1858452k free, 305928k buffers


swap:33554424k Total, 467420k used, 33087004k free, 66811412k cached





PID USER PR NI virt RES SHR S%cpu%mem time+ COMMAND


3010 Oracle 0 150g 26m 21m S 23.6 0.0 0:08.60 oracleq9db2 (local=no)


26936 Oracle 0 150g 33m 28m S 22.9 0.0 0:12.53 oracleq9db2 (local=no)


9691 Oracle 0 150g 34m 28m D 21.0 0.0 0:48.73 oracleq9db2 (local=no)


9694 Oracle 0 150g 34m 28m S 17.4 0.0 0:45.74 oracleq9db2 (local=no)


14366 Oracle 0 150g 33m 28m R 17.4 0.0 0:25.11 oracleq9db2 (local=no)


2471 oracle-2 0 150g 180m 37m S 16.7 0.1 10795:55 ORA_LMS3_Q9DB2


2463 oracle-2 0 150g 180m 37m S 15.7 0.1 10648:38 ORA_LMS1_Q9DB2


2459 oracle-2 0 150g 180m 37m S 14.8 0.1 10726:42 ORA_LMS0_Q9DB2


2467 oracle-2 0 150g 180m 36m S 14.8 0.1 10980:33 ORA_LMS2_Q9DB2


13324 Oracle 0 150g 31m 26m S 14.1 0.0 0:22.75 oracleq9db2 (local=no)


16740 Oracle 0 150g 34m 28m R 13.4 0.0 0:43.85 oracleq9db2 (local=no)


1908 Oracle 0 150g 27m 22m S 11.8 0.0 0:03.95 oracleq9db2 (local=no)


9689 Oracle 0 150g 33m 27m S 11.8 0.0 0:46.01 oracleq9db2 (local=no)


19410 Oracle 0 150g 31m 26m S 11.8 0.0 0:43.18 oracleq9db2 (local=no)


14102 Oracle 0 150g 31m 25m S 11.5 0.0 2:17.23 oracleq9db2 (local=no)


1914 Oracle 0 150g 29m 24m S 11.1 0.0 0:04.77 oracleq9db2 (local=no)


31106 Oracle 0 150g 34m 28m S 9.8 0.0 1:24.85 oracleq9db2 (local=no)


31139 Oracle 0 150g 30m 24m S 9.8 0.0 1:21.75 oracleq9db2 (local=no)


2498 Oracle 0 150g 42m 35m S 7.9 0.0 3838:43 ora_lgwr_q9db2


28108 Oracle 0 150g 36m 29m S 7.9 0.0 0:18.19 oracleq9db2 (local=no)


2392 Oracle 0 150g 35m 17m S 7.5 0.0 5304:57 ORA_LMD0_Q9DB2

Contact: Mobile Phone (13429648788) QQ (107644445)

Link: http://www.xifenfei.com/5309.html

Title: Execution plan changes result in high database load

Author: Xi-fei © Copyright [Article allows reprint, but must be linked to the source address, or to investigate legal liability.]