今天收到3封報警郵件，從郵件內容中的報警情況來看，還是比較反常的。需要引起關注，找到原因處理。 這個庫是一個歷史庫，庫中的資料非常龐大，幾十億資料的表還是有好幾個。但是訪問頻率很低，一般到歷史庫中所做的歷史資料分析查詢需求還是要少很多。 報警郵件如下，可以看到DB time的閥值還是很高的。 #郵件1 [DB監控系統][email protected]_報警 ZABBIX-監控系統: ------------------------------------ 報警內容: DB time is too high ------------------------------------ 報警級別: PROBLEM ------------------------------------ 監控專案: DBtime：1403 % ------------------------------------ 報警時間:2015.10.21-05:09:35 ##郵件2 ZABBIX-監控系統: ------------------------------------ 報警內容: DB time is too high ------------------------------------ 報警級別: PROBLEM ------------------------------------ 監控專案: DBtime：1403 % ------------------------------------ 報警時間:2015.10.21-05:19:35 #郵件3 ZABBIX-監控系統: ------------------------------- 監控專案: DBtime_447 % ------------------------------------ 主機名稱：[email protected] ------------------------------------ 恢復時間:2015.10.21-05:29:38 通過這三封郵件可以看到，問題持續了有近20分鐘，然後恢復正常。 那麼這種抖動通過快照級的資料情況來看，還是可以體現出明顯的浮動。 Current Instance ~~~~~~~~~~~~~~~~ DBID DB_NAME INST_NUM INST_NAME ---------- --------- ---------- ---------------- 2534640677 testdb2 1 testdb2 DB_NAME BEGIN_SNAP END_SNAP SNAPDATE LVL DURATION_MINS DBTIME --------- ---------- ---------- -------------------- ---------- ------------- ---------- testdb2 45336 45337 21 Oct 2015 00:00 1 30 0 45337 45338 21 Oct 2015 00:30 1 30 0 45338 45339 21 Oct 2015 01:00 1 30 0 45339 45340 21 Oct 2015 01:30 1 30 4 45340 45341 21 Oct 2015 02:00 1 30 40 45341 45342 21 Oct 2015 02:31 1 30 30 45342 45343 21 Oct 2015 03:00 1 29 31 45343 45344 21 Oct 2015 03:30 1 30 31 45344 45345 21 Oct 2015 04:00 1 30 31 45345 45346 21 Oct 2015 04:30 1 30 31 45346 45347 21 Oct 2015 05:00 1 30 131 45347 45348 21 Oct 2015 05:30 1 30 0 45348 45349 21 Oct 2015 06:00 1 30 3

這個時候自己就對自己提出一個問題，為什麼平時不會報出這個問題？ 下面的圖是兩天內的DB time情況，通過下面的圖可以看到DB time前一天是到了臨界閥值，但是還沒有越界，所以沒有報警，而昨天卻又很大的抖動。

通過下面的圖可以看到，在凌晨的時候，不只報警的時間點存在大量的等待時間，主要等待時間為multiblock read，而且持續時間還是幾個小時。

可見還是存在著大量的讀操作，相對來說還是比較高的。 鑑於此，基本可以推斷可以是sql級的原因導致的，先抓取一個報告，看看在問題時間段裡，哪些sql佔用了大量的DB time ksh showsnapsql.sh 45347 SNAP_ID SQL_ID EXECUTIONS_DELTA ELAPSED_TI PER_TOTAL ---------- ------------- ---------------- ---------- ---------- 45347 b6usrg82hwsa3 1 391s 47% 45347 3rz14z1006jbk 18 290s 35% 45347 53yakkh4cbmp9 3 98s 12% 45347 4yf9vjwa2yg5j 6 9s 1% 45347 04m0jsy80udjp 6 0s 0% 從這個圖可以看出，問題還是比較明顯的，sql_id為b6usrg82hwsa3的語句佔用了大量的DB time. 那麼來看看是怎麼樣的一條sql語句，抓取下來看到竟然是一個後臺job. SQL_FULLTEXT ---------------------------------------------------------------------------------------------------- call dbms_stats.gather_database_stats_job_proc ( )

對於這個問題，同樣有一些疑點，首先為什麼今天的負載就格外高，平時也在執行這些自動任務。還有為什麼job會持續很長的時間，每天都在消耗大量的資源。 檢視資料庫日誌內容如下： Wed Oct 21 02:00:15 2015 DBMS_STATS: GATHER_STATS_JOB encountered errors. Check the trace file. Errors in file /U02/app/oracle/diag/rdbms/testdb2/testdb2/trace/testdb2_j000_3799.trc: ORA-20011: Approximate NDV failed: ORA-29913: error in executing ODCIEXTTABLEOPEN callout KUP-11024: This external table can only be accessed from within a Data Pump job. Wed Oct 21 02:01:44 2015 End automatic SQL Tuning Advisor run for special tuning task "SYS_AUTO_SQL_TUNING_TASK" Wed Oct 21 06:01:28 2015 DBMS_STATS: GATHER_STATS_JOB encountered errors. Check the trace file. Errors in file /U02/app/oracle/diag/rdbms/testdb2/testdb2/trace/testdb2_j000_16901.trc: ORA-20011: Approximate NDV failed: ORA-29913: error in executing ODCIEXTTABLEOPEN callout KUP-11024: This external table can only be accessed from within a Data Pump job. Wed Oct 21 06:20:33 2015 Thread 1 advanced to log sequence 99940 (LGWR switch) Current log# 22 seq# 99940 mem# 0: +DATA/testdb2/onlinelog/group_22.863.811354265 Wed Oct 21 06:20:38 2015 Archived Log entry 215736 added for thread 1 sequence 99939 ID 0x9bd5d836 dest 1: Wed Oct 21 08:00:00 2015 Closing scheduler window Closing Resource Manager plan via scheduler window Clearing Resource Manager plan via parameter create tablespace DETAIL_DATA_20160110 datafile '+data' size 50m autoextend on next 10m maxsize 34359721984 Completed: create tablespace TLDETAIL_DATA_20160110 datafile '+data' size 50m autoextend on next 10m maxsize 34359721984 create tablespace DETAIL_INDEX_20160110 datafile '+data' size 50m autoextend on next 10m maxsize 34359721984 Completed: create tablespace TLDETAIL_INDEX_20160110 datafile '+data' size 50m autoextend on next 10m maxsize 34359721984 create tablespace SERLOG_DATA_20160110 datafile '+data' size 50m autoextend on next 10m maxsize 34359721984 Completed: create tablespace TLSERLOG_DATA_20160110 datafile '+data' size 50m autoextend on next 10m maxsize 34359721984 通過這個日誌可以看出還是存在兩個問題，一個是因為嘗試去收集統計資訊的job失敗了。還有一個是表在昨天建立了大量的表空間。 問題可以初步分解。報錯的trace檔案內容如下，發現是一個datapump的臨時表導致的。 $ less /U02/app/oracle/diag/rdbms/testdb2/testdb2/trace/testdb2_j000_3799.trc *** 2015-10-21 02:00:15.184 *** SESSION ID:(5090.5085) 2015-10-21 02:00:15.184 *** CLIENT ID:() 2015-10-21 02:00:15.184 *** SERVICE NAME:(SYS$USERS) 2015-10-21 02:00:15.184 *** MODULE NAME:(DBMS_SCHEDULER) 2015-10-21 02:00:15.184 *** ACTION NAME:(ORA$AT_OS_OPT_SY_5869) 2015-10-21 02:00:15.184 ORA-20011: Approximate NDV failed: ORA-29913: error in executing ODCIEXTTABLEOPEN callout KUP-11024: This external table can only be accessed from within a Data Pump job. *** 2015-10-21 02:00:15.184 DBMS_STATS: GATHER_STATS_JOB: GATHER_TABLE_STATS('"SYS"','"ET$136C02550001"','""', ...) DBMS_STATS: ORA-20011: Approximate NDV failed: ORA-29913: error in executing ODCIEXTTABLEOPEN callout KUP-11024: This external table can only be accessed from within a Data Pump job. 至於這個臨時表為什麼沒有清除，還是歷史原因，早已經存在很久了。所以還是可以驗證後直接drop. 當然為了徹底解決問題還是抓取問題的本質，所以先刪除這個有問題的臨時表。 SQL> select owner,table_name from dba_tables where table_name like 'ET%'; OWNER TABLE_NAME ------------------------------ ------------------------------ SYS ET$136C02550001 SQL> DROP TABLE ET$136C02550001; Table dropped. 這個時候還是先保留後臺job enable,然後對比一下在同樣的情況下，今天的負載情況。但是單純來分析alert日誌，發現每天的幾個時段都都會存在ORA的問題。 $ grep -B5 "ORA-20011" alert*.log|grep 2015 Thu Oct 15 02:00:13 2015 Thu Oct 15 06:03:14 2015 Fri Oct 16 02:00:13 2015 Fri Oct 16 02:00:24 2015 Fri Oct 16 06:04:35 2015 Sat Oct 17 06:00:12 2015 Sat Oct 17 10:06:10 2015 Sat Oct 17 14:06:27 2015 Sat Oct 17 18:06:37 2015 Sat Oct 17 22:06:51 2015 Sun Oct 18 06:00:01 2015 Sun Oct 18 06:00:12 2015 Sun Oct 18 06:16:25 2015 Sun Oct 18 10:07:31 2015 Sun Oct 18 14:07:45 2015 Sun Oct 18 18:08:02 2015 Sun Oct 18 22:08:13 2015 Mon Oct 19 02:00:10 2015 Mon Oct 19 06:08:44 2015 Tue Oct 20 02:00:16 2015 Wed Oct 21 02:00:02 2015 Wed Oct 21 02:00:15 2015 Wed Oct 21 02:01:44 2015 Wed Oct 21 06:01:28 2015 所以這個問題看來還是影響很大，也算遺留歷史問題。 至於為什麼負載突然升高那麼多，一般來說後臺的自動任務的消耗還是相對較高，但是也高不了多少。為什麼統計資訊，統計資訊收集的閥值，可以參考mos的文章。 Automatic Optimizer Statistics Collection on Partitioned Table (Doc ID 1592404.1)