一条简单的报警信息发现的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