一條簡單的報警資訊發現的oracle bug
系統中有這樣一條報警資訊，看似比較簡單，但是引起了我的注意，主要原因是因為這是一個10gR2的備庫，備庫如果出現這樣的問題，看起來似乎是在歸檔刪除上存在一些問題。
[DB監控系統]_ora_test_s2_yangjr@10.127.2.133_報警
ZABBIX-監控系統:
------------------------------------
報警內容: Free disk space is less than 20% on volume /opt
------------------------------------
報警級別: PROBLEM
------------------------------------
監控專案: Free disk space on /opt (percentage)：9.99 %
------------------------------------
報警時間:2016.03.17-02:54:03
於是做了初步的檢查，檢視磁碟空間，發現資料分割槽的空間使用率已經剩下差不多9%了。
[@test.cyou.com arch]# df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda1 5.9G 1.5G 4.1G 27% /
/dev/sda6 459G 392G 44G 91% /opt
/dev/sda3 7.8G 1.2G 6.2G 17% /var
/dev/sda5 12G 2.6G 8.6G 23% /usr
tmpfs 32G 8.0K 32G 1% /dev/shm
為了鍛鍊公司裡的幾個實習同學，於是我叫他們過來分析分析。他們噼裡啪啦的敲了一會鍵盤，然後試探性的告訴我說，發現問題了，是一個磁碟空間裡面存在大量的歷史歸檔，細看那些歸檔檔案，都是好幾年以前的，而且不在歸檔路徑下，簡單做了確認，然後做了刪除，問題的分析就告一段落。
再次檢視空間，發現已經剩餘近54%，看起來是達到了初步的效果。
[@test.cyou.com ~]# df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda1 5.9G 1.5G 4.1G 27% /
/dev/sda6 459G 197G 239G 46% /opt
/dev/sda3 7.8G 1.2G 6.2G 17% /var
/dev/sda5 12G 2.6G 8.6G 23% /usr
tmpfs 32G 8.0K 32G 1% /dev/shm
實習的同學看著我，這個問題就這樣了吧，我說稍等，仔細檢視資料的使用情況。
目前空間使用大197G,如果單純這樣看，肯定發現不了問題，但是我的印象之中，這個庫只有100G的樣子，剩下的90多個G看起來還是有些可疑，於是我大手一揮，說這個問題還是有些蹊蹺，再查查這近90G的空間消耗在哪兒了？
然後他們帶著疑惑又開始在電腦上查詢，當然也找到了一些線索。發現審計日誌裡面有大量的審計日誌，大概佔用幾個G，做了簡單確認，清了近4G的檔案，那麼這個問題似乎離根本又近了一步，但是根本問題還沒有找到。繼續讓他們檢視。其實這個時候我也不知道問題的根本原因，但是透過這些大體的數字告訴我，這應該是個問題。
他們最後發現歸檔檔案佔用了近60多G的空間，但是檢視了各個指令碼的情況，分析了各個目錄的使用情況，也沒有發現究竟是哪裡出了問題。
於是我告訴他們這樣來分析，既然歸檔目錄佔用了近60G的空間，為什麼會有60G的空間。這個問題其實很好回答，日誌檔案大小是多大，每天的歸檔日誌量是多少，歸檔的保留期限是多長時間。
帶著這樣的思路他們很快找到了答案，歸檔是100M,每天歸檔量大概在300~400M之間，歸檔保留3天，如此算來這個業務也不算繁忙，保留三天應該只佔用1G左右的空間，為什麼佔用了60G的空間，帶著這個問題，首先排除了備庫是read-only的狀態，即歸檔沒有應用的潛在風險，然後進一步分析，發現歸檔的刪除指令碼是使用crontab的方式來觸發，每天觸發一次。
歸檔的刪除策略主要的指令碼內容為：
rman target / <<eof
backup current controlfile format '/home/oracle/backup_stage/ctl_%d_%T_%s.bak';
CONFIGURE ARCHIVELOG DELETION POLICY TO applied on all standby ;
crosscheck archivelog all;
delete noprompt expired archivelog all;
delete noprompt archivelog until time "sysdate-3";
exit
EOF
這個指令碼看起來是沒有任何問題，使用crosscheck這幾個命令的時候都沒有問題，那問題出在哪裡了呢？
只有這兩句了。
backup current controlfile format '/home/oracle/backup_stage/ctl_%d_%T_%s.bak';
CONFIGURE ARCHIVELOG DELETION POLICY TO applied on all standby ;
我們單獨執行看看，發現果真報錯了。
RMAN> backup current controlfile format '/home/oracle/backup_stage/ctl_%d_%T_%s.bak';
Starting backup at 17-MAR-16
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=2971 devtype=DISK
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
including current control file in backupset
channel ORA_DISK_1: starting piece 1 at 17-MAR-16
channel ORA_DISK_1: finished piece 1 at 17-MAR-16
piece handle=/home/oracle/backup_stage/ctl_test_20160317_1914.bak tag=TAG20160317T181920 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-00601: fatal error in recovery manager
RMAN-03004: fatal error during execution of command
RMAN-10006: error running SQL statement: select sofar, context, start_time from v$session_longops where (start_time > nvl(:1, sysdate-100) or start_time = nvl(:2, sysdate+100)) and sid = :3 and serial# = :4 and opname like 'RMAN:%' order by start_time desc, context desc
RMAN-10002: ORACLE error: ORA-00000: normal, successful completion
備份控制檔案怎麼出了問題了。那下面的配置有沒有問題呢。
RMAN> CONFIGURE ARCHIVELOG DELETION POLICY TO applied on all standby ;
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-00558: error encountered while parsing input commands
RMAN-01009: syntax error: found "all": expecting one of: "standby"
RMAN-01007: at line 1 column 52 file: standard input
因為這是一個10gR2的備庫，所以這個配置再10g中是沒有那個all的，即CONFIGURE ARCHIVELOG DELETION POLICY TO applied on standby;
然後回到備份控制檔案的部分，為什麼這個步驟會出錯呢。我們跳轉到備份目錄下，發現控制檔案卻是備份成功了。
[@test.cyou.com 20160317]$
-rw-r----- 1 oracle oinstall 7667712 Mar 12 08:40 ctl_test_20160312_1907.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 13 08:40 ctl_test_20160313_1908.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 14 08:40 ctl_test_20160314_1909.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 15 08:40 ctl_test_20160315_1910.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 16 08:40 ctl_test_20160316_1911.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 17 08:40 ctl_test_20160317_1912.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 17 18:16 ctl_test_20160317_1913.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 17 18:19 ctl_test_20160317_1914.bak
drwxr-xr-x 2 oracle oinstall 4096 Nov 9 2011 standby
[@test.cyou.com backup_stage]$ pwd
/home/oracle/backup_stage
看到這裡我已經明白了問題的基本原因，那就是在10gR2中，備庫反覆再read-only,online狀態之間切換會觸發一個bug（5583049）,但是rman操作的結果返回ORA-00000: normal, successful completion,直接導致了後面的指令碼沒有執行。
這種情況一個解決方案就是重啟備庫。
所以簡單做了確認，發現備庫其實在去年年底重啟過一次。按照問題的時間來算，似乎也正是從那個時候開始歸檔就一直沒有成功刪除。
idle> select startup_time from v$instance;
STARTUP_TIME
------------
09-NOV-15
重啟之後，再次嘗試刪除，就會發現沒有任何問題了。
MAN> backup current controlfile format '/home/oracle/backup_stage/ctl_%d_%T_%s.bak';
Starting backup at 17-MAR-16
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=2958 devtype=DISK
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
including current control file in backupset
channel ORA_DISK_1: starting piece 1 at 17-MAR-16
channel ORA_DISK_1: finished piece 1 at 17-MAR-16
piece handle=/home/oracle/backup_stage/ctl_test_20160317_1915.bak tag=TAG20160317T182733 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 17-MAR-16
Starting Control File and SPFILE Autobackup at 17-MAR-16
piece handle=/U01/app/oracle/flash_recovery_area/Stest2/autobackup/2016_03_17/o1_mf_s_906705220_cgo1nptx_.bkp comment=NONE
Finished Control File and SPFILE Autobackup at 17-MAR-16
這個問題的進一步解決就是可以在刪除歸檔的指令碼里面去掉控制檔案的這種備份方式，保證歸檔及時刪除即可，可以透過主庫生成，或者在主庫備份控制檔案即可。
所以如此一來，透過一個很簡單的案例，一層一層分析，還是可以發現很多潛在的問題。
</eof
[DB監控系統]_ora_test_s2_yangjr@10.127.2.133_報警
ZABBIX-監控系統:
------------------------------------
報警內容: Free disk space is less than 20% on volume /opt
------------------------------------
報警級別: PROBLEM
------------------------------------
監控專案: Free disk space on /opt (percentage)：9.99 %
------------------------------------
報警時間:2016.03.17-02:54:03
於是做了初步的檢查，檢視磁碟空間，發現資料分割槽的空間使用率已經剩下差不多9%了。
[@test.cyou.com arch]# df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda1 5.9G 1.5G 4.1G 27% /
/dev/sda6 459G 392G 44G 91% /opt
/dev/sda3 7.8G 1.2G 6.2G 17% /var
/dev/sda5 12G 2.6G 8.6G 23% /usr
tmpfs 32G 8.0K 32G 1% /dev/shm
為了鍛鍊公司裡的幾個實習同學，於是我叫他們過來分析分析。他們噼裡啪啦的敲了一會鍵盤，然後試探性的告訴我說，發現問題了，是一個磁碟空間裡面存在大量的歷史歸檔，細看那些歸檔檔案，都是好幾年以前的，而且不在歸檔路徑下，簡單做了確認，然後做了刪除，問題的分析就告一段落。
再次檢視空間，發現已經剩餘近54%，看起來是達到了初步的效果。
[@test.cyou.com ~]# df -h
Filesystem Size Used Avail Use% Mounted on
/dev/sda1 5.9G 1.5G 4.1G 27% /
/dev/sda6 459G 197G 239G 46% /opt
/dev/sda3 7.8G 1.2G 6.2G 17% /var
/dev/sda5 12G 2.6G 8.6G 23% /usr
tmpfs 32G 8.0K 32G 1% /dev/shm
實習的同學看著我，這個問題就這樣了吧，我說稍等，仔細檢視資料的使用情況。
目前空間使用大197G,如果單純這樣看，肯定發現不了問題，但是我的印象之中，這個庫只有100G的樣子，剩下的90多個G看起來還是有些可疑，於是我大手一揮，說這個問題還是有些蹊蹺，再查查這近90G的空間消耗在哪兒了？
然後他們帶著疑惑又開始在電腦上查詢，當然也找到了一些線索。發現審計日誌裡面有大量的審計日誌，大概佔用幾個G，做了簡單確認，清了近4G的檔案，那麼這個問題似乎離根本又近了一步，但是根本問題還沒有找到。繼續讓他們檢視。其實這個時候我也不知道問題的根本原因，但是透過這些大體的數字告訴我，這應該是個問題。
他們最後發現歸檔檔案佔用了近60多G的空間，但是檢視了各個指令碼的情況，分析了各個目錄的使用情況，也沒有發現究竟是哪裡出了問題。
於是我告訴他們這樣來分析，既然歸檔目錄佔用了近60G的空間，為什麼會有60G的空間。這個問題其實很好回答，日誌檔案大小是多大，每天的歸檔日誌量是多少，歸檔的保留期限是多長時間。
帶著這樣的思路他們很快找到了答案，歸檔是100M,每天歸檔量大概在300~400M之間，歸檔保留3天，如此算來這個業務也不算繁忙，保留三天應該只佔用1G左右的空間，為什麼佔用了60G的空間，帶著這個問題，首先排除了備庫是read-only的狀態，即歸檔沒有應用的潛在風險，然後進一步分析，發現歸檔的刪除指令碼是使用crontab的方式來觸發，每天觸發一次。
歸檔的刪除策略主要的指令碼內容為：
rman target / <<eof
backup current controlfile format '/home/oracle/backup_stage/ctl_%d_%T_%s.bak';
CONFIGURE ARCHIVELOG DELETION POLICY TO applied on all standby ;
crosscheck archivelog all;
delete noprompt expired archivelog all;
delete noprompt archivelog until time "sysdate-3";
exit
EOF
這個指令碼看起來是沒有任何問題，使用crosscheck這幾個命令的時候都沒有問題，那問題出在哪裡了呢？
只有這兩句了。
backup current controlfile format '/home/oracle/backup_stage/ctl_%d_%T_%s.bak';
CONFIGURE ARCHIVELOG DELETION POLICY TO applied on all standby ;
我們單獨執行看看，發現果真報錯了。
RMAN> backup current controlfile format '/home/oracle/backup_stage/ctl_%d_%T_%s.bak';
Starting backup at 17-MAR-16
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=2971 devtype=DISK
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
including current control file in backupset
channel ORA_DISK_1: starting piece 1 at 17-MAR-16
channel ORA_DISK_1: finished piece 1 at 17-MAR-16
piece handle=/home/oracle/backup_stage/ctl_test_20160317_1914.bak tag=TAG20160317T181920 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-00601: fatal error in recovery manager
RMAN-03004: fatal error during execution of command
RMAN-10006: error running SQL statement: select sofar, context, start_time from v$session_longops where (start_time > nvl(:1, sysdate-100) or start_time = nvl(:2, sysdate+100)) and sid = :3 and serial# = :4 and opname like 'RMAN:%' order by start_time desc, context desc
RMAN-10002: ORACLE error: ORA-00000: normal, successful completion
備份控制檔案怎麼出了問題了。那下面的配置有沒有問題呢。
RMAN> CONFIGURE ARCHIVELOG DELETION POLICY TO applied on all standby ;
RMAN-00571: ===========================================================
RMAN-00569: =============== ERROR MESSAGE STACK FOLLOWS ===============
RMAN-00571: ===========================================================
RMAN-00558: error encountered while parsing input commands
RMAN-01009: syntax error: found "all": expecting one of: "standby"
RMAN-01007: at line 1 column 52 file: standard input
因為這是一個10gR2的備庫，所以這個配置再10g中是沒有那個all的，即CONFIGURE ARCHIVELOG DELETION POLICY TO applied on standby;
然後回到備份控制檔案的部分，為什麼這個步驟會出錯呢。我們跳轉到備份目錄下，發現控制檔案卻是備份成功了。
[@test.cyou.com 20160317]$
-rw-r----- 1 oracle oinstall 7667712 Mar 12 08:40 ctl_test_20160312_1907.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 13 08:40 ctl_test_20160313_1908.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 14 08:40 ctl_test_20160314_1909.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 15 08:40 ctl_test_20160315_1910.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 16 08:40 ctl_test_20160316_1911.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 17 08:40 ctl_test_20160317_1912.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 17 18:16 ctl_test_20160317_1913.bak
-rw-r----- 1 oracle oinstall 7667712 Mar 17 18:19 ctl_test_20160317_1914.bak
drwxr-xr-x 2 oracle oinstall 4096 Nov 9 2011 standby
[@test.cyou.com backup_stage]$ pwd
/home/oracle/backup_stage
看到這裡我已經明白了問題的基本原因，那就是在10gR2中，備庫反覆再read-only,online狀態之間切換會觸發一個bug（5583049）,但是rman操作的結果返回ORA-00000: normal, successful completion,直接導致了後面的指令碼沒有執行。
這種情況一個解決方案就是重啟備庫。
所以簡單做了確認，發現備庫其實在去年年底重啟過一次。按照問題的時間來算，似乎也正是從那個時候開始歸檔就一直沒有成功刪除。
idle> select startup_time from v$instance;
STARTUP_TIME
------------
09-NOV-15
重啟之後，再次嘗試刪除，就會發現沒有任何問題了。
MAN> backup current controlfile format '/home/oracle/backup_stage/ctl_%d_%T_%s.bak';
Starting backup at 17-MAR-16
using target database control file instead of recovery catalog
allocated channel: ORA_DISK_1
channel ORA_DISK_1: sid=2958 devtype=DISK
channel ORA_DISK_1: starting full datafile backupset
channel ORA_DISK_1: specifying datafile(s) in backupset
including current control file in backupset
channel ORA_DISK_1: starting piece 1 at 17-MAR-16
channel ORA_DISK_1: finished piece 1 at 17-MAR-16
piece handle=/home/oracle/backup_stage/ctl_test_20160317_1915.bak tag=TAG20160317T182733 comment=NONE
channel ORA_DISK_1: backup set complete, elapsed time: 00:00:01
Finished backup at 17-MAR-16
Starting Control File and SPFILE Autobackup at 17-MAR-16
piece handle=/U01/app/oracle/flash_recovery_area/Stest2/autobackup/2016_03_17/o1_mf_s_906705220_cgo1nptx_.bkp comment=NONE
Finished Control File and SPFILE Autobackup at 17-MAR-16
這個問題的進一步解決就是可以在刪除歸檔的指令碼里面去掉控制檔案的這種備份方式，保證歸檔及時刪除即可，可以透過主庫生成，或者在主庫備份控制檔案即可。
所以如此一來，透過一個很簡單的案例，一層一層分析，還是可以發現很多潛在的問題。
</eof
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/8494287/viewspace-2089574/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 由報警郵件分析發現的備庫oracle bugOracle
- 一條報警資訊的快速處理和分析
- 一條細小的報警簡訊的處理
- 兩條報警資訊的分析（第一篇)
- 一個oracle bug的簡單驗證Oracle
- 一個慢查詢報警的簡單處理
- 一條看似平常的報警郵件所做的分析
- 一條關於swap爭用的報警郵件分析(一）
- 一條關於swap爭用的報警郵件分析
- 使用timer控制元件建立一個簡單的報警程式 (轉)控制元件
- 一條關於swap爭用的報警郵件分析(二）
- 一條執行了3天的"簡單"的sqlSQL
- oracle資料庫自動發郵件實現報警功能Oracle資料庫
- 發現Mapstruct的一個bugStruct
- 簡單實現帶節點的進度條
- jquery 實現滑動條的簡單驗證jQuery
- Oracle警報系統Oracle
- 必備丨iOS12的新功能讓手機一鍵發簡訊報警iOS
- oracle dbms_alert對指定事件發警報Oracle事件
- 簡單實現一下Flutter的Stepper做一個側邊進度條Flutter
- 自動化報警的實現思路
- 簡單的SVG線條動畫SVG動畫
- oracle的一個bugOracle
- 一則備庫CPU報警的思考
- 我好像發現了一個Go的Bug？Go
- 一條簡單的更新語句，MySQL是如何加鎖的？MySql
- 對一條基於分割槽的簡單SQL的優化SQL優化
- 一個簡單的傳送資訊到郵箱的程式
- 實現一個簡單的 jQuery 的 APIjQueryAPI
- Oracle的又一巨型bugOracle
- 接上條，問題可能是Oracle新出的BUGOracle
- 一個簡單的選單按鈕的實現 (轉)
- php實現一個簡單的socketPHP
- 實現一個簡單的TomcatTomcat
- 實現一個簡單的 RESTful APIRESTAPI
- 簡單聊一聊FutureTask的實現
- 實現一個簡單的模板引擎
- 實現一個簡單的 dd 庫