Latch Free、Library cache伪游标(pseudo cursor)之间的乱七八糟的事情

1. Latch Free很头疼
“57.8这套系统CPU又100%啦,同事赶紧帮忙看一下。”远处传来了客户的声音。
我不慌不忙的打开终端,轻叹口气道:“唉,又是这套库,自从我来这边,已经查了2遍了,而且其他人也查过好几遍了,问题很难定位啊!“
前面我查了几次都觉得是SQL硬解析的问题,可是把这个事情反馈过去之后。他们给我们发了以前的statspack报告,发现硬解析过去是300次/秒,现在下降到了60次/秒,Latch free却增加了不少,着实摸不着头脑。”通过前期的排查基本上定位出了Latch Free的争用是由于library cache引起的。当系统出现大量的Library cache争用的时候,CPU就会达到100%。但是原因?最重要的原因一直未找到。我认为是硬解析导致的,也有同事认为是shared pool太小导致的。还有同事认为是几条逻辑读较高的语句导致的。众说纷纭,也没有一个准。基本上这些方法客户都尝试过了,仍然未能解决这个问题。

2. 从Library cache入手走下去
前期的排查让我们确信的一点是CPU的消耗是在Library cache争用上面,那么Library cache里面情况又是如何的呢?为了一探究竟,我决定在出问题期间直接查询v$libarycache视图,找寻根源。

SQL> select NAMESPACE,GETS,GETHITS,GETHITRATIO,PINS,PINHITS,PINHITRATIO from v$librarycache;
NAMESPACE GETS GETHITS GETHITRATIO PINS PINHITS PINHITRATIO RELOADS
--------------- ---------- ---------- ----------- ---------- ---------- ----------- ---------
SQL AREA 2681757300 2466988687 .91991497 2526130229 636861692 .252109604 145268976
TABLE/PROCEDURE 1425869375 1426215639 1.00024284 400135986 395962811 .989570608 4011372
BODY 149608221 149606649 .999989493 149608385 149605739 .999982314 747
TRIGGER 201588390 201584681 .999981601 201588426 201582160 .999968917 2513
INDEX 147927 144354 .975846194 147833 144231 .975634669 7
CLUSTER 1913453 1905342 .995761067 1116345 1100128 .985473129 1
OBJECT 0 0 1 0 0 1 0
PIPE 0 0 1 0 0 1 0
JAVA SOURCE 2995 1199 .40033389 2995 1199 .40033389 0
JAVA RESOURCE 2995 1202 .401335559 2995 1202 .401335559 0
JAVA DATA 0 0 1 0 0 1 0

从v$librarycache视图中我们发现了一个问题,在对SQL AREA这种对象在pin的时候发生了丢失,可以看到pin hint这项命中率只有区区的25%。而在其他上面都接近100%。那我们来具体的看一下library cache的结构。

123edc

在我们寻找hash bucket,定位cursor的handle,还有寻找具体的child cursor,或者是其依赖的对象,都需要将其pin住。然后做完操作在unpin。
发现pin的问题后,我根据文档的提示检查了v$latch_misses视图,通过这个视图我们可以看到在函数kglpnc:child和kglupc:child上面sleep_count和wtr_slp_count两个值是很高的。sleep_count字段记录进程在此位置hold对应latch而处于sleep状态的次数,而wtr_slp_count记录此内核位置request对应latch的次数。通过文档我们发现kglpnc:child和kglupc:child正好对应了pin和unpin的函数操作。

SQL> select * from v$latch_misses where PARENT_NAME = 'library cache' order by SLEEP_COUNT desc;

PARENT_NAME WHERE SLEEP_COUNT WTR_SLP_COUNT
-------------- ------------------------------------ ----------- -------------
library cache kglpndl: child: before processing 176450042 56119602
library cache kglpnc: child 175151792 205921071
library cache kglupc: child 157330567 135873756
library cache kgllkdl: child: cleanup 103775154 93107365

在网上和Mos上胡乱搜索一通,还真找到了一个解决办法,可以将参数” cursor_space_for_time”改为true,能有效的将部分cursor给pin在内存中,这样就可以减少pin和unpin产生的次数,不过修改这个参数又是有风险的。长期把这些cursor pin在shared pool内存当中,内存一定要足够大才行,不然容易报ORA-04031的错误,毕竟这可是9i的数据库呀。另外一个风险就是你的应用有cursor泄漏,那么泄漏的cursor会浪费大量内存并在一段时间的运行之后对性能产生负面影响。
所以当我们提出修改这个参数的时候,客户也说了:”年关将至,我们最好保守一些,等过完年之后在大动干戈,现在是要想办法让他把这段时间撑过去。“
3. 保守,促使需要寻找根本原因
既然要求我们保守一点,那就需要寻找问题的根源。这就需要找到引起Library cache争用的具体的对象。通过对系统的监控,我们发现了下列可疑的信息。
123rfv
可以从图中看到。我们的Library cache争用主要集中在table_这一类的东西上面,那”table_”代表着什么呢?
通过一系列的文档和资料发现叫做伪游标(pseudo cursor)。首先我们在执行一条SQL语句的时候会在内存里面申请一块区域存放我们的游标,这个内存区域就是我们的Library cache。我们可以通过v$open_cursor查询我们打开的游标,同时我们也可以通过我们的v$sql、v$sqlarea查询执行过的游标,但是会有一个奇怪的现象,一部分v$open_cursor中打开的游标在v$sql或者v$sqlarea中是查不到的。那么这一类不存在的游标有一些就是我们的伪游标了。伪游标的具体表现形式就类似”table_4_9_d6c6_0_0_0“。

SQL> select NAME,TYPE from v$db_object_cache where name like '%table_%';
NAME                                                      TYPE
------------------------------------------------------------ 
table_4_9_d6c6_0_0_0                                      CURSOR

伪游标是怎么产生的呢?在Oracle访问数据字典表、Lob字段或者Nchar、Nvarchar2的时候,Oracle内部都会提供伪游标这个结构去直接访问数据库对象,这么做的好处是省去了写一个显示的Select语句的开销。
还有一些时候,我们的AWR报告会显示下面的一系列的内容。显示**SQL Text Not Avaliable **,这类的SQL有SQL ID,可是没有SQL Text,这类的SQL也可能是伪游标。
123yhn
前面介绍了伪游标是怎么产生的,那么如何查询伪游标是在那个对象产生的呢?我们可以通过v$open_cursor查询到打开的伪游标,可以看到它的展现形式是“table_4_9_d6c6_0_0_0”,那么这个中间有一个d6c6,我们需要将这个十六进制的字符串转换成十进制,转换成十进制后就是54982,这个值对应我们的object_id。然后我们就能把object_name找出来。
还有一个办法就是在文档1298471.1提供了一个脚本可以直接帮我们查到相关的对象。脚本内容如下:

create or replace view h$pseudo_cursor as
select Pseudo_cursor, sql_id,obj_id hex_obj_id
     ,obj# object_id, u.name owner, o.name object_name
from (select distinct 
             KGLNAOBJ Pseudo_cursor,kglobt03 sql_id
        ,substr(KGLNAOBJ
               ,instr(KGLNAOBJ,'_',1,3)+1
               ,instr(KGLNAOBJ,'_',1,4)-instr(KGLNAOBJ,'_',1,3)-1) obj_id 
       ,(case when 
         replace(translate(substr(upper(KGLNAOBJ)
                                 ,instr(KGLNAOBJ,'_',1,3)+1
                                 ,instr(KGLNAOBJ,'_',1,4)
                                  -instr(KGLNAOBJ,'_',1,3)-1)
                          ,'0123456789ABCDEF','................')
                ,'.') is null then 'Y' else 'N' end) is_safe_to_compare
            from x$kglob) k
   , obj$ o, user$ u
where obj#=decode(is_safe_to_compare,'Y',to_number(obj_id,'xxxxxxxxxx'),0)
   and o.owner#=u.user#;

找到了这些伪游标,我们又找到了其相关的对象,接下来就是找到和这些对象相关的SQL语句,最保守的做法就是把能想办法把一部分LOB类的SQL进行改造。或者是高峰期错开运行。

AUL恢复Truncate数据

需要说吗一下,这里为什么要选择AUL工具,那是因为其他工具都没有办法执行大数据量的抽取,在性能上AUL也比其他工具要速度快,所以这里选用了AUL作为恢复工具。

1.进入AUL,需要设置LICENCE 

SET LICENCE XXXXX
SET BYTE_ORDER BIG

才能认到文件。第一列显示Y

AUL> open db11.cfg
*  ts#  rfn ver bsize     blocks   sizemb filename
- ---- ---- --- ----- ---------- -------- -----------------------------------
Y    0    1 a2   8192    1048576        0 /oradata10/pboss_sys/system01.dbf
Y   62  876 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_01.dbf
Y   62  894 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_04.dbf
Y   62  903 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_05.dbf
Y   62  904 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_06.dbf
Y   62  905 a2   8192    1048576        0 /oradata10/pboss_tmp1/LINKAGE_NF_DATA_07.dbf
Y   62  872 a2   8192    1048576        0 /oradata10/pboss_tmp1/linkage_std_data72.dbf

2.LOAD数据字典

AUL> UNLOAD TABLE USER$;
AUL> UNLOAD TABLE OBJ$;
AUL> UNLOAD TABLE TAB$;
AUL> UNLOAD TABLE COL$;

3.设置LOB字段参数

SET LOB_STORAGE 1
SET MAXLOBDIR 2000

4.查看用户表信息

AUL> desc pboss.TIP_NGCRMRECEIVE_LOG
Storage(OBJ#=0 OBJD=0 TS=0 FILE=0 BLOCK=0 CLUSTER=0)
No. SEQ INT Column Name                   Type
--- --- --- ----------------------------- ----------------
1   1   1 LOG_ID                        VARCHAR2(32) NOT NULL
2   2   2 SEQ                           NUMBER NOT NULL
3   3   3 SERVCODE                      VARCHAR2(5)
4   4   4 FINDCODE                      VARCHAR2(64)
5   5   5 SYSID                         VARCHAR2(5)
6   6   6 REQCODE                       VARCHAR2(4)
7   7   7 SERERRORCODE                  VARCHAR2(500)
8   8   8 REQDESC                       VARCHAR2(2000)
9   9   9 RECEIVECONTENT                CLOB  (SYS_IL0000393293C00009$$)
10  10  10 RETURNCONTENT                CLOB  (SYS_IL0000393293C00010$$)
11  11  11 LOG_FLAG                     CHAR(1)
12  12  12 LOG_DATE                     DATE NOT NULL

5.获取DATA_OBJECT_ID
去原来的生产库上执行

SQL> select SEGMENT_NAME,PARTITION_NAME,HEADER_FILE,HEADER_BLOCK from dba_segments where SEGMENT_NAME='TIP_NGCRMRECEIVE_LOG' order by PARTITION_NAME;
SEGMENT_NAME                   PARTITION_NAME     HEADER_FILE HEADER_BLOCK
------------------------------ ------------------------------ ------------
TIP_NGCRMRECEIVE_LOG           P1209                      713       113962
TIP_NGCRMRECEIVE_LOG           P1210                      713       113970
TIP_NGCRMRECEIVE_LOG           P1211                      713       113978
TIP_NGCRMRECEIVE_LOG           P1212                      713       113986
TIP_NGCRMRECEIVE_LOG           P1301                      713       113994
TIP_NGCRMRECEIVE_LOG           P1302                      713       114002
TIP_NGCRMRECEIVE_LOG           P1303                      713       114010
TIP_NGCRMRECEIVE_LOG           P1304                      713       114018
TIP_NGCRMRECEIVE_LOG           P1305                      713       114026
TIP_NGCRMRECEIVE_LOG           P1306                      713       114034
TIP_NGCRMRECEIVE_LOG           P1307                      713       114042
TIP_NGCRMRECEIVE_LOG           P1308                      672       137466
TIP_NGCRMRECEIVE_LOG           P1309                      679       105914
TIP_NGCRMRECEIVE_LOG           P1310                      679       105922
TIP_NGCRMRECEIVE_LOG           P1311                      679       105930
TIP_NGCRMRECEIVE_LOG           P1312                      679       105938
TIP_NGCRMRECEIVE_LOG           P1401                      695       648170
TIP_NGCRMRECEIVE_LOG           P1402                      695       648210
TIP_NGCRMRECEIVE_LOG           P1403                      695       648250
TIP_NGCRMRECEIVE_LOG           P1404                      695       648314
TIP_NGCRMRECEIVE_LOG           P1405                      695       648330
TIP_NGCRMRECEIVE_LOG           P1406                      695       648378
TIP_NGCRMRECEIVE_LOG           P1407                      695       648426
TIP_NGCRMRECEIVE_LOG           P1408                      695       648450
TIP_NGCRMRECEIVE_LOG           P1409                      695       648490
TIP_NGCRMRECEIVE_LOG           P1410                      695       648538
TIP_NGCRMRECEIVE_LOG           P1411                      710       118098    =>118103
TIP_NGCRMRECEIVE_LOG           P1412                      695       648610    =>648615
TIP_NGCRMRECEIVE_LOG           P1501                      695       648650    =>648655
TIP_NGCRMRECEIVE_LOG           P1502                      695       648690    =>648695
TIP_NGCRMRECEIVE_LOG           P1503                      695       648730    =>648735
TIP_NGCRMRECEIVE_LOG           P1504                      695       648770    =>648775
TIP_NGCRMRECEIVE_LOG           P1505                      695       648810    =>648815
TIP_NGCRMRECEIVE_LOG           P1506                      695       648850
TIP_NGCRMRECEIVE_LOG           P1507                      695       648890
TIP_NGCRMRECEIVE_LOG           P1508                      695       648930
TIP_NGCRMRECEIVE_LOG           P1509                      695       648970
TIP_NGCRMRECEIVE_LOG           P1510                      695       649010
TIP_NGCRMRECEIVE_LOG           P1511                      695       649050
TIP_NGCRMRECEIVE_LOG           P1512                      695       649090
TIP_NGCRMRECEIVE_LOG           P1601                      695       649098

select SEGMENT_NAME,PARTITION_NAME,HEADER_FILE,HEADER_BLOCK from dba_segments where SEGMENT_NAME='TOM_BO_INSTANCE_HIS' order by PARTITION_NAME;

SEGMENT_NAME                             PARTITION_NAME                 HEADER_FILE HEADER_BLOCK
---------------------------------------- ------------------------------ ----------- ------------
TOM_BO_INSTANCE_HIS                      P1212                                  763       110738
TOM_BO_INSTANCE_HIS                      P1301                                  763       110746
TOM_BO_INSTANCE_HIS                      P1302                                  763       110754
TOM_BO_INSTANCE_HIS                      P1303                                  763       110762
TOM_BO_INSTANCE_HIS                      P1304                                  763       110770
TOM_BO_INSTANCE_HIS                      P1305                                  763       110778
TOM_BO_INSTANCE_HIS                      P1306                                  763       110786
TOM_BO_INSTANCE_HIS                      P1307                                  763       110794
TOM_BO_INSTANCE_HIS                      P1308                                  763       110802
TOM_BO_INSTANCE_HIS                      P1309                                  763       110810
TOM_BO_INSTANCE_HIS                      P1310                                  763       110818
TOM_BO_INSTANCE_HIS                      P1311                                  763       110826
TOM_BO_INSTANCE_HIS                      P1312                                  763       110834
TOM_BO_INSTANCE_HIS                      P1401                                  695       652162
TOM_BO_INSTANCE_HIS                      P1402                                  695       654354
TOM_BO_INSTANCE_HIS                      P1403                                  696       588266
TOM_BO_INSTANCE_HIS                      P1404                                  696       588370
TOM_BO_INSTANCE_HIS                      P1405                                  695       657586   => 657591
TOM_BO_INSTANCE_HIS                      P1406                                  695       658706   => 658711
TOM_BO_INSTANCE_HIS                      P1407                                  695       658802   => 658807
TOM_BO_INSTANCE_HIS                      P1408                                  696       588498   => 588503
TOM_BO_INSTANCE_HIS                      P1409                                  695       661938   => 661943
TOM_BO_INSTANCE_HIS                      P1410                                  695       663058   => 663063
TOM_BO_INSTANCE_HIS                      P1411                                  695       663154   => 663159
TOM_BO_INSTANCE_HIS                      P1412                                  696       588626   => 588631
TOM_BO_INSTANCE_HIS                      P1501                                  695       666290   => 666295
TOM_BO_INSTANCE_HIS                      P1502                                  695       667410
TOM_BO_INSTANCE_HIS                      P1503                                  695       667506
TOM_BO_INSTANCE_HIS                      P1504                                  696       588754   =>588759
TOM_BO_INSTANCE_HIS                      P1505                                  695       670642   =>670647
TOM_BO_INSTANCE_HIS                      P1506                                  695       671762
TOM_BO_INSTANCE_HIS                      P1507                                  695       671858
TOM_BO_INSTANCE_HIS                      P1508                                  696       641234
TOM_BO_INSTANCE_HIS                      P1509                                  695       674994
TOM_BO_INSTANCE_HIS                      P1510                                  695       676114
TOM_BO_INSTANCE_HIS                      P1511                                  695       676210
TOM_BO_INSTANCE_HIS                      P1512                                  696       641362
TOM_BO_INSTANCE_HIS                      P1601                                  696       641370

然后执行dump命令dump出数据块,注意不是段头块,一般将块号增加几个,我这里增加的是5

SQL> oradebug setmypid
Statement processed.
SQL> oradebug tracefile_name
/oracle/database/diag/rdbms/integ/integ3/trace/integ3_ora_26183.trc
SQL> alter system dump datafile 695 block 661943

通过trace文件搜索obj查到相关的obj号码,然后转换成10进制

seg/obj: 0x70f31 =>462641

6.然后再AUL中用LIST命令获取执行代码

AUL> list table pboss
UNLOAD TABLE pboss.ZH0914 TO ZH0914.txt;
UNLOAD TABLE pboss.TOM_WORK_ORDER_HANG_UP TO TOM_WORK_ORDER_HANG_UP.txt;
UNLOAD TABLE pboss.TIP_ZXTV_INFO TO TIP_ZXTV_INFO.txt;
UNLOAD TABLE pboss.TIP_BESTTV_LOG_HIS TO TIP_BESTTV_LOG_HIS.txt;
UNLOAD TABLE pboss.TRMAP_EXEC_ORDER_HIS TO TRMAP_EXEC_ORDER_HIS.txt;
UNLOAD TABLE pboss.TMID_POWER_ALLDEVICE TO TMID_POWER_ALLDEVICE.txt;

7.执行获取代码,中间要加上object编号

UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1411 object 462641 TO TIP_NGCRMRECEIVE_LOG_P1411.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1412 object 462655 TO TIP_NGCRMRECEIVE_LOG_P1412.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1501 object 462669 TO TIP_NGCRMRECEIVE_LOG_P1501.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1502 object 462683 TO TIP_NGCRMRECEIVE_LOG_P1502.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1503 object 462697 TO TIP_NGCRMRECEIVE_LOG_P1503.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1504 object 462711 TO TIP_NGCRMRECEIVE_LOG_P1504.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1505 object 3019673 TO TIP_NGCRMRECEIVE_LOG_P1505.txt;
UNLOAD TABLE PBOSS.TIP_NGCRMRECEIVE_LOG PARTITION P1505 object 462725 TO TIP_NGCRMRECEIVE_LOG_P15052.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1405 object 463223 TO TOM_BO_INSTANCE_HIS_P1405.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1406 object 463239 TO TOM_BO_INSTANCE_HIS_P1406.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1407 object 463255 TO TOM_BO_INSTANCE_HIS_P1407.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1408 object  TO TOM_BO_INSTANCE_HIS_P1408.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1409 object 463287 TO TOM_BO_INSTANCE_HIS_P1409.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1410 object 463303 TO TOM_BO_INSTANCE_HIS_P1410.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1411 object 463319 TO TOM_BO_INSTANCE_HIS_P1411.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1412 object 463335 TO TOM_BO_INSTANCE_HIS_P1412.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1501 object 463351 TO TOM_BO_INSTANCE_HIS_P1501.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1502 TO TOM_BO_INSTANCE_HIS_P1502.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1503 TO TOM_BO_INSTANCE_HIS_P1503.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1504 object 463399 TO TOM_BO_INSTANCE_HIS_P1504.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1505 object 3019551 TO TOM_BO_INSTANCE_HIS_P1505.txt;
UNLOAD TABLE pboss.TOM_BO_INSTANCE_HIS PARTITION P1505 object 463415 TO TOM_BO_INSTANCE_HIS_P15052.txt;

8.到AUL目录下执行导入数据,注意修改表空间和表名

sqlplus dbmon/dbmon123 @TIP_NGCRMRECEIVE_LOG_syntax.sql
sqlldr dbmon/dbmon123 control=TIP_NGCRMRECEIVE_LOG_P1411_sqlldr.ctl
TIP_NGCRMRECEIVE_LOGp1412
TIP_NGCRMRECEIVE_LOGP1412

ORA-00494: enqueue [CF] held for too long (more than 900 seconds)问题分析

数据库在下午13点05分左右爆发了ORA-00494: enqueue [CF] held for too long (more than 900 seconds)问题,最终导致数据库异常宕机,通过对日志的分析发现下列信息:

Errors in file /u01/oracle/admin/cppicids/bdump/cppicids_lgwr_168278.trc: ORA-00494: enqueue [CF] held for too long (more than 900 seconds) (more than 900 seconds) by inst 1, osid 270814')
Thu Jun 11 13:05:21 2015System State dumped to trace file /u01/oracle/admin/cppicids/bdump/cppicids_lgwr_168278.trcKilling enqueue blocker (pid=270814) on resource CF-00000000-00000000 by killing session 882.1Killing enqueue blocker (pid=270814) on resource CF-00000000-00000000 by terminating the processLGWR: terminating instance due to error 2103

从中我们可以看到进程270814持有cf锁达到900秒,最终引发lgwr终止了实例,并抛出了错误代码2103。我们进一步分析lgwr的trace,发现下列信息。

SO: 700000e74329590, type: 2, owner: 0, flag: INIT/-/-/0x00
  (process) Oracle pid=5, calls cur/top: 700000e754de920/700000e754de920, flag: (6) SYSTEM
            int error: 0, call error: 0, sess error: 0, txn error 0
  (post info) last post received: 0 0 24
              last post received-location: ksasnd
              last process to post me: 700000e74329d70 1 6
              last post sent: 0 0 24
              last post sent-location: ksasnd
              last process posted by me: 700000e74329d70 1 6
  (latch info) wait_event=0 bits=0
    Process Group: DEFAULT, pseudo proc: 700000e76341580
    O/S info: user: oracle, term: UNKNOWN, ospid: 270814 
    OSD pid info: Unix process pid: 270814, image: oracle@CXIDSDBBAK (DBW0)
Dump of memory from 0x0700000E7430F978 to 0x0700000E7430FB80
SO: 700000e75474ba0, type: 4, owner: 700000e74329590, flag: INIT/-/-/0x00
  (session) sid: 882 trans: 0, creator: 700000e74329590, flag: (51) USR/- BSY/-/-/-/-/-
            DID: 0001-0005-00000005, short-term DID: 0000-0000-00000000
            txn branch: 0
            oct: 0, prv: 0, sql: 0, psql: 0, user: 0/SYS
  waiting for 'kcbzps' blocking sess=0x0 seq=64993 wait_time=0 seconds since wait started=60
          =0, =0, =0
  Dumping Session Wait History
   for 'kcbzps' count=1 wait_time=1102055
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97670
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97671
          =0, =0, =0
   for 'kcbzps' count=1 wait_time=97666

我们可以看到270814进程是dbw0进程,也就是数据写入进程。它的历史和现在的等待事件都是’kcbzps’,等待的时间非常之长,也就是说dbw0进程一直在等待。
我们在看一下dbw0持有的队列信息。

    SO: 700000e7350ce88, type: 5, owner: 700000e754de920, flag: INIT/-/-/0x00
      (enqueue) CF-00000000-00000000    DID: 0001-0005-00000005
      lv: 02 0f dd 46 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x2
      res: 0x700000e764b2458, mode: S, lock_flag: 0x0
      own: 0x700000e75474ba0, sess: 0x700000e75474ba0, proc: 0x700000e74329590, prv: 0x700000e764b2468

  SO: 700000e735123b0, type: 5, owner: 700000e000040d8, flag: INIT/-/-/0x00
      (enqueue) CF-00000000-00000000    DID: 0001-00B9-0000C7C5
      lv: 02 0f dd 46 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x2
      res: 0x700000e764b2458, req: SSX, lock_flag: 0x0
      own: 0x700000e74468560, sess: 0x700000e74468560, proc: 0x700000e7433f7f0, prv: 0x700000e764b2478

我们可以看到我们的dbw0进程以s模式持有了CF-00000000-00000000锁,而另外一个进程想以X模式来持有它。我们来看看是什么进程。

 (session) sid: 659 trans: 0, creator: 700000e7433f7f0, flag: (c0000041) USR/- BSY/-/-/-/-/-
              DID: 0001-00B9-0000C7C5, short-term DID: 0000-0000-00000000
              txn branch: 0
              oct: 47, prv: 0, sql: 700000e47f92088, psql: 700000e47f92088, user: 0/SYS
    service name: SYS$USERS
    O/S info: user: oracle, term: , ospid: 1798860, machine: CXIDSDBBAK
              program: rman@CXIDSDBBAK (TNS V1-V3)
    application name: rman@CXIDSDBBAK (TNS V1-V3), hash value=3432807229
    action name: 0000001 FINISHED70, hash value=706507012
    waiting for 'enq: CF - contention' blocking sess=0x700000e75474ba0 seq=131 wait_time=0 seconds since wait started=0
                name|mode=43460005, 0=0, operation=0
    Dumping Session Wait History
     for 'enq: CF - contention' count=1 wait_time=2929718
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929703
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929700
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929699
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929699
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929709
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929702
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929700
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929700
                name|mode=43460005, 0=0, operation=0
     for 'enq: CF - contention' count=1 wait_time=2929701
                name|mode=43460005, 0=0, operation=0

通过trace我们发现是用户发起的rman进程需要以x模式获取cf锁,而此时我们的cf锁是被dbw0以s模式持有着,正常情况是能释放的,而dbw0进程因为等待’kcbzps’导致无法正常释放的。此时我们前台的rman进程的等待事件是enq: CF – contention。
一、 解决办法
根据错误号和相关的等待事件’kcbzps’我们可以发现文档ORA-00494: enqueue [CF] held for too long (more than 900 seconds); LGWR:Terminating Instance Due to Error 2103 (Doc ID 1089733.1)是比较符合我们的情况的
该问题提到了4中情况:
1) Starts with space error and file offline
2) Sessions are waiting for CF enqueue
3) Arguments ksliwat   kslwaitns_timed  kskthbwt  kslwait… match that in the call stack of bug
4) There is a wait on kcbzps and occurs with DBWR
我们和第四种情况匹配,为了进一步证实这个问题,我们在通过文档提到的堆栈来进行对比。
如下图所示,文档中提到的堆栈如下:
123qaz
我们trace中相关堆栈如下图:
123wsx
通过对比,堆栈是一致的。也就是印证了这个问题。
那么解决办法是安装Apply Patch 7411568。而这个数据库的PSU较高,最好先检查PSU中是否包含该补丁,如果包含此补丁,需要确认补丁相关的文件是否损坏,损坏了可以重新单独对这个补丁安装,如果没有可以立即安装这个补丁。

Enq: RO – fast object reuse问题处理

应用会话在ybtdb2数据库执行Truncate操作无法成功,数据库出现异常等待事件“enq: RO – fast object reuse”。出现异常等待期间数据库主机资源使用正常。为了进一步分析问题,对该进程做了errorstack,errorstack trace文件如下:

SO: 70000050fc93af8, type: 4, owner: 70000050f8d63d8, flag: INIT/-/-/0x00
    (session) sid: 1103 trans: 7000004f99b71a8, creator: 70000050f8d63d8, flag: (100041) USR/- BSY/-/-/-/-/-
              DID: 0002-0227-00001ECA, short-term DID: 0002-0227-00001ECB
              txn branch: 0
              oct: 170, prv: 0, sql: 7000004cd3ff508, psql: 7000004cd3ff508, user: 35/YBT
    service name: ybtdb
    O/S info: user: ybtcenter, term: , ospid: 15266, machine: ybtapp2
              program: loadidsdata@ybtapp2 (TNS V1-V3)
    client info: 10.190.115.2
    application name: loadidsdata@ybtapp2 (TNS V1-V3), hash value=227635376
    waiting for 'enq: RO - fast object reuse' blocking sess=0x0 seq=15114 wait_time=0 seconds since wait started=278032
                name|mode=524f0006, 2=20227, 0=1
    Dumping Session Wait History
     for 'enq: RO - fast object reuse' count=1 wait_time=488301
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488295
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488299
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488293
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488292
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488290
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488291
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488292
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488296
                name|mode=524f0006, 2=20227, 0=1
     for 'enq: RO - fast object reuse' count=1 wait_time=488299
                name|mode=524f0006, 2=20227, 0=1
    temporary object counter: 0

可以看到该会话一直在等待enq: RO – fast object reuse,且等待时间较长。

----- PL/SQL Call Stack -----
  object      line  object
  handle    number  name
7000004cde152e0       909  package body SYS.DBMS_SYS_SQL
7000004cde15990        39  package body SYS.DBMS_SQL
70000050e323ca8         7  procedure YBT.TRUNCATE_TABLE
----- Call Stack Trace -----
ksliwat+06c0         bl       skgpwwait            FFFFFFFFFFEB1F0 ? 000000000 ?
                                                   103AC4EF8 ? 000000000 ?
                                                   FFFFFFFFFFEB1F0 ?
kslwaitns_timed+002  bl       ksliwat              000000000 ? 000000000 ?
4                                                  000000000 ? 000000000 ?
                                                   000000000 ? 000000000 ?
                                                   000000000 ? 000000000 ?
kskthbwt+022c        bl       kslwaitns_timed      000000004 ? 000000000 ?
                                                   FFFFFFFFFFEBE20 ? 000000000 ?
                                                   3784759F126D58 ? 000000061 ?
                                                   FFFFFFFFFFEB530 ? 000000000 ?
kslwait+00f4         bl       kskthbwt             3200000032 ? 4900000049 ?
                                                   000000000 ? 0524F0006 ?
                                                   000020227 ? 000000001 ?
                                                   E00000000000E ?
                                                   6955278669552786 ?
kjuscv+0ad0          bl       kslwait              FFFFFFFFFFEB704 ? 200000003 ?
                                                   5000001101960E8 ? 700000000 ?
                                                   000000020 ? 000000000 ?
ksipcon+041c         bl       kjuscv               700000509346A00 ?
                                                   50000010564B0D0 ?
                                                   61FFFFFFBF ? 0FFFFFEFF ?
                                                   FFFFFFFFFFEBE20 ? 000000000 ?
                                                   000000000 ? FFFFFFFFFFEBD4C ?
ksqcmi+0e14          bl       ksipcon              10564B8E4 ? 10564B8F0 ?
                                                   10564B928 ? 10564B914 ?
                                                   10564B908 ? 080000004 ?
                                                   10564B940 ? 10564B934 ?
ksqcnv+030c          bl       ksqcmi               70000050B0D3DF8 ? 600000000 ?
                                                   FFFF0011BD18 ?
                                                   147AE140B4A3EC8 ?
                                                   FFFFFFFFFFED260 ?
                                                   FFFFFFFFFFED4B0 ? 000000004 ?
                                                   110001248 ?
ksqcov+0034          bl       ksqcnv               FFFFFFFFFFED84C ? 000000000 ?
                                                   FFFFFFFFFFED844 ? 000000001 ?
                                                   000000001 ? 000020227 ?
                                                   00147AE14 ?
kcbo_reuse_obj+0880  bl       01F94504             
kcbrbo+00bc          bl       01F93AE0             
ktsstrn_segment+0f6  bl       kcbrbo               FFFFFFFFFFEE0C0 ? 000000000 ?
c                                                  7000004BD28E470 ?
kkbtts_trunc_tbl_se  bl       ktsstrn_segment      FFFFFFFFFFEE0C0 ? 02CC03F1D ?
g+04b8                                             000000000 ? 0FFFEE268 ?
                                                   064232020 ? 064232020 ?
kkbtrn+13f8          bl       kkbtts_trunc_tbl_se  047548A48 ? 7000004BD28E318 ?
                              g                    000000000 ? 1FFFEE7A0 ?
                                                   7000004D42A5D88 ?
                                                   700000443A513F0 ?
                                                   3000000000003 ?
opiexe+317c          bl       kkbtrn

通过观察堆栈发现是在执行Truncate语句,执行过程中采取了下列调用。

kslwaitns_timed -> kskthbwt -> kslwait -> kjuscv -> ksipcon -> ksqcmi -> ksipcon -> ksqcnv -> ksqcov -> kcbo_reuse_obj -> kcbrbo -> ktsstrn_segment -> kkbtts_trunc_tbl_se

通过metalink note进行搜索,找到了文档Process waits too long for ‘enq: RO – fast object reuse’. Cause: CKPT Process Bug 7385253 (文档 ID 785232.1)里面的文档中的Call Stack和我们的类似。文档中指出的Call Stack如下所示:

kslwaitns_timed kskthbwt kslwait ksqcmi ksqcnv ksqcov kcbo_reuse_obj kcbrbo ..etc

同时可以观察队列资源的情况。

----------resource 0x7000004c3fb9410----------------------
resname       : [0x20227][0x1],[RO]
GRANTED_Q :
lp 70000050bce5f40 gl KJUSERCR rp 7000004c3fb9410 [0x20227][0x1],[RO]
  master 1 gl owner 70000050cd9d4d0 possible pid 2064446 xid 2001-0013-00000005 bast 0 rseq 15 mseq 0 history 0x95514955
  open opt KJUSERDEADLOCK  KJUSERIDLK 
CONVERT_Q: 
lp 700000509346a00 gl KJUSERPW rl KJUSEREX rp 7000004c3fb9410 [0x20227][0x1],[RO]
  master 1 gl owner 70000050fc93af8 possible pid 1159360 xid 2022-0227-00001ECA bast 0 rseq 15 mseq 0 history 0x5514955a
  convert opt KJUSERGETVALUE KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK

可以看到该队列和pid 2064446和pid 1159360有关。

SO: 70000050b0d3dd8, type: 5, owner: 700000481adb5a0, flag: INIT/-/-/0x00
        (enqueue) RO-00020227-00000001  DID: 0002-0227-00001ECA
        lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  res_flag: 0x3
        res: 0x70000050a15e320, mode: SSX, req: X, lock_flag: 0x0
        own: 0x70000050fc93af8, sess: 0x70000050fc93af8, proc: 0x70000050f8d63d8, prv: 0x70000050a15e350
        slk: 0x700000509346a00

possible owner[19.2064446] on resource RO-00020227-00000001

继续分析可以发现pid 1159360以X模式在请求持有队列RO-00020227-00000001。pid 1159360正是发起truncate的会话进程。而队列RO-00020227-00000001是被pid 2064446所持有的。而通过查询2064446发现是ckpt进程。

[jtdba@sxybtdb2 ~]$ps -ef | grep ckpt
   jtdba 1581064 2146438   0 14:30:52  pts/0  0:00 grep ckpt 
  oracle 2064446       1   0   Dec 21      - 28:02 ora_ckpt_ybtdb2

问题解决
建议安装单独的patch 7385253来规避这个问题.
建议将数据库升级到11.2来规避此问题.11.2以上的版本才修复了该问题.

ORA-00600: 内部错误代码, 参数: [4442], [0x7000008A7C22EF8], [53]问题分析

数据库突然异常宕机。查看后台alert日志,PMON进程出现致命错误,报ORA-00600[4442]错误。

Thu Jan 22 11:04:46 2015 
Thread 1 advanced to log sequence 442095 
Current log# 8 seq# 442095 mem# 0: /p09bp_mm/mm_u01/mm/redo08_a.log 
Current log# 8 seq# 442095 mem# 1: /p09bp_mm/mm_u02/mm/redo08_b.log 
Thu Jan 22 11:07:27 2015 
Errors in file /u01/oracle/admin/mm/bdump/mm_pmon_1757288.trc: 
ORA-00600: 内部错误代码, 参数: [4442], [0x7000008A7C22EF8], [53], [], [], [], [], [] 
Thu Jan 22 11:07:30 2015 
Errors in file /u01/oracle/admin/mm/bdump/mm_pmon_1757288.trc: 
ORA-00600: 内部错误代码, 参数: [4442], [0x7000008A7C22EF8], [53], [], [], [], [], [] 
Thu Jan 22 11:07:30 2015 
PMON: terminating instance due to error 472 
Termination issued to instance processes. Waiting for the processes to exit 
Thu Jan 22 11:07:40 2015 
Instance termination failed to kill one or more processes 
Instance terminated by PMON, pid = 1757288 
Thu Jan 22 11:23:06 2015 
Starting ORACLE instance (normal) 
LICENSE_MAX_SESSION = 0 
LICENSE_SESSIONS_WARNING = 0 
Picked latch-free SCN scheme 3 
Autotune of undo retention is turned on.

为了进一步研究PMON进程为何突发异常,我们需要研究PMON的Trace文件。

PROCESS STATE 
------------- 
Process global information: 
process: 7000008ca28f5b8, call: 7000008cb3d54e8, xact: 0, curses: 7000008c93d0c10, usrses: 7000008c93d0c10 
---------------------------------------- 
SO: 7000008ca28f5b8, type: 2, owner: 0, flag: INIT/-/-/0x00 
(process) Oracle pid=2, calls cur/top: 7000008cb3d54e8/7000008cb3d54e8, flag: (e) SYSTEM 
int error: 0, call error: 0, sess error: 0, txn error 0 
(post info) last post received: 0 0 15 
last post received-location: ksupsc 
last process to post me: 7000008ca28fd98 1 6 
last post sent: 0 0 147 
last post sent-location: ktmpsm 
last process posted by me: 7000008cf28ba40 1 22 
(latch info) wait_event=0 bits=40 
holding (efd=4) 70000001001c670 transaction branch allocation level=6 
Location from where latch is held: ktcxdp: 
Context saved from call: 0 
state=busy, wlstate=free 
waiters [orapid (seconds since: put on list, posted, alive check)]: 
213 (0, 1421896047, 0) 
190 (0, 1421896047, 0) 
134 (0, 1421896047, 0) 
41 (0, 1421896047, 0) 
113 (0, 1421896047, 0) 
146 (0, 1421896047, 0) 
131 (0, 1421896047, 0) 
137 (0, 1421896047, 0) 
32 (0, 1421896047, 0) 
waiter count=9 
Process Group: DEFAULT, pseudo proc: 7000008ce30e4d0 
O/S info: user: oracle, term: UNKNOWN, ospid: 1757288 
OSD pid info: Unix process pid: 1757288, image: oracle@CXSFDB1 (PMON) 

可以看到PMON进程的trace显示Location from where latch is held: ktcxdp。也就是在执行函数ktcxdp的时候出现了latch的阻塞。导致pmon进程被堵塞。而pmon的进一步堵塞导致了9个会话被堵。

而Trace里面的函数堆栈显示:

----- Call Stack Trace ----- 
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
ksedst+001c          bl       ksedst1              0FFFFFFFF ? 000000020 ?
ksedmp+0290          bl       ksedst               104811CB8 ?
ksfdmp+0018          bl       03F40AE0             
kgeriv+0108          bl       _ptrgl               
kgesiv+0080          bl       kgeriv               1048E451C ? 1048E451C ?
                                                   1048E451C ? 1048E451C ?
                                                   1048E451C ?
ksesic2+0060         bl       kgesiv               000000002 ? 054C0696F ?
                                                   000000001 ? 70000001001C670 ?
                                                   1104D3E80 ?
ktcxdp+0344          bl       ksesic2              115A0000115A ? 000000002 ?
                                                   7000008A7C22EF8 ? 000000000 ?
                                                   000000035 ? 00011D1D3 ?
                                                   000000000 ? 000000000 ?
ksucln+0938          bl       ktcxdp               
ksbrdp+03e0          bl       _ptrgl               
opirip+03fc          bl       01FAFCBC             
opidrv+0448          bl       opirip               11029E590 ? 41029FED0 ?
                                                   FFFFFFFFFFFF6D0 ?
sou2o+0090           bl       opidrv               32031840FC ? 4A0170928 ?
                                                   FFFFFFFFFFFF6D0 ?
opimai_real+0150     bl       01FAB1B4             
main+0098            bl       opimai_real          000000000 ? 000000000 ?
__start+0098         bl       main                 000000000 ? 000000000 ?

ksedst <- ksedmp <- ksfdmp <- kgeriv <- kgesiv 
<- ksesic2 <- ktcxdp <- ksucln <- ksbrdp <- opirip 
<- opidrv <- sou2o <- opimai_real <- main <- start 

通过metalink note进行搜索,找到了文档Database Crashed After ORA-600 [4442] (文档 ID 368877.1)里面的文档中的Call Stack和我们的类似。而文档中指出的Call Stack如下所示:

ORA-600 [4442] is signalled by PMON, with the stack trace:
ktcxdp <- ksucln <- ksbrdp <- opirip <- opidrv <- sou2o

因此我们可以确定命中了Bug 4891103 'INSTANCE DOWN OWING TO ORA-600 [4442]'. This is due to PMON cleaning up a distributed transaction incorrectly.那么这个问题就出在我们的PMON去清理分布式事务的时候触发的。为了进一步确认分布式事务引起的问题,我们还在PMON的trace中看到下列信息。

B0BB3C91:3BDB1F4E    12  1315 10254  71 KSBCTI: (RECO) : (interrupt action) : acnum=[1] comment=[KSB action for X-instance calls]
B0BB3C9D:3BDB1F4F    12  1315 10254  71 KSBCTI: (RECO) : (interrupt action) : acnum=[63] comment=[Scumnt mount lock]
B0BB3C9E:3BDB1F50    12  1315 10254  71 KSBCTI: (RECO) : (interrupt action) : acnum=[64] comment=[Poll system events broadcast channel]
B0BB3CA1:3BDB1F51    12  1315 10254  73 KSBCTI: (RECO) : (timeout action)   : acnum=[0] comment=[Monitor Cleanup]
B0BB3CD9:3BDB1F52    12  1315 10254  73 KSBCTI: (RECO) : (timeout action)   : acnum=[119] comment=[distributed recovery wakeup]
B0BB3E0F:3BDB1F53    12  1315 10254  71 KSBCTI: (RECO) : (interrupt action) : acnum=[1] comment=[KSB action for X-instance calls]

这里可以看到我们的reco的进程也是被唤醒过的,恢复进程recoverer process (RECO)用于分布式数据库结构,自动解决分布式事务的错误。但是因为数据库异常宕机,通过trace文件无法定位到具体的分布式SQL语句。
问题解决

  1. 建议安装单独的patch 4891103来规避这个问题.
  2. 目前版本是10.2.0.2,在10.2.0.3上已经修复该问题,建议升级到10.2.0.5以上的版本.
  3. 通过dba_2pc_pengding视图监控相关的分布式事务,找出引发异常2pc事务的源头。
  4. 文档126069.1给出了一个手动解决有问题的分布式事务的方法。NOTE:126069.1 - Manually Resolving In-Doubt Transactions: Different Scenarios

Latch row cache object问题分析

客户的系统,先后发生了几次Latch:row cache object等待,该等待会导致CPU迅速达到100%。

SQL> select event,p1,P1RAW from v$session where event='latch: row cache objects';
EVENT                                                P1 P1RAW
-------------------------------------------- ---------- ----------------
latch: row cache objects                     5.0440E+17 07000018A74C3918
latch: row cache objects                     5.0440E+17 07000018A74C3918
latch: row cache objects                     5.0440E+17 07000018A74C3918
latch: row cache objects                     5.0440E+17 07000018A74C3918
latch: row cache objects                     5.0440E+17 07000018A74C3918
latch: row cache objects                     5.0440E+17 07000018A74C3918
latch: row cache objects                     5.0440E+17 07000018A74C3918
latch: row cache objects                     5.0440E+17 07000018A74C3918
latch: row cache objects                     5.0440E+17 07000018A74C3918

我们可以从p1raw的值中可以看到,几乎全部的p1raw等待的地址都是07000018A74C3918。继续通过这个地址查询基表,我们发现全部的等待都集中在数据字典dc_user上。

SQL> SELECT kqrsttxt PARAMETER, kqrstcid CACHE#, kqrstcln "Lchild#", kqrstgrq "DCGets", l.gets   "LGets", l.misses "Misses"  FROM X$KQRST, V$LATCH_CHILDREN l WHERE l.addr='07000018A74C3918' and l.child#=KQRSTCLN ORDER BY 1,2;
PARAMETER            CACHE#    Lchild#     DCGets      LGets     Misses
--------------------------- ---------- ---------- ---------- ----------
dc_users                  7          7 -432944865 2494354363 3396983919
dc_users                  7          7          0 2494354363 3396983919
dc_users                  7          7 -488978240 2494354363 3396983919
dc_users                  7          7    6423076 2494354363 3396983919

出问题时间段AWR报告的情况。latch: row cache objects占据了整个等待的53.5%

Top 5 Timed Events

Event

Waits

Time(s)

Avg Wait(ms)

% Total Call Time

Wait Class

latch: row cache objects

3,074,567

292,212

95

53.5

Concurrency
CPU time

147,945

27.1

db file sequential read

4,342,112

37,436

9

6.9

User I/O
gc buffer busy

2,573,835

10,621

4

1.9

Cluster
read by other session

493,143

2,536

5

.5

User I/O

数据字典使用情况

Dictionary Cache Stats

  • “Pct Misses” should be very low (< 2% in most cases)
  • “Final Usage” is the number of cache entries being used

Cache

Get Requests

Pct Miss

Scan Reqs

Pct Miss

Mod Reqs

Final Usage

dc_awr_control

148

0.00

0

2

1

dc_database_links

2,361

0.00

0

0

1

dc_files

36,460

0.00

0

0

3,646

dc_global_oids

2,833

0.28

0

0

30

dc_histogram_data

36,128

3.26

0

0

30,437

dc_histogram_defs

54,038

3.81

0

0

28,382

dc_object_grants

652

3.07

0

0

65

dc_object_ids

94,802

0.32

0

0

4,453

dc_objects

8,349

3.03

0

59

2,702

dc_profiles

1,176

0.00

0

0

2

dc_rollback_segments

961,666

0.00

0

0

925

dc_segments

23,648

39.61

0

1,535

69,506

dc_sequences

739

82.14

0

739

224

dc_tablespace_quotas

4,865

4.07

0

0

162

dc_tablespaces

149,688

0.00

0

0

229

dc_usernames

24,338

0.00

0

0

979

dc_users

121,991,028

0.00

0

0

2,929

outstanding_alerts

2,735

97.95

0

6

452

 

正常时间段AWR报告

Top 5 Timed Events

Event

Waits

Time(s)

Avg Wait(ms)

% Total Call Time

Wait Class

db file sequential read

5,091,217

41,713

8

65.6

User I/O

CPU time

18,880

29.7

gc buffer busy

1,098,325

4,530

4

7.1

Cluster

db file scattered read

269,197

1,225

5

1.9

User I/O

db file parallel write

1,113,985

1,060

1

1.7

System I/O

正常时间段数据字典使用情况

Dictionary Cache Stats

  • “Pct Misses” should be very low (< 2% in most cases)
  • “Final Usage” is the number of cache entries being used

Cache

Get Requests

Pct Miss

Scan Reqs

Pct Miss

Mod Reqs

Final Usage

dc_awr_control

67

1.49

0

1

1

dc_database_links

2,801

0.00

0

0

1

dc_files

76,566

0.00

0

0

3,646

dc_global_oids

1,926

0.00

0

0

22

dc_histogram_data

22,093

5.27

0

0

29,261

dc_histogram_defs

26,514

6.77

0

0

27,758

dc_object_grants

96

0.00

0

0

45

dc_object_ids

91,305

0.15

0

0

4,229

dc_objects

5,241

1.74

0

74

2,599

dc_profiles

1,396

0.00

0

0

2

dc_rollback_segments

376,713

0.00

0

0

925

dc_segments

22,509

55.27

0

1,992

60,544

dc_sequences

676

86.09

0

676

243

dc_tablespace_quotas

6,815

2.61

0

0

163

dc_tablespaces

83,635

0.00

0

0

229

dc_usernames

22,585

0.00

0

0

978

dc_users

69,522,674

0.00

0

0

2,928

outstanding_alerts

2,730

98.02

0

0

5

 

经过正常时间段和异常时间段相比,发现dc_users的request的数量从69522674上升到了121991028次,多了一倍,正好和我们前面查询出的结果吻合。

通过MOS文档Heavy “latch: row cache objects” Contention on dc_objects and dc_users when Using Roles and System Level Grants (文档 ID 1639293.1)中间的描述。

Since a set of privileges grouped together in a role cannot be static and can change frequently, the role cannot be cached as a library_cache object. Additionally, because the role includes system level privileges it needs to be looked up during every execution of the cursor irrespective of whether it is cached or not.

Under heavy concurrent execution this can lead to high numbers or lookups for object privileges and cause ‘latch: row cache objects’ contention

If you are granting ‘GRANT ANY …’ privileges to users then, because of an optimization introduces in Bug 10023443, if you have thousands of different users executing RPCs without direct privileges then a large set of validation data has to be scanned taking a lot of time and leading to high row cache contention. Granting the privileges directly to the object avoids this contention.

Solution

If these symptoms occur, explicitly grant access to the underlying object to the user (not through the role):

这里提到如果用户不是当前的用户,而大批量执行会导致大量对对象权限的检查,引起latch:row cache objects,一个有效的避免办法就是直接赋予对象授权。

我们在看高并发一个时间段具体的情况,这里可以看到user_id集中在120上,总共有69个会话同一时间发起对不同对象的请求。

SQL> select USER_ID,to_char(sample_time,'YYYY-MM-DD HH24:MI:ss') atime,event,CURRENT_OBJ#
from dba_hist_active_sess_history where SNAP_ID >46342 and SNAP_ID<=46343 
and event='latch: row cache objects' and to_char(sample_time,'YYYY-MM-DD HH24:MI:ss')='2014-12-31 10:53:41' and CURRENT_OBJ# not in (-1,0);

   USER_ID ATIME               EVENT                                                            CURRENT_OBJ#
---------- ------------------- ---------------------------------------------------------------- ------------
       120 2014-12-31 10:53:41 latch: row cache objects                                              7956834
       120 2014-12-31 10:53:41 latch: row cache objects                                              7956834
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107750
       120 2014-12-31 10:53:41 latch: row cache objects                                              8435865
       120 2014-12-31 10:53:41 latch: row cache objects                                              7956834
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107765
       120 2014-12-31 10:53:41 latch: row cache objects                                              1855183
       120 2014-12-31 10:53:41 latch: row cache objects                                              8431388
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107772
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107741
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107747
       123 2014-12-31 10:53:41 latch: row cache objects                                              4924792
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107751
       123 2014-12-31 10:53:41 latch: row cache objects                                              5199531
       120 2014-12-31 10:53:41 latch: row cache objects                                              8431388
       120 2014-12-31 10:53:41 latch: row cache objects                                              8431389
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107762
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107770
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107758
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107762
       103 2014-12-31 10:53:41 latch: row cache objects                                              5138768
       123 2014-12-31 10:53:41 latch: row cache objects                                              4924792
       120 2014-12-31 10:53:41 latch: row cache objects                                              8428997
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107770
       120 2014-12-31 10:53:41 latch: row cache objects                                              8431319
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107749
       123 2014-12-31 10:53:41 latch: row cache objects                                              8470682
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107764
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107747
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107771
       120 2014-12-31 10:53:41 latch: row cache objects                                              8435513
       120 2014-12-31 10:53:41 latch: row cache objects                                              8472729
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107765
       123 2014-12-31 10:53:41 latch: row cache objects                                              2540191
       120 2014-12-31 10:53:41 latch: row cache objects                                              1882550
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107771
       120 2014-12-31 10:53:41 latch: row cache objects                                              6916742
       120 2014-12-31 10:53:41 latch: row cache objects                                              8428997
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107766
       120 2014-12-31 10:53:41 latch: row cache objects                                              1886171
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107767
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107754
       120 2014-12-31 10:53:41 latch: row cache objects                                              8164310
       120 2014-12-31 10:53:41 latch: row cache objects                                              1882543
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107752
       120 2014-12-31 10:53:41 latch: row cache objects                                              1855381
       120 2014-12-31 10:53:41 latch: row cache objects                                              1248853
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107726
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107756
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107750
       103 2014-12-31 10:53:41 latch: row cache objects                                              8427924
       120 2014-12-31 10:53:41 latch: row cache objects                                              8435865
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107754
       120 2014-12-31 10:53:41 latch: row cache objects                                              8428997
       120 2014-12-31 10:53:41 latch: row cache objects                                              8431388
       120 2014-12-31 10:53:41 latch: row cache objects                                              1855351
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107766
       120 2014-12-31 10:53:41 latch: row cache objects                                              1889082
       120 2014-12-31 10:53:41 latch: row cache objects                                              7624584
       120 2014-12-31 10:53:41 latch: row cache objects                                              8428997
       120 2014-12-31 10:53:41 latch: row cache objects                                              1855718
       123 2014-12-31 10:53:41 latch: row cache objects                                              4924792
       120 2014-12-31 10:53:41 latch: row cache objects                                              2540227
       120 2014-12-31 10:53:41 latch: row cache objects                                              8435865
       120 2014-12-31 10:53:41 latch: row cache objects                                              1905505
       120 2014-12-31 10:53:41 latch: row cache objects                                              3026654
       123 2014-12-31 10:53:41 latch: row cache objects                                              8157538
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107742
       120 2014-12-31 10:53:41 latch: row cache objects                                              8107747
69 rows selected.

查询user_id为120用户的权限情况

SQL> select username from dba_users where user_id=120; 
USERNAME
------------------------------
TUX_INTRFC

SQL> select * from dba_sys_privs where GRANTEE='TUX_INTRFC';

GRANTEE         PRIVILEGE                 ADMIN_
--------------- ------------------------- ------
TUX_INTRFC      SELECT ANY SEQUENCE       NO
TUX_INTRFC      ALTER ANY SEQUENCE        NO
TUX_INTRFC      ALTER SESSION             NO
TUX_INTRFC      CREATE SEQUENCE           NO
TUX_INTRFC      CREATE ANY INDEX          NO
TUX_INTRFC      SELECT ANY TABLE          NO
TUX_INTRFC      ALTER ANY TABLE           NO
TUX_INTRFC      CREATE ANY TABLE          NO
TUX_INTRFC      SELECT ANY DICTIONARY     NO
TUX_INTRFC      EXECUTE ANY INDEXTYPE     NO
TUX_INTRFC      ALTER ANY INDEX           NO
TUX_INTRFC      LOCK ANY TABLE            NO
TUX_INTRFC      CREATE ANY SEQUENCE       NO
TUX_INTRFC      DELETE ANY TABLE          NO
TUX_INTRFC      EXECUTE ANY PROCEDURE     NO
TUX_INTRFC      UPDATE ANY TABLE          NO
TUX_INTRFC      INSERT ANY TABLE          NO
TUX_INTRFC      UNLIMITED TABLESPACE      NO      

SQL> select * from dba_role_privs where GRANTEE='TUX_INTRFC';
GRANTEE         GRANTED_ROLE                                                 ADMIN_ DEFAUL
--------------- ------------------------------------------------------------ ------ ------
TUX_INTRFC      RESOURCE                                                     NO     YES
TUX_INTRFC      CONNECT                                                      NO     YES

SQL> select * from DBA_TAB_PRIVS where GRANTEE='TUX_INTRFC';
no rows selected

这里可以看到TUX_INTRFC用户只具备系统权限,而不具备对象权限。这就会导致文档1639293.1中描述的情况产生。

解决办法

首先查出具体问题时间段影响最多的用户。这里可以看到120用户是影响最多的。

SQL> select user_id,count(1) from dba_hist_active_sess_history where SNAP_ID >46342 and SNAP_ID<=46343
 and event='latch: row cache objects' group by user_id order by 2;

   USER_ID   COUNT(1)
---------- ----------
        53          1
       149          1
        71          2
       122          3
         0          4
        72          5
        74          5
        46          5
        70          6
        77          6
        75          6
        76          7
        73         10
        32         15
        64        107
        58        122
        62        124
        65        126
        59        127
        60        129
        66        130
        67        130
        55        131
        57        135
        69        136
        63        136
        56        140
        54        140
        68        146
        61        151
       103        217
       123       1573
       120      24998

出问题时间段120用户访问表对象。

SQL> select owner,object_name from 
  2  (
  3  select distinct CURRENT_OBJ#
  4  from dba_hist_active_sess_history where SNAP_ID >46342 and SNAP_ID<=46343
  5  and event='latch: row cache objects' and user_id=120 and CURRENT_OBJ# not in (1,0)
  6  ) b ,(select owner,object_name,object_type,object_id from dba_objects) a 
  7  where a.object_id = b.CURRENT_OBJ#
  8  and object_type='TABLE';

OWNER                          OBJECT_NAME
------------------------------ ------------------------------
FFPDUSER                       CP_KZH_MEMBER_INFO
FFPDUSER                       CP_KZH_FAMILY_INFO
FFPDUSER                       C_IDS_ID_CHGCON_TBL
FFPDUSER                       C_PRNT_CNTRCT_SUSPEND_CHNG_END
FFPDUSER                       C_IDS_ID_APP_POS_TBL
FFPDUSER                       C_IDS_PRE_CDELREC_TBL
FFPDUSER                       CP_GPS_RQSTING
FFPDUSER                       C_PRNT_SPEC_TERM_CHNG
FFPDUSER                       CP_CNTRCT_DETAIL
FFPDUSER                       CP_INTRFC_BIZUNIT_AUTH
FFPDUSER                       C_INTRFC_PREM_RENEW_TBL
FFPDUSER                       CT_QUA_EMPNO
FFPDUSER                       CP_FINANCIAL_DTL
FFPDUSER                       CP_PARTICIPATION
FFPDUSER                       CP_PAYROLL
FFPDUSER                       C_PRNT_ACCNT_STATEMENT
FFPDUSER                       CP_HISTORICAL_NOTE
FFPDUSER                       CP_CLAUSE
FFPDUSER                       C_IDS_ADDR_TBL
FFPDUSER                       C_IDS_SPREREC_TBL
FFPDUSER                       C_IDS_RISKCON_TBL
FFPDUSER                       CP_LIFE_SURVEY
FFPDCMS                        CP_ELECTRONIC_ADDR
FFPDUSER                       AGT_CREDIT_GRADE
FFPDUSER                       C_IDS_RISKCON_RENEW_TBL
FFPDUSER                       C_IDS_ACCTLIST_TBL
FFPDUSER                       C_IDS_PHONE_TBL
FFPDUSER                       C_IDS_PERSON_TBL
FFPDCPICDATA                   IDL_WL_PYEAR_PAY2010
FFPDUSER                       CP_PRSN_WEB
FFPDUSER                       C_APP_NB_TBL
FFPDUSER                       CP_ACCEPT_INFO
FFPDUSER                       C_PRNT_CNTRCT_REPAY_END
FFPDUSER                       C_PRNT_PRSN_MSG_CHNG_END
FFPDCPICDATA                   IDL_WL_PYEAR_PAY2009
FFPDCPICDATA                   IDL_WL_RISKBONUS_ENG
FFPDMASTER                     CD_CVRG_BENEFIT
FFPDMASTER                     CD_CLAUSE_LINK
FFPDMASTER                     CD_VARIABLE
FFPDUSER                       CP_CLOB_NO_DATE
FFPDUSER                       CP_CLOB_FULL_NO_PRPGT
FFPDUSER                       C_IDS_PARTY_BRANCH_RLSHIP_TBL
FFPDUSER                       CP_KZH_TJ_INQUIRY
FFPDUSER                       CP_KZH_TJ_PRODUCT
FFPDUSER                       C_INTRFC_WX_SMS_TBL
FFPDCMS                        CP_ORG
FFPDUSER                       CO_DISTRIBUTOR
FFPDUSER                       CP_CLAUSE_LINK
FFPDUSER                       CP_CVRG_BENEFIT_PAYOUT_DTL
FFPDUSER                       CP_DVDND_PAYOUT_DTL
FFPDUSER                       CP_LNK
FFPDUSER                       CP_LOAN
FFPDUSER                       CP_SECURITY_KEY_DISTRIBUTOR
FFPDUSER                       CP_STTLMNT_CVRG
FFPDUSER                       C_IDS_APP_NB_TBL
FFPDUSER                       C_IDS_MONEYSCH_TBL
FFPDUSER                       C_IDS_POLICYST_TBL
FFPDUSER                       C_IDS_TMPPAY_TBL

使用下列语法赋予相关对象权限

grant select on FFPDUSER.CP_KZH_MEMBER_INFO to TUX_INTRFC;
grant insert on FFPDUSER.CP_KZH_MEMBER_INFO to TUX_INTRFC;
grant update on FFPDUSER.CP_KZH_MEMBER_INFO to TUX_INTRFC;
grant delete on FFPDUSER.CP_KZH_MEMBER_INFO to TUX_INTRFC;

12C/11g asmlib导致ocr丢失恢复的全过程

一、问题背景

客户一套12C的数据库,CRS无法启动,经过简单的查看发现OCR的磁盘出现了问题。客户使用ASMLIB包实现将物理磁盘转换成Oracle能识别的ASM的磁盘。为了达到冗余的目的,客户使用了3块2G的物理盘用于创建OCR。默认情况下通过ASMLIB包绑定后,我们是应该可以看到可用的3个ASM磁盘的,但是不知道是什么原因,导致只能看到一个磁盘。

[10:21:17]grid@oracle12c01:/dev/oracleasm/disks> ls -l
[10:21:17]total 0
[10:21:17]brw-rw---- 1 grid asmadmin 8,  81 Jan 20 19:05 ASMDATA1
[10:21:17]brw-rw---- 1 grid asmadmin 8,  82 Jan 20 19:05 ASMDATA2
[10:21:17]brw-rw---- 1 grid asmadmin 8,  83 Jan 20 19:05 ASMDATA3
[10:21:17]brw-rw---- 1 grid asmadmin 8,  84 Jan 20 19:05 ASMDATA4
[10:21:17]brw-rw---- 1 grid asmadmin 8,  85 Jan 20 19:05 ASMDATA5
[10:21:17]brw-rw---- 1 grid asmadmin 8, 144 Jan 20 19:05 ASMOCR2G3

可以看到本来应该有ASMOCR2G1, ASMOCR2G2, ASMOCR2G3三个磁盘的,而现在只有ASMOCR2G3了。那么是不是磁盘头发生了损坏,导致我们不能识别呢?

[10:39:11]oracle12c01:~ # /oracle/app/12.1.0/grid/bin/kfed read /dev/mapper/emc2G01
[10:39:12]kfbh.endian:                          1 ; 0x000: 0x01
[10:39:12]kfbh.hard:                          130 ; 0x001: 0x82
[10:39:12]kfbh.type:                            1 ; 0x002: KFBTYP_DISKHEAD
[10:39:12]kfbh.datfmt:                          1 ; 0x003: 0x01
[10:39:12]kfbh.block.blk:                       0 ; 0x004: blk=0
[10:39:12]kfbh.block.obj:              2147483648 ; 0x008: disk=0

[10:39:37]oracle12c01:~ # /oracle/app/12.1.0/grid/bin/kfed read /dev/mapper/emc2G02
[10:39:37]kfbh.endian:                          1 ; 0x000: 0x01
[10:39:37]kfbh.hard:                          130 ; 0x001: 0x82
[10:39:37]kfbh.type:                            1 ; 0x002: KFBTYP_DISKHEAD
[10:39:37]kfbh.datfmt:                          1 ; 0x003: 0x01
[10:39:37]kfbh.block.blk:                       0 ; 0x004: blk=0
[10:39:37]kfbh.block.obj:              2147483649 ; 0x008: disk=1

[10:35:46]oracle12c01:~ # /oracle/app/12.1.0/grid/bin/kfed read /dev/mapper/emc2G03
[10:35:49]kfbh.endian:                          0 ; 0x000: 0x00
[10:35:49]kfbh.hard:                            0 ; 0x001: 0x00
[10:35:49]kfbh.type:                            0 ; 0x002: KFBTYP_INVALID
[10:35:49]kfbh.datfmt:                          0 ; 0x003: 0x00
[10:35:49]kfbh.block.blk:                       0 ; 0x004: blk=0
[10:35:49]kfbh.block.obj:                       0 ; 0x008: file=0

通过kfed工具我们发现其实ASMOCR2G1和ASMOCR2G2的磁盘头都是正常的。而ASMLIB能识别的ASMOCR2G3确显示磁盘头是无效的。针对这种问题,我觉得一大部分原因可以归咎到ASMLIB上去,网上也有很多关于它和udev优缺点的讨论。那么我们探讨的是出现这种问题如何恢复。

二、故障解决

那么首先我们考虑的是以前的备份,如果以前OCR的备份是好的,那么我们直接恢复就可以了,但是问题在于你不清楚这些备份是不是好的。如果备份是无效的,那么我们还可以重建OCR。从风险和难易程度上来看,我们先用备份来恢复吧。

[11:04:56]oracle12c01:/oracle/app/12.1.0/grid/bin # ./ocrconfig –showbackup
[11:05:02]PROT-26: Oracle Cluster Registry backup locations were retrieved from a local copy
[11:05:02]oracle12c01     2015/01/20 17:22:43     /oracle/app/12.1.0/grid/cdata/oracle1-cluster/backup00.ocr
[11:05:02]oracle12c01     2015/01/20 13:22:43     /oracle/app/12.1.0/grid/cdata/oracle1-cluster/backup01.ocr
[11:05:02]oracle12c01     2015/01/20 09:22:42     /oracle/app/12.1.0/grid/cdata/oracle1-cluster/backup02.ocr

[11:09:03]oracle12c01:/oracle/app/12.1.0/grid/bin # ./ocrconfig -restore  /oracle/app/12.1.0/grid/cdata/oracle1-cluster/backup00.ocr
[11:09:03]PROT-35: The configured OCR locations are not accessible

直接就报了这种错误,restore的时候OCR路径不可访问。那么这个情况是因为我们的asmlib下面看不到盘,所以我们要重新解决asmlib识别盘的问题。

[11:32:32]oracle12c01:/oracle/app/12.1.0/grid/bin # dd if=/dev/mapper/emc2G01 of=/tmp/ocr01.ocr bs=8192 count=10000000
[11:36:32]oracle12c01:/oracle/app/12.1.0/grid/bin # dd if=/dev/zero of=/dev/mapper/emc2G01 bs=8192 count=100000000
[11:37:03]oracle12c01:/oracle/app/12.1.0/grid/bin #  /etc/init.d/oracleasm createdisk ASMOCR2G1 /dev/mapper/emc2G01
[11:37:03]Marking disk "ASMOCR2G1" as an ASM disk:                                                                                                                               done

按照上面的操作把emc2G01,emc2G02,emc2G03都备份了一遍,然后格式掉后,重新用asmlib成功进行了绑定。绑定完成之后继续restore,发现还是报同样的错误。

[11:46:42]oracle12c01:/oracle/app/12.1.0/grid/bin # ./ocrconfig -restore /oracle/app/12.1.0/grid/cdata/oracle1-cluster/backup01.ocr
[11:46:42]PROT-35: The configured OCR locations are not accessible

可以看到仍然和以前错误一样的。所以,我们还是去Metalink上搜一搜这种情况,究竟该怎么restore。我们可以参考metalink上的文档:How to restore ASM based OCR after complete loss of the CRS diskgroup on Linux/Unix systems (文档 ID 1062983.1)

1.停止CRS软件,两个节点都要停掉

[13:44:11]oracle12c01:/oracle/app/12.1.0/grid/bin # ./crsctl stop crs –f

2.启动CRS到exclusive mode

[13:44:50]oracle12c01:/oracle/app/12.1.0/grid/bin # ./crsctl start crs -excl -nocrs

文档中作完这一步就是重新使用asmlib包去标记物理磁盘,而这一步骤我们前面已经做过了,所以剩下的步骤就是在sqlplus里面创建磁盘组。

3.使用sqlplus创建crs磁盘组

[14:12:53]grid@oracle12c01:~> sqlplus / as sysasm
[14:12:53]SQL*Plus: Release 12.1.0.1.0 Production on Wed Jan 21 14:16:54 2015
[14:12:53]Copyright (c) 1982, 2013, Oracle.  All rights reserved.
[14:12:53]Connected to:
[14:12:53]Oracle Database 12c Enterprise Edition Release 12.1.0.1.0 - 64bit Production
[14:12:53]With the Real Application Clusters and Automatic Storage Management options
[14:17:38]SQL> create diskgroup OCRDG external redundancy disk '/dev/oracleasm/disks/ASMOCR2G1', '/dev/oracleasm/disks/ASMOCR2G2', '/dev/oracleasm/disks/ASMOCR2G3'  attribute 'COMPATIBLE.ASM' = '12.1.0.0.0';
[14:17:53]Diskgroup created.

这里我们使用grid账号操作登陆到sqlplus里面进行操作,因为我是12.1.0.1.0的数据库,所以这里的asm兼容性参数也设置成了12.1.0.0.0.

4.Restore ocr备份

切换到root用户下面执行ocr的还原,这次很顺利还原成功。

[14:18:49]oracle12c01:/oracle/app/12.1.0/grid/bin # ./ocrconfig -restore  /oracle/app/12.1.0/grid/cdata/oracle1-cluster/backup01.ocr
[14:20:53]oracle12c01:/oracle/app/12.1.0/grid/bin # ./ocrcheck
[14:20:53]Status of Oracle Cluster Registry is as follows :
[14:20:53]         Version                  :          4
[14:20:53]         Total space (kbytes)     :     409568
[14:20:53]         Used space (kbytes)      :       1460
[14:20:53]         Available space (kbytes) :     408108
[14:20:53]         ID                       : 1063957750
[14:20:53]         Device/File Name         :     +OCRDG
[14:20:53]                                    Device/File integrity check succeeded
[14:20:53]                                    Device/File not configured
[14:20:53]                                    Device/File not configured
[14:20:53]                                    Device/File not configured
[14:20:53]                                    Device/File not configured
[14:20:53]         Cluster registry integrity check succeeded
[14:20:55]         Logical corruption check succeeded

5.重新创建Voteing Disk

[14:21:10]oracle12c01:/oracle/app/12.1.0/grid/bin # ./crsctl replace votedisk +OCRDG
[14:21:12]CRS-4602: Failed 27 to add voting file aa67b0c44b724f92bfc2e2a1d88f6b28.
[14:21:12]Failed to replace voting disk group with +OCRDG.
[14:21:12]CRS-4000: Command Replace failed, or completed with errors.

原本以为可以一路的顺畅到底,没想到啊,在创建votedisk的时候遇到了CRS-4602错误。这个问题根据文档:CRS-4256 CRS-4602 While Replacing Voting Disk (文档 ID 1475588.1)的描述,总共有4种可能性。

  • 这个命令必须是使用root用户执行;
  • ASM diskgroup 不是online或者空间不足;
  • ASM compatible attribute 不正确;
  • asm_diskstring参数没设置。

第一条和第三条,不存在这种问题。我们的问题可能是问题二和问题四。

SQL> select group_number  "Group"
,disk_number   "Disk"
,header_status "Header"
,mode_status   "Mode"
,state         "State"
,redundancy    "Redundancy"
,total_mb      "Total MB"
,free_mb       "Free MB"
,name          "Disk Name"
,failgroup     "Failure Group"
,path          "Path"
from   v$asm_disk
order by group_number
,disk_number
/
[14:47:37]Group Disk Header Mode    State    Redunda   Total MB  Free MB Disk Name  Failure Group   Path
[14:47:37]----- ---- -------------- -------- ------- --------------------------------------------   -----
[14:47:37]    1    0 MEMBER ONLINE  NORMAL   UNKNOWN       1024  949 OCRDG_0000     OCRDG_0000      /dev/oracleasm/disks/ASMOCR2G1
[14:47:37]    1    1 MEMBER ONLINE  NORMAL   UNKNOWN       1024  947 OCRDG_0001     OCRDG_0001      /dev/oracleasm/disks/ASMOCR2G2
[14:47:37]    1    2 MEMBER ONLINE  NORMAL   UNKNOWN       1024  951 OCRDG_0002     OCRDG_0002      /dev/oracleasm/disks/ASMOCR2G3

可以看到我们的磁盘组是刚刚创建的,空间也是足够的。然后检查asm_diskstring的值,发现是空的。

[15:05:01]SQL> show parameter disk
[15:05:01]
[15:05:01]NAME                                 TYPE        VALUE
[15:05:01]------------------------------------ ----------- ------------------------------
[15:05:01]asm_diskgroups                       string      OCRDG
[15:05:01]asm_diskstring                       string

于是只能重新配置参数。在ASM的alert日志里面找了一份历史的启动参数做了一个pfile文件。

[15:11:55]grid@oracle12c01:/oracle/app/12.1.0/grid/dbs> sqlplus / as sysasm
[15:11:55]SQL*Plus: Release 12.1.0.1.0 Production on Wed Jan 21 15:15:57 2015
[15:11:55]Copyright (c) 1982, 2013, Oracle.  All rights reserved.
[15:11:55]Connected to an idle instance.
[15:12:36]SQL> startup pfile='/oracle/app/12.1.0/grid/dbs/initasm.ora';
[15:12:41]ASM instance started
[15:12:41]Total System Global Area 1135747072 bytes
[15:12:41]Fixed Size                  2297344 bytes
[15:12:41]Variable Size            1108283904 bytes
[15:12:41]ASM Cache                  25165824 bytes
[15:12:48]ASM diskgroups mounted
[15:12:48]ASM diskgroups volume enabled
[15:13:57]SQL> show parameter asm
[15:13:57]NAME                                 TYPE        VALUE
[15:13:57]------------------------------------ ----------- ------------------------------
[15:13:57]asm_diskgroups                       string
[15:13:57]asm_diskstring                       string      /dev/oracleasm/disks/*
[15:13:57]asm_power_limit                      integer     1
[15:13:57]asm_preferred_read_failure_groups    string

再次执行创建votedisk的操作,执行成功。

[15:14:30]grid@oracle12c01:/oracle/app/12.1.0/grid/dbs> crsctl replace votedisk +OCRDG
[15:14:33]Successful addition of voting disk 08d0bf0676724fe7bf189d454cdfe158.
[15:14:33]Successfully replaced voting disk group with +OCRDG.
[15:14:33]CRS-4266: Voting file(s) successfully replaced

完成这一步后可以按照metalink文档重新创建asm的spfile并存放到ocr中,我这里没有创建,我发现也可以。只不过asm_diskstrings参数是空白的,官方文档对于这一步的操作也是可选的。

6.重启CRS

以上操作完成之后,重启CRS到正常模式即可。这里建议最好按照官方文档的命令做一下asmlib的scandisk的操作。

[15:18:22]oracle12c01:/oracle/app/12.1.0/grid/bin # ./crsctl stop crs –f
[15:19:04]oracle12c01:/oracle/app/12.1.0/grid/bin # /usr/sbin/oracleasm scandisks
[15:19:05]Reloading disk partitions: done
[15:19:05]Cleaning any stale ASM disks...
[15:19:05]Scanning system for ASM disks...
[15:19:13]oracle12c01:/oracle/app/12.1.0/grid/bin # ./crsctl start crs
[15:19:21]CRS-4123: Oracle High Availability Services has been started.

[15:23:20]SQL> select name,state from v$asm_disk;
[15:23:20]
[15:23:20]NAME                           STATE
[15:23:20]------------------------------ --------
[15:23:20]OCRDG_0002                     NORMAL
[15:23:20]OCRDG_0001                     NORMAL
[15:23:20]OCRDG_0000                     NORMAL
[15:23:20]DATADG1_0001                   NORMAL
[15:23:20]DATADG2_0002                   NORMAL
[15:23:20]DATADG2_0001                   NORMAL
[15:23:20]DATADG2_0000                   NORMAL
[15:23:20]DATADG1_0000                   NORMAL

参考文档:

How to restore ASM based OCR after complete loss of the CRS diskgroup on Linux/Unix systems (文档 ID 1062983.1)

CRS-4256 CRS-4602 While Replacing Voting Disk (文档 ID 1475588.1)