生產庫故障分析（主外來鍵和DML效能分析）

原創 轉載請註明出處

（我的學習筆記）   

公司生產庫2009年06月18日，出現批處理(JOB)阻塞了大量的使用者操作，具體表現就是大量的表備鎖做，並且CPU資源消耗達到了60%，讓整個系統變慢，此時間長達30分鐘。

出現問題後，我首先檢視了系統使用有大事物的存在：

select username,opname,

round(((totalwork-sofar)/totalwork),4)*100 "pct_remaining"

from V$session_Longops

WHERE TIME_REMAINING >0;

看到有大的的FULL SCAN 也就是全表掃描存在，當然這樣也看不出來問題的所在，然後進行了4點到5點的AWRRPT，報告截圖如下

DB Name	DB Id	Instance	Inst num	Release	RAC	Host
GELCPRO	4091276223	GELCPRO	1	10.2.0.1.0	NO	D0-LNXDB01

 

	Snap Id	Snap Time	Sessions	Cursors/Session
Begin Snap:	26795	18-Jun-09 15:00:32	46	11.3
End Snap:	26796	18-Jun-09 16:00:56	45	6.8
Elapsed:		60.40 (mins)
DB Time:		63.25 (mins)

 

Top 5 Timed Events

Event	Waits	Time(s)	Avg Wait(ms)	% Total Call Time	Wait Class
CPU time		3,733		98.4
ARCH wait on SENDREQ	502	934	1,861	24.6	Network
log file parallel write	8,365	107	13	2.8	System I/O
log file sync	4,470	62	14	1.6	Commit
control file parallel write	2,717	17	6	.4	System I/O

 

可以看到資料庫的負載是比較重的，而且問題出現時CPU大量消耗，感覺有CPU密集型的語句正在執行

然後檢視TOP CPU SQL，和TOP time sql

 

SQL ordered by Elapsed Time

• Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
• % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100

Elapsed Time (s)	CPU Time (s)	Executions	Elap per Exec (s)	% Total DB Time	SQL Id	SQL Module	SQL Text
1,788	1,785	121	14.78	47.11			DECLARE job BINARY_INTEGER := ...
1,780	1,779	1	1779.55	46.89			begin pkg_ls_chl_com.p_backgro...
1,279	1,279	1	1279.34	33.71			DELETE T_COMMISION_INFO CI WHE...
1,137	1,125	114,068	0.01	29.95			select /*+ all_rows */ count(...

 

 

SQL ordered by CPU Time

• Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
• % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100

CPU Time (s)	Elapsed Time (s)	Executions	CPU per Exec (s)	% Total DB Time	SQL Id	SQL Module	SQL Text
1,785	1,788	121	14.75	47.11			DECLARE job BINARY_INTEGER := ...
1,779	1,780	1	1778.72	46.89			begin pkg_ls_chl_com.p_backgro...
1,279	1,279	1	1279.08	33.71			DELETE T_COMMISION_INFO CI WHE...
1,125	1,137	114,068	0.01	29.95			select /*+ all_rows */ count(...

 

根據報告可以確定問題語句的大概範圍。

 

 

1、DECLARE job BINARY_INTEGER := :job; next_date DATE := :mydate; broken BOOLEAN := FALSE; BEGIN pkg_life_public_back_process.p_run(2, 2); :mydate := next_date; IF broken THEN :b := 1; ELSE :b := 0; END IF; END;

2、begin pkg_ls_chl_com.p_background_cal_commision(:1, :2, :3); end;

3、DELETE T_COMMISION_INFO CI WHERE CI.AGGREGATION_ID = :B1

4、select /*+ all_rows */ count(1) from "GELC_PROD"."T_COMMISSION_FEE" where "COMMISION_ID" = :1

 

 

其實前面兩個語句也許不是問題的重點，然後透過日誌挖掘挖掘日誌4點到5點的時候日誌切換最頻繁的時候時間大概在5分鐘以內切換的3個日誌，發現出現了大量的DML語句，主要集中在兩個表上

 

select seg_name,count(seg_name) count from v$logmnr_contents group by seg_name order by  count;

SEG_NAME                         COUNT

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

T_STAND_PREM_DETAIL              2028

T_SESSION_TRACE                  2096

SEQ$                             11245

T_PERFORMANCE_INFO               109267

T_COMMISION_INFO                 157757

AUD$                             249216

這裡給出了最後6行，而AUD$是審計表，T_PERFORMANCE_INFO在AWRRPT中並沒有設計到，可以確定T_PERFORMANCE_INFO雖然DML次數多但是沒有引起效能問題，剩下的就是T_COMMISION_INFO了，進一步檢視：

SQL> select substrb(sql_redo,1,50) su,count(substrb(sql_redo,1,50)) te from v$logmnr_contents where SEG_NAME='T_COMMISION_INFO'

  2  group by substrb(sql_redo,1,50) order by te ;

 

SU                                                         TE

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

update "GELC_PROD"."T_COMMISION_INFO" set "COMM_ST       4609

delete from "GELC_PROD"."T_COMMISION_INFO" where "         14503

update "GELC_PROD"."T_COMMISION_INFO" set "MONEY"       23081

Unsupported                                                 25651

insert into "GELC_PROD"."T_COMMISION_INFO"("COMMIS      89913

 

這裡出現了AWRRPT中指出的語句delete from "GELC_PROD"."T_COMMISION_INFO" where "，所以我確定真正的效能問題出在這裡，因為日誌挖掘和AWRRPT同時出現這樣的語句。

 

進一步分析發現T_COMMISION_INFO表的資料量是比較大了10W以上，當然這裡我覺得也不是問題所在，單一的一張表進行DELETE也不會出現如此的等待，然後我想可能是此表中的主鍵關聯了大量的子表，在進行刪除的時候，每一條記錄中的主鍵都會去匹配子表，如果主表中的記錄在子表中有引用，就會報錯，如果沒有引用才能被刪除，這樣如果子表的外來鍵中不存在相應的索引就會進行全表掃描，引起大量的等待，而且會鎖住子表，最初看到的多個表被鎖住，也許就是這樣引起的，當然如果一切成立最初看到的大事物的全表掃描，也是因為子表的全表掃描引起的。

透過語句

select CONSTRAINT_NAME,TABLE_NAME from dba_constraints where CONSTRAINT_TYPE='R' AND R_CONSTRAINT_NAME='PK_T_COMMISION_INFO';

發現了確實有6張表都引用了此表中的主鍵，這樣沒刪除一條資料就會去全表掃描這6張表，

T_COMMISSION_FEE   

T_COUNT_DEPT_AWARD

T_PRODUCT_COMMISION

T_COMMISION_DETAIL

T_ADJUST_AWARD

T_REMAIN_COMM   

其中T_COMMISSION_FEE 有10w多條資料

T_PRODUCT_COMMISION 有3W多條資料

 

為了證明問題確實出在這裡，在開發環境中我也做了試驗，在T_COMMISSION_FEE插入了4W多條資料，然後開啟SQL_TRACE後，用TKPROF進行格式化檢視，

我使用的語句是

delete gelcdev216.T_COMMISION_INFO where COMMISION_ID>50000;

雖然這條語句報錯了但是絲毫沒有引向結果。

當T_COMMISSION_FEE 中 COMMISION_ID沒有加索引的情況下，這條語句重啟動到失敗共耗時8秒，

並且TKPROF報告看到了這樣的情況

select /*+ all_rows */ count(1)

from

 "GELCDEV216"."T_COMMISSION_FEE" where "COMMISION_ID" = :1

 

 

call     count       cpu    elapsed       disk      query    current        rows

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

Parse        1      0.00       0.00          0          0          0           0

Execute   1274      0.02       0.03          0          0          0           0

Fetch     1274      7.91       7.75          0     718536          0        1274

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

total     2549      7.94       7.79          0     718536          0        1274

 

這個消耗是比較嚴重的，而且我只是做的其中很小的一部分，而且

select /*+ all_rows */ count(1)  from "GELCDEV216"."T_COMMISSION_FEE" where "COMMISION_ID" = :1

正是在AWRRPT中出現的

select /*+ all_rows */ count(1) from "GELC_PROD"."T_COMMISSION_FEE" where "COMMISION_ID" = :1

就是因為大量的進行一致性驗證而導致的語句，當然起初看到的全表掃描也是對子表的全表掃描，況且大量的鎖出現部分也是由於這裡的問題。

當我在T_COMMISSION_FEE 中 COMMISION_ID建立索引過後執行同樣的語句

delete gelcdev216.T_COMMISION_INFO where COMMISION_ID>50000;

 

時間只是0.5秒，而且在TKPROF中也不會出現相應掃描子表的語句，因為現在會去掃描新建的索引。

 

所以我覺得解決這個問題的方法就是在相應的資料較大的子表中建立索引，避免出現全表掃描，也不會去鎖表，因為現在掃描的僅僅是索引中的塊而已。方法及如下：

CREATE  INDEX  ****  ON T_COMMISSION_FEE(COMMISION_ID);

CREATE  INDEX  ****  ON T_PRODUCT_COMMISION(COMMISION_ID);

 

也許一條DELETE不會引起效能問題，但是如果進行批次的DELETE那小小的問題將會被放大很多。。。