ORACLE Bug 4431215 引发的血案—处理篇

shenyg

　　今早一大早就到了公司，正想去享受美味早餐，出于职业反映去检查了下几个核心RAC数据库，居然发现其中一个RAC数据库的两个节点的ALERT日志均有错误，其中一个节点更是持续滚动输出，马上提起12分的精神开始面对这新的挑战。初步查看发现，两个节点通过PL/SQL均不能连接，但是本机能正常登陆，而查询业务语句只有在节点1可以运行，但节点1也经常处于HANG这个状态。
     说来也巧，昨天由于机房检修，我们这个RAC库的DATAGUARD从库被列入了停机的黑名单，因此故障发生时DG从库是处于关机状态下的，也就意味着归档不能从主库同步到从库，我的脑海里首先不自觉的就把该错误和DG从库联系到一起，以至于一定时间内干扰了对问题的认识，并导致处理方案并不是最优的，今天晚上就不得不花费数小时来弥补这不是最优的选项，但是想想业务在半小时内得到了恢复，这是最让人欣慰的。
　　错误日志：
　　

• 节点1的ALERT日志：
  
• Wed Jul 13 04:06:26 2011
  
• >>> WAITED TOO LONG FOR A ROW CACHE ENQUEUE LOCK! pid=214
  
• System State dumped to trace file /u01/app/oracle/admin/port/udump/port1_ora_4668.trc
  
• Wed Jul 13 06:26:59 2011
  
• Errors in file /u01/app/oracle/admin/port/bdump/port1_j000_3593.trc:
  
• ORA-12012: error on auto execute of job 42780
  
• ORA-27468: "." is locked by another process
  
• Wed Jul 13 06:49:44 2011
  
• Errors in file /u01/app/oracle/admin/port/bdump/port1_j001_4323.trc:
  
• ORA-12012: error on auto execute of job 42781
  
• ORA-27468: "." is locked by another process
  
• Wed Jul 13 07:25:30 2011
  
• Errors in file /u01/app/oracle/admin/port/bdump/port1_j000_3593.trc:
  
• ORA-12012: error on auto execute of job 42780
  
• ORA-27468: "." is locked by another process
  
• Wed Jul 13 07:49:45 2011
  
• Errors in file /u01/app/oracle/admin/port/bdump/port1_j001_4323.trc:
  
• ORA-12012: error on auto execute of job 42781
  
• ORA-27468: "." is locked by another process
  
• 
  
• 节点2的ALERT日志：
  
• Tue Jul 12 22:57:19 2011
  
• Thread 2 advanced to log sequence 6850 (LGWR switch)
  
•   Current log# 4 seq# 6850 mem# 0: +DATA/port/onlinelog/group_4.270.697238219
  
•   Current log# 4 seq# 6850 mem# 1: +DATA/port/onlinelog/group_4.271.697238221
  
• Wed Jul 13 01:20:27 2011
  
• Thread 2 advanced to log sequence 6851 (LGWR switch)
  
•   Current log# 3 seq# 6851 mem# 0: +DATA/port/onlinelog/group_3.268.697238217
  
•   Current log# 3 seq# 6851 mem# 1: +DATA/port/onlinelog/group_3.269.697238219
  
• Thread 2 cannot allocate new log, sequence 6852
  
• Checkpoint not complete
  
•   Current log# 3 seq# 6851 mem# 0: +DATA/port/onlinelog/group_3.268.697238217
  
•   Current log# 3 seq# 6851 mem# 1: +DATA/port/onlinelog/group_3.269.697238219
  
• Wed Jul 13 01:20:36 2011
  
• Thread 2 advanced to log sequence 6852 (LGWR switch)
  
•   Current log# 4 seq# 6852 mem# 0: +DATA/port/onlinelog/group_4.270.697238219
  
•   Current log# 4 seq# 6852 mem# 1: +DATA/port/onlinelog/group_4.271.697238221
  
• Wed Jul 13 01:51:41 2011
  
• Thread 2 advanced to log sequence 6853 (LGWR switch)
  
•   Current log# 3 seq# 6853 mem# 0: +DATA/port/onlinelog/group_3.268.697238217
  
•   Current log# 3 seq# 6853 mem# 1: +DATA/port/onlinelog/group_3.269.697238219
  
• Wed Jul 13 01:51:41 2011
  
• ARCH: Archival stopped, error occurred. Will continue retrying
  
• Wed Jul 13 01:51:41 2011
  
• ORACLE Instance port2 - Archival Error
  
• Wed Jul 13 01:51:41 2011
  
• ORA-16038: log 4 sequence# 6852 cannot be archived
  
• ORA-00254: error in archive control string ''
  
• ORA-00312: online log 4 thread 2: '+DATA/port/onlinelog/group_4.270.697238219'
  
• ORA-00312: online log 4 thread 2: '+DATA/port/onlinelog/group_4.271.697238221'
  
• ORA-15173: entry 'archivelog' does not exist in directory 'port'
  

　　

　　从以上日志可以看出，故障发生时间在01:20:27-01:21:36之间，为什么这么说，因为在01：21：36时候已经出现“Checkpoint not complete”错误了，其实就是归档出了问题。但在查看具体错误的时候笔者犯了经验注意的错误，因为从库也有archivelog目录，而恰恰故障前一天停止了从库服务器，且要命的是PLSQL连接提示00257错误，这个错误经验性的让人想到是日志空间满了，不单是笔者，支援的同事和第三方维保支持人员也都进行了管辖思维，错误的判断成了是DG从库不能传输日志导致的故障，事实上只要仔细看如上的“ORA-15173: entry 'archivelog' does not exist in directory 'port'”错误和ORA-00254错误，应该可以定位故障是主库归档的问题。
　　由于这个小小的疏忽，且由于处理时效的限制，在采取备份、删除归档日志:
　　

• backup archivelog all format '/u01/archive/arch_%U';
  
• delete noprompt archivelog until time 'sysdate -3';
  
• delete noprompt archivelog until time 'sysdate -2';
  
• delete noprompt archivelog until time 'sysdate -1';
  
• delete noprompt archivelog until time 'sysdate -0';
  

　　

　　向从库传输日志无果后.便匆匆忙忙的启用了主库的非归档模式。而就是这小小的模式变动，导致了DG从库需要在今晚从主库导出全库数据，然后恢复，然后同步日志，而对于180G以上的数据量加上从库本地磁盘的属性，决定了这个过程是相当的漫长，我们在维护报告中把维护窗口从当天22：00一直申请到了次日5：00.
　　事实上只要处理时间稍微充裕那么一点，我们不难发现更简便的方法，通过ASMCMD直接创建丢失的archivelog目录就可以了。
　　

• [oradba@oracle1 rmanbak]$ export ORACLE_SID=+ASM1
  
• [oradba@oracle1 rmanbak]$ asmcmd
  
• ASMCMD> cd data
  
• ASMCMD> mkdir archivelog
  
• ASMCMD> ls
  
• PORT/
  
• archivelog/