进程日志中出现out of OS kernel IO resources

Posted on 2011/11/15 by yangtingkun

在检查一个进程的日志时，意外发现这个问题。
错误信息如下：

/ora10g/app/admin/dbname/bdump/dbname1_j001_8567.trc
Oracle DATABASE 10g Enterprise Edition Release 10.2.0.3.0 - 64bit Production
WITH the Partitioning, REAL Application Clusters, OLAP AND DATA Mining options
ORACLE_HOME = /ora10g/app/product/10.2.0/dbname
System name: HP-UX
Node name: dbname1
Release: B.11.23
Version: U
Machine: ia64
Instance name: dbname1
Redo thread mounted BY this instance: 1
Oracle process NUMBER: 34
Unix process pid: 8567, image: oracle@dbname1 (J001)
*** 2011-11-14 22:40:19.204
*** ACTION NAME:(GATHER_STATS_JOB) 2011-11-14 22:40:19.066
*** MODULE NAME:(DBMS_SCHEDULER) 2011-11-14 22:40:19.066
*** SERVICE NAME:(SYS$USERS) 2011-11-14 22:40:19.066
*** CLIENT ID:() 2011-11-14 22:40:19.066
*** SESSION ID:(1476.50721) 2011-11-14 22:40:19.066
WARNING:Oracle process running OUT OF OS kernel I/O resources 
*** 2011-11-14 22:40:55.057
WARNING:Oracle process running OUT OF OS kernel I/O resources 
*** 2011-11-14 22:44:30.269
WARNING:Oracle process running OUT OF OS kernel I/O resources 
*** 2011-11-14 22:47:40.952
WARNING:Oracle process running OUT OF OS kernel I/O resources 
WARNING:Oracle process running OUT OF OS kernel I/O resources

检查了一下MOS，发现了相似的bug：
Bug 6687381 – “WARNING: Oracle process running out of OS kernel I/O resources” messages [ID 6687381.8]；
Bug 6908655 – “WARNING:Oracle process running out of OS kernel I/O resources” messages [ID 6908655.8]；
Bug 7523755 – “WARNING:Oracle process running out of OS kernel I/O resources” messages [ID 7523755.8]
这几个bug的共同点是都影响10.2.0.5一下的版本，且问题都在10.2.0.5被fixed。在11g的版本中，这几个bug的表现有所差别，第一个bug在11.1.0.7中被fixed，而另外两个需要在11.2.0.1中才被fixed。
这个问题可能导致严重的性能影响，严重的情况下甚至是数据库的崩溃，因此如果告警日志或trace文件中频繁出现这个问题，建议尽快按照补丁解决这个问题。

Posted in BUG | Tagged , | Leave a comment

ORA-7445(sigsetjmp)错误

Posted on 2011/11/14 by yangtingkun

客户数据库中出现ORA-7445错误，导致错误的SQL在访问V$ACCESS视图。
错误信息如下：

Sun Sep 19 17:15:17 2010
Errors IN file /home/oracle/admin/ARIC/udump/aric_ora_26489.trc:
ORA-07445: exception encountered: core dump [SIGSEGV] [Address NOT mapped TO object] [0] [] [] []

对应的详细TRACE：

/home/oracle/admin/ARIC/udump/aric_ora_26489.trc
Oracle DATABASE 10g Enterprise Edition Release 10.2.0.3.0 - Production
WITH the Partitioning, OLAP AND DATA Mining options
ORACLE_HOME = /home/oracle/product/10.2.0
System name: SunOS
Node name: aric
Release: 5.10
Version: Generic_127128-11
Machine: i86pc
Instance name: ARIC
Redo thread mounted BY this instance: 1
Oracle process NUMBER: 51
Unix process pid: 26489, image: oracleARIC@aric
*** 2010-09-19 17:15:17.370
*** ACTION NAME:() 2010-09-19 17:15:17.339
*** MODULE NAME:(TOAD 8.6.1.0) 2010-09-19 17:15:17.339
*** SERVICE NAME:(ARIC) 2010-09-19 17:15:17.339
*** SESSION ID:(202.3926) 2010-09-19 17:15:17.339
Exception signal: 11 (SIGSEGV), code: 1 (Address NOT mapped TO object), addr: 0x0
*** 2010-09-19 17:15:17.371
ksedmp: internal OR fatal error
ORA-07445: exception encountered: core dump [SIGSEGV] [Address NOT mapped TO object] [0] [] [] []
CURRENT SQL statement FOR this SESSION:
SELECT  sid, owner, TYPE, object FROM v$access WHERE  sid = '651'
----- Call Stack Trace -----
calling              CALL     entry                argument VALUES IN hex      
location             TYPE     point                (? means dubious VALUE)     
-------------------- -------- -------------------- ----------------------------
ksedst()+23          ?        0000000000000001     0017B341C 000000000 0062E5A60
                                                   000000000
ksedmp()+636         ?        0000000000000001     0017B1EB1 000000000 00000000B
                                                   000000000
ssexhd()+729         ?        0000000000000001     000E90E7E 000000000 0062E5B90
                                                   000000000
sigsetjmp()+25       ?        0000000000000001     0FDDC00B6 0FFFFFD7F 0062E5B50
                                                   000000000
call_user_handler()  ?        0000000000000001     0FDDB53A2 0FFFFFD7F 0062E5EF0
+589                                               000000000
sigacthandler()+163  ?        0000000000000001     0FDDB5588 0FFFFFD7F 0FF3FB2F0
                                                   0FFFFFD7F
_memcpy()+245        ?        0000000000000001     0FFFFFFFF 0FFFFFFFF 00000000B
                                                   000000000
kglLockIterator()+5  ?        0000000000000001     003E36CE1 000000000 0C582FDCC
96                                                 000000000
kqlftl()+194         ?        0000000000000001     001F2A4B7 000000000 000000000
                                                   000000000
qerfxFetch()+4999    ?        0000000000000001     00340E894 000000000 000000000
                                                   000000000
qerjotFetch()+214    ?        0000000000000001     0033BEBA3 000000000 0060B9478
                                                   000000000
qerjotFetch()+280    ?        0000000000000001     0033BEBE5 000000000 0000001F4
                                                   000000000
qerghFetch()+293     ?        0000000000000001     0034C19B2 000000000 0000001F4
                                                   000000000
qervwFetch()+158     ?        0000000000000001     0033BCFBB 000000000 0000001F4
                                                   000000000
opifch2()+2608       ?        0000000000000001     002932E8D 000000000 000000000
                                                   000000000
kpoal8()+3638        ?        0000000000000001     0028CF6BB 000000000 000000000
                                                   000000000
opiodr()+1087        ?        0000000000000001     000E97C5C 000000000 000000000
                                                   000000000
ttcpip()+1165        ?        0000000000000001     003D9F6CA 000000000 005F663F8
                                                   000000000
opitsk()+1278        ?        0000000000000001     000E939C3 000000000 000E97840
                                                   000000000
opiino()+931         ?        0000000000000001     000E96F08 000000000 005F5D840
                                                   000000000
opiodr()+1087        ?        0000000000000001     000E97C5C 000000000 000000000
                                                   000000000
opidrv()+748         ?        0000000000000001     000E924C1 000000000 0FFDFF8C8
                                                   0FFFFFD7F
sou2o()+86           ?        0000000000000001     000E8F8FB 000000000 000000000
                                                   000000000
opimai_real()+127    ?        0000000000000001     000E552D4 000000000 000000000
                                                   000000000
main()+95            ?        0000000000000001     000E551A4 000000000 000000000
                                                   000000000
0000000000E54FE7     ?        0000000000000001     000E54FEC 000000000 000000000
                                                   000000000
--------------------- Binary Stack Dump ---------------------

导致错误产生的语句很简单，就是一个简单的单表查询，只不过访问的是Oracle的动态性能视图表。而这种情况下出现的错误，基本上可以确定是bug。
根据错误号sigsetjmp检查MOS信息，发现包括堆栈信息在内的各方面信息都与Bug 7149072: ORA-7445 OCCURS WHEN SELECTING FROM V$ACCESS描述的一致，只不过这个bug描述并不是一个基本BUG，而这个问题对应的基本bug是：Bug 4969005 Dump [kglLockIterator] querying V$ views，而这个bug描述中对应的kglLockIterator和memcpy错误函数在当前错误中同样存在，而且当前数据库版本的也是受影响的10.2.0.3，基本上可以确定bug了。
这个BUG在11.2.0.4和11.1.0.6中被fixed。

Posted in BUG | Tagged , , , , | Leave a comment

AIX系统谨慎使用reboot命令

Posted on 2011/11/13 by yangtingkun

在客户一次停机维护中，发现了这个问题。
环境是ORACLE 10G RAC for AIX6，使用了HACMP管理共享磁盘。
在停机维护时间段内需要重启主机，当关闭了数据库和CLUSTER后，节点1使用reboot命令重启操作系统，等了很长时间，系统仍然没有启动的迹象，不得以到机房中检查，发现服务器处于关机状态。
手工启动服务器后，发现HACMP启动报错，原因是/etc/snmpdv3.conf文件被清空。将另外节点的文件拷贝到当前节点上，HACMP和RAC环境顺利启动。
而节点2同样采用reboot操作，同样服务器没有自动重启而只是关机，手工启动后发现ORACLE_HOME所在盘出现错误，必须要执行fsck命令，结果检查出几个不一致的块，并且丢失了一些文件，好在出问题的都是Oracle产生的trace文件，fsck结束后该盘顺利挂载。
特意检查了一下reboot命令，发现这个命令在单用户模式下是重启服务器，而多用户模式下，该命令只是关机，而且可能会导致文件系统的损坏。
正确的重启方式是shutdown –Fr，随后又进行了两次重启，都采用了shutdown –Fr方式，没有碰到任何问题。

Posted in OPERATING SYSTEM | Tagged , , | Leave a comment

11.2数据库登录出现library cache lock等待（二）

Posted on 2011/11/12 by yangtingkun

客户的11.2.0.2 RAC for Linux X86-64环境的数据库在登录时，发现出现长时间等待。
这一篇描述现象重现过程。
11.2数据库登录出现library cache lock等待（一）：https://yangtingkun.net/?p=279
上一篇描述了客户的11.2.0.2 RAC for Linux X86-64环境出现library cache lock的问题，同事回来后想要模拟这个现象，在Windows环境下的11.2.0.1上却没有模拟出来，我也在Windows上的11.2.0.1上尝试了一下，结果没有出现library cache lock等待，但是出现了row cache lock等待事件。
测试步骤很简单，开启三个sqlplus，其中一个设置SET TIME ON，获取时间信息，并不断的已错误的用户名密码尝试连接数据库。另一个会话以正确的用户名和密码连接到数据库，设置SQLPROMPT为SQL2>，以便于和第一个会话区别。最后一个会话以SYS登录数据库，检查会话的等待状态：

SQL> SET TIME ON
08:34:41 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:34:42 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:34:42 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:34:43 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:34:44 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:34:46 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:34:49 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:34:54 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:34:59 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:35:05 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:35:12 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:35:21 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:35:30 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:35:40 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:35:50 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:36:01 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:36:01 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:36:01 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:36:01 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:36:02 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:36:05 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
.
.
.
08:38:00 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:38:10 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:38:20 SQL> CONN TEST/A@192.25.1.100/TEST112
ERROR:
ORA-01017: 用户名/口令无效; 登录被拒绝
 
08:38:30 SQL>

可以看到，会话1登录失败的等待时间从1秒慢慢涨到了10秒，随后又缩短到1秒以内，最后又一次涨到了10秒。
之所以等待时间被重置，是因为会话2上成功的执行一次登录：

SQL> CONN TEST/TEST@192.25.1.100/TEST112
已连接。
SQL> SET SQLP 'SQL2> '
SQL2> CONN TEST/TEST@192.25.1.100/TEST112
已连接。
SQL2>

会话2的登录成功，使得会话1上10秒的延迟验证被重置到1秒以内。
最后看一下V$SESSION视图查询的等待信息：

SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        12            sqlplusw.exe    SQL*Net message FROM client                         4
        63 TEST       sqlplusw.exe    SQL*Net message FROM client                        89
SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        12            sqlplusw.exe    SQL*Net message FROM client                         2
        63 TEST       sqlplusw.exe    SQL*Net message FROM client                       103
SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        12            sqlplusw.exe    SQL*Net message FROM client                         6
        63 TEST       sqlplusw.exe    SQL*Net message FROM client                       107
SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        12            sqlplusw.exe    SQL*Net message FROM client                         8
        63 TEST       sqlplusw.exe    SQL*Net message FROM client                       143
SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        12            sqlplusw.exe    SQL*Net message FROM client                         1
        63            sqlplusw.exe    ROW cache LOCK                                      1
SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        12            sqlplusw.exe    SQL*Net message FROM client                         4
        63            sqlplusw.exe    ROW cache LOCK                                      4
SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        12            sqlplusw.exe    SQL*Net message FROM client                         6
        63            sqlplusw.exe    ROW cache LOCK                                      6
SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        12            sqlplusw.exe    SQL*Net message FROM client                         9
        63            sqlplusw.exe    ROW cache LOCK                                      8
SQL> SELECT SID, USERNAME, PROGRAM, EVENT, SECONDS_IN_WAIT 
  2  FROM V$SESSION 
  3  WHERE NVL(USERNAME, 'OTHER') != USER 
  4  AND NVL(PROGRAM, 'OTHER') NOT LIKE 'ORACLE.EXE%';
       SID USERNAME   PROGRAM         EVENT                                 SECONDS_IN_WAIT
---------- ---------- --------------- ------------------------------------- ---------------
        63 TEST       sqlplusw.exe    SQL*Net message FROM client                         1
        69            sqlplusw.exe    SQL*Net message FROM client                         0

可以看到，如果只有一个会话连接数据库失败，则不会导致任何异常等待的出现，如果这时存在另一个会话以同样的用户名来访问数据库，那么不管这个用户使用的密码是否正确，都会引发row cache lock等待事件。
而同样的测试在11.2.0.2的环境中，出现的等待是library cache lock。检查了一下，当前的row cache lock等待事件，实际上是11.2.0.1的一个bug：Bug 9720182: DUE TO ROW CACHE LOCK WAIT EVENTS IN DATABASE APPLICATION GOT HUNG。
Oracle提供了专门的PATCH可以解决这个问题，其实解决这个问题的最有效的办法，就是避免用户使用不正确的密码来连接数据库。

Posted in ORACLE | Tagged , , | Leave a comment

11.2数据库登录出现library cache lock等待（一）

Posted on 2011/11/11 by yangtingkun

客户的11.2.0.2 RAC for Linux X86-64环境的数据库在登录时，发现出现长时间等待。
这一篇描述问题的现象的诊断。
出问题的时候我正好在客户现场，于是当时诊断了一下。
客户反映，问题发生在一个用户上，使用这个用户登录需要等待很长时间，而使用其他的用户登录则不存在问题。
首先检查了DBA_PROFILES，确认和密码以及登录有关的PROFILE是否存在限制，当前数据库已经都设置为UNLIMITED，那么问题应该和PROFILE无关。
检查出现问题的用户，也未发现任何特别之处。
在sqlplus上使用这个用户登录，经历了将近10秒左右的等待，终于成功登录。同时检查到会话当时出现library cache lock等待事件。
当再次尝试重现问题时，却已发现问题无法重现了，现在即使使用刚才的问题用户，也可以很快登录成功，并不会出现明显的登录等待。莫非一次成功的登录，就可以解决这个问题。
不过很快，问题再次出现，为了检查会话执行的具体操作，对这个问题用户创建了一个登录触发器，在登录触发器中设置会话的TRACE：

SQL> CREATE OR REPLACE TRIGGER T_AFTER_LOGON AFTER LOGON ON DATABASE
2 BEGIN
3 IF USER = 'GJT' THEN
4 DBMS_SESSION.SESSION_TRACE_ENABLE(TRUE, TRUE);
5 END IF;
6 END;
7 /
TRIGGER created.

虽然问题重现了，但是找到会话的TRACE信息，却没有发现任何异常之处，甚至在TRACE信息中都找不到任何library cache lock等待事件的信息。
而且此时还发现一个现象，就是利用这个用户登录时，即使用户名的密码输入错误，sqlplus也会等待很长时间，然后才会返回错误信息。而这个长时间的等待从V$SESSION视图中查询，恰恰就是library cache lock等待事件。
上面的两个现象说明，library cache lock的等待实际上是发生在用户登录之前的。其实从数据库V$SESSION视图中也可以看出这个问题：

SQL> SELECT sid, username, event, p1text, p1, p2text, p2, p3text, p3, seconds_in_wait
  2  FROM gv$session
  3  WHERE event = 'library cache lock';
        SID USERNAME                       EVENT              SECONDS_IN_WAIT 
----------- ------------------------------ ------------------ --------------- 
         19                                library cache LOCK              21
       2017                                library cache LOCK              20
       2062                                library cache LOCK               0
       2147                                library cache LOCK              10
       2210                                library cache LOCK              21

可以看到，所有出现library cache lock等待的会话用户名都是空。这些会话并不是Oracle后台进程，而是刚才提到的问题用户，这同样说明当方式这个library cache lock等待时，会话还没有成功的登录到数据库中。
那么现在问题有点棘手，如果会话没有登录，则没有办法检查会话执行了哪些操作，Oracle的文档中也没有提到过，会话登录之前会进行哪些操作，经历哪些等待。
分析一下这个问题，整个数据库目前只有这个用户出现了library cache lock的等待，而其他用户没有出现，说明问题肯定和这个用户的自身特点有关。而数据库中只存在默认的DEFAULT PROFILE，且所有限制都设置为UNLIMITED，那么问题应该和PROFILE没有关系。通过登录触发器设置TRACE后发现，会话登录后并无任何异常操作，且TRACE文件中看不到library cache lock等待信息。而且即使用户名密码错误，也会出现这个等待事件。这说明等待发生在登录之前，与用户登录后的行为无关。
简单总结一下，问题和当前用户的自身特性有关，且与DBA_PROFILE无关，也与用户登录后的行为无关。如果不考虑PROFILE，那么用户特有的属性恐怕就剩下了用户名和密码了。而且在一次成功的登录数据库后，这个现象曾短时间消失，这说明问题可能确实和密码有关系。
在11g中，Oracle的密码策略确实出现了一些改变，比如密码变成大小写敏感。这个问题很可能导致老的程序来连接数据库时出现密码错误的现象。此外，11g还新增了一个密码相关的特性——密码错误延迟验证：当用户连续的输入错误的密码，Oracle所需要的密码验证时间会逐步增加，这可以有效的避免有人试图通过暴力方式来破解密码。关于11g新增密码错误延迟验证的详细内容，可以参考：http://yangtingkun.itpub.net/post/468/505041
那么当前的问题和这个密码延迟验证有关系吗，如果是密码延迟验证的问题，那么至少要多次重复输入错误的密码。不过从刚才的V$SESSION视图中可以看到，问题用户存在多个会话在登录数据库，如果是程序连接数据库，且配置了错误的密码，那么基本上就可以确定问题了。
询问了相关程序人员，发现一个测试程序的密码确实配置错误，且这个程序目前仍然在后台不断的尝试连接数据库。
现在所有的疑问都解开了，用户程序已错误的密码不断登录，在加上11g的密码延迟验证，使得用户的验证等待时间不断加长。这也解释了为什么输入正确的密码登录后，这个现象曾短暂消失，因为用户成功登录，密码延迟验证的时间归零。
找到问题的原因后，在客户的数据库上以其他的用户尝试模拟这个现象，测试发现，如果一个会话登录数据库，即使每次密码都不正确使得延迟验证时间不断变长，也不会引发library cache lock的等待时间，但是只要该用户存在第二个登录会话，这时library cache lock会在两个会话同时出现，而且即使这个会话尝试使用正确的密码登录，在成功登录之前，也要等待library cache lock事件。
根据这个现象，个人推测Oracle为了实现延迟验证，必然需要在共享池中保存一个类似计数器的对象。这个计数器记录用户登录连续密码错误次数，从而确定延迟验证的等待时间。当用户成功登录，计数器清零。如果是一个会话，那么只需要独占这个计数器就可以了，当存在两个以上的会话，且两个会话都试图修改计数器的内容，那么资源竞争就出现了，而体现在数据库中的等待事件就是library cache lock。当然这只是个人的猜测而已，还没有看到Oracle官方对这种情况的说明。

Posted in ORACLE | Tagged , , | 2 Comments

数据库升级导致ORA-918错误

Posted on 2011/11/10 by yangtingkun

客户的数据库从10.2.0.1升级到10.2.0.5后，出现了ORA-918错误，不过导致错误出现的原因并不是升级碰到了BUG，而是升级解决了BUG。
在Oracle 10.2.0.5中，解决了一个Bug 5368296 ANSI join SQL may not report ORA-918 for ambiguous column，结果原本客户受这个bug影响而没有报错的SQL语句，在升级之后开始大面积报错。
而解决办法除了修改SQL语句外，只有回退一个办法，Oracle显然不会为了重现一个bug而提供什么解决方案。当然这个问题的避免应该通过前期的测试来避免，不过这里还是关注一下这个bug。
在如果使用标准查询写法，当关联表的个数超过2个，且表都包含相同的列名，那么在查询的时候如果不指定这个列名的属主，是不会报错的。

SQL*Plus: Release 10.2.0.3.0 - Production ON Tue Nov 8 15:51:41 2011
Copyright (c) 1982, 2006, Oracle. ALL Rights Reserved.
Connected TO:
Oracle DATABASE 10g Enterprise Edition Release 10.2.0.3.0 - Production
WITH the Partitioning, OLAP AND DATA Mining options
SQL> CREATE USER u1 IDENTIFIED BY u1 DEFAULT tablespace users;
USER created.
SQL> GRANT CONNECT, resource TO u1;
GRANT succeeded.
SQL> conn u1/u1
Connected.
SQL> CREATE TABLE t1 (id NUMBER);
TABLE created.
SQL> CREATE TABLE t2 (id NUMBER);
TABLE created.
SQL> CREATE TABLE t3 (id NUMBER);
TABLE created.
SQL> SELECT id FROM t1, t2, t3 WHERE t1.id = t2.id AND t1.id = t3.id;
SELECT id FROM t1, t2, t3 WHERE t1.id = t2.id AND t1.id = t3.id
*
ERROR at line 1:
ORA-00918: COLUMN ambiguously defined
 
SQL> SELECT id FROM t1 JOIN t2 ON t1.id = t2.id JOIN t3 ON t1.id = t3.id;
no ROWS selected
SQL> SELECT id FROM t1 JOIN t2 ON t1.id = t2.id;
SELECT id FROM t1 JOIN t2 ON t1.id = t2.id
*
ERROR at line 1:
ORA-00918: COLUMN ambiguously defined

可以看到，Oracle的写法不存在这个问题，而如果使用标准SQL写法，在表连接数超过2张的时候，就会引发bug，Oracle会忽略列重名问题。

SQL> ALTER TABLE t3 ADD (id1 NUMBER);
TABLE altered.
SQL> SELECT id FROM t1 JOIN t2 ON t1.id = t2.id JOIN t3 ON t1.id = t3.id1;
no ROWS selected
SQL> ALTER TABLE t3 DROP (id);
TABLE altered.
SQL> SELECT id FROM t1 JOIN t2 ON t1.id = t2.id JOIN t3 ON t1.id = t3.id1;
SELECT id FROM t1 JOIN t2 ON t1.id = t2.id JOIN t3 ON t1.id = t3.id1
*
ERROR at line 1:
ORA-00918: COLUMN ambiguously defined

测试还发现，导致问题的原因只和表中是否存在列有关，而与是否是连接列没有关系，因此必须三张或以上的表拥有相同的列名，才会引发这个bug。

Posted in BUG | Tagged , | Leave a comment

ORA-600(2037)错误

Posted on 2011/11/09 by yangtingkun

最近已经碰到多起客户数据库无法打开的情况，这就是其中一次。
这是一个10201 for Windows 64bit数据库，在一次掉电后，数据库无法启动，在后台告警日志中出现下列的错误：

Mon Oct 31 00:00:28 2011
ALTER DATABASE OPEN
Mon Oct 31 00:00:28 2011
Beginning crash recovery OF 1 threads
parallel recovery started WITH 16 processes
Mon Oct 31 00:00:28 2011
Started redo scan
Mon Oct 31 00:00:28 2011
Completed redo scan
12587 redo blocks READ, 161 DATA blocks need recovery
Mon Oct 31 00:00:29 2011
Started redo application at
Thread 1: logseq 661, block 34225
Mon Oct 31 00:00:29 2011
Recovery OF Online Redo Log: Thread 1 GROUP 3 Seq 661 Reading mem 0
Mem# 0 errs 0: D:\ORACLE\PRODUCT\10.2.0\ORADATA\YCBG\REDO03.LOG
Mon Oct 31 00:00:29 2011
Completed redo application
Mon Oct 31 00:00:29 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_p002_2196.trc:
ORA-00600: internal error code, arguments: [2037], [21598604], [2441871360], [0], [0], [0], [3729260873], [536936448]
Mon Oct 31 00:00:29 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_p006_2212.trc:
ORA-00600: internal error code, arguments: [2037], [4198106], [249167872], [229], [159], [0], [1456275520], [100740646]
.
.
.
Mon Oct 31 00:00:30 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_p002_2196.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [kcbs_dump_adv_state+1127] [PC:0x60D4E1] [ADDR:0xFFFFFFFFFFFFFFFF] [UNABLE_TO_READ] []
ORA-00600: internal error code, arguments: [2037], [21598604], [2441871360], [0], [0], [0], [3729260873], [536936448]
.
.
.
Mon Oct 31 00:00:31 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_p012_2236.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [ksl_cleanup+1220] [PC:0x49DA9C] [ADDR:0xFFFFFFFFFFFFFFFF] [UNABLE_TO_READ] []
ORA-00081: address range [0x179B63600000, 0x179B63600004) IS NOT readable
ORA-00600: internal error code, arguments: [2037], [21649715], [1496514560], [228], [10], [0], [3855679818], [100820580]
Mon Oct 31 00:00:31 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_p007_2216.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [kslwte_tm+754] [PC:0x49FC16] [ADDR:0x82FD2228AB8] [UNABLE_TO_WRITE] []
.
.
.
Mon Oct 31 00:00:35 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\udump\ycbg_ora_2256.trc:
ORA-00600: internal error code, arguments: [ksuapc1], [0x110000078], [0x7FFD63F4E90], [131072], [0x7FFD62F4E98], [], [], []
.
.
.
Corrupt block relative dba: 0x014895b9 (file 5, block 562617)
Bad header found during crash/instance recovery
DATA IN bad block:
TYPE: 91 format: 5 rdba: 0x95b90000
LAST CHANGE scn: 0x0229.e7210148 seq: 0x0 flg: 0x00
spare1: 0x6 spare2: 0xa2 spare3: 0x8b1d
consistency VALUE IN tail: 0x06010000
CHECK VALUE IN block header: 0x401
block checksum disabled
.
.
.
Mon Oct 31 00:01:23 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_ora_2164.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [ksliwat+3150] [PC:0x4A1D92] [ADDR:0xFFFFFFFFFFFFFFFF] [UNABLE_TO_READ] []
.
.
.
Mon Oct 31 00:01:26 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_reco_2148.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [kslwte_tm+754] [PC:0x49FC16] [ADDR:0x82FD2228AB8] [UNABLE_TO_WRITE] []
.
.
.
Mon Oct 31 00:09:13 2011
USER: terminating instance due TO error 472
Mon Oct 31 00:09:13 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\udump\ycbg_ora_2772.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [ksuitm+1655] [PC:0x417C41] 
.
.
.
Mon Oct 31 00:41:26 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_ora_2080.trc:
ORA-00600: internal error code, arguments: [kmcpsched:Bad caller], [], [], [], [], [], [], []
.
.
.
Mon Oct 31 04:58:05 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_p007_2960.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [kksOnErrorMutexCleanup+53] [PC:0x4A7ED5] [ADDR:0xFFFFFFFFFFFFFFFF] [UNABLE_TO_READ] []
ORA-00081: address range [0x163A63600000, 0x163A63600004) IS NOT readable
ORA-00600: internal error code, arguments: [ksfdrmms1], [0x1111B5080], [], [], [], [], [], []
.
.
.
Mon Oct 31 05:04:57 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_p004_3920.trc:
ORA-00600: internal error code, arguments: [ksfdchkfob1], [0x1111B8138], [0x1112694580000], [], [], [], [], []
.
.
.
Mon Oct 31 05:04:58 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_mmon_2384.trc:
ORA-00600: internal error code, arguments: [KSSRMP2], [0x1112697F8], [0], [0], [], [], [], []
ORA-27041: unable TO OPEN file
OSD-04001: 逻辑块大小无效 (OS 33554432)
.
.
.
Mon Oct 31 05:15:08 2011
Errors IN file e:\oracle\product\10.2.0\admin\ycbg\bdump\ycbg_p013_2484.trc:
ORA-07445: exception encountered: core dump [ACCESS_VIOLATION] [kksOnErrorMutexCleanup+53] [PC:0x4A7ED5] [ADDR:0xFFFFFFFFFFFFFFFF] [UNABLE_TO_READ] []
ORA-00081: address range [0x17F663600000, 0x17F663600004) IS NOT readable
ORA-00600: internal error code, arguments: [545], [0x110563848], [0], [16], [], [], [], []

这里只是记录了不重复错误，每个错误都会出现很多次，简直是ORA-600和ORA-7445错误的大集合。由于一个错误，一次性引发这么多的不同ORA-600和ORA-7445，我还是第一次碰到。
虽然错误信息很多，但是后面的大部分错误，除了个别几个在MOS中没有记录外，一些错误与不正常的启动有关，一些错误与实例崩溃有关，另一些是与文件损坏有关。也就是说，这些错误的产生只是现象，而问题的主要原因还要从第一个错误上入手。

*** 2011-10-31 00:00:29.259
ksedmp: internal OR fatal error
ORA-00600: internal error code, arguments: [2037], [21598604], [2441871360], [0], [0], [0], [3729260873], [536936448]
----- Call Stack Trace -----
calling              CALL     entry                argument VALUES IN hex      
location             TYPE     point                (? means dubious VALUE)     
-------------------- -------- -------------------- ----------------------------
ksedst+55            CALL???  ksedst1+573          970A00000000 00001D688
                                                   014BBDE10 00001E5F0
ksedmp+663           CALL???  ksedst+55            003A750A8 000000000 014BBC888
                                                   000000000
ksfdmp+19            CALL???  ksedmp+663           000000003 013EE4650 013A78A88
                                                   003A975A0
kgeriv+184           CALL???  ksfdmp+19            00001E5F0 013EE4010 000AEBD23
                                                   27F00001FA0
kgesiv+102           CALL???  kgeriv+184           000000000 000000000 013EE4010
                                                   000000000
ksesic7+125          CALL???  kgesiv+102           7FFD2001EC0 232FBC020
                                                   400000000 000000000
kcoexam+249          CALL???  ksesic7+125          1000007F5 000000000 00149918C
                                                   000000000
kcbtema+647          CALL???  kcoexam+249          01B7C5FA0 10F776000 000000001
                                                   000000007
kcrpap+356           CALL???  kcbtema+647          1A1FBB198 7FF9EFC0B88
                                                   7FF9EFC0604 013A7A558
kcrpdv+1521          CALL???  kcrpap+356           003E5B9A8 00000000B 000000000
                                                   000000000
kxfprdp+1360         CALL???  kcrpdv+1521          000000001 003A7AC60 000000000
                                                   000000000
opirip+1250          CALL???  kxfprdp+1360         30315C740000001E 003A782E8
                                                   014BBFA70 000000000
opidrv+860           CALL???  opirip+1250          000000032 000000004 014BBFDA0
                                                   000000000
sou2o+52             CALL???  opidrv+860           000000032 000000004 014BBFDA0
                                                   0068679D2
opimai_real+272      CALL???  sou2o+52             000000000 0139C0000 000000828
                                                   000000000
opimai+96            CALL???  opimai_real+272      000000000 000000000 000000000
                                                   000000000
BackgroundThreadSta  CALL???  opimai+96            014BBFEF0 000000001 000000000
rt+530                                             000000000
0000000078D3B6DA     CALL???  BackgroundThreadSta  0068675C0 000000000 000000000
                              rt+530               014BBFFA8
--------------------- Binary Stack Dump ---------------------

查询MOS后发现，文档During Startup (Open Database) Alert Log Shows ORA-600[2037] and ORA-7445[kcbs_dump_adv_state] [ID 551993.1]和当前描述的现象最为接近：不但2037错误和kcbs_dump_adv_state错误信息一致，数据库版本相符，连文档中提到的kcoexam kcbtema kcrpap kcrpdv kxfprdp堆栈信息在TRACE中也可以一点不差的找到。
如果在处理分布式事务的时候使用了IMU（In Memory Undo）技术，那么如果这个时候数据库出现了崩溃，那么很不幸，在Oracle重启的时候尝试实例恢复的过程中，就会导致REDO或UNDO的损坏，从而导致数据库无法打开。而当前数据库的报错集中发生在PNNN进程上，这说明Oracle在启用并行恢复，而错误信息中还可以看到RECO进程，说明Oracle在处理分布式事务的恢复，所有的现象都很好的符合了bug的描述。
这个Bug 4899479影响10.2.0.1到10.2.0.3版本，在10.2.0.4中被FIXED。而解决这个问题的常规手段只有通过备份进行及时点不完全恢复。

Posted in BUG | Tagged , , , , , | Leave a comment

ORA-27300 和skgpspawn3错误

Posted on 2011/11/08 by yangtingkun

以前碰到过类似的ORA-27300系列错误，问题都是和系统上错误有关，这次的问题也不例外。
详细错误信息如下：

Tue May 17 22:01:04 2011
Process startup failed, error stack:
Tue May 17 22:01:04 2011
Errors IN file /home/oracle/admin/ARIC/bdump/aric_psp0_866.trc:
ORA-27300: OS system dependent operation:fork failed WITH STATUS: 11
ORA-27301: OS failure message: Resource temporarily unavailable
ORA-27302: failure occurred at: skgpspawn3
Tue May 17 22:01:05 2011
Process J001 died, see its trace file
Tue May 17 22:01:05 2011
kkjcre1p: unable TO spawn jobq slave process 
Tue May 17 22:01:05 2011
Errors IN file /home/oracle/admin/ARIC/bdump/aric_cjq0_894.trc:
Tue May 17 22:01:42 2011
Process startup failed, error stack:
Tue May 17 22:01:42 2011
Errors IN file /home/oracle/admin/ARIC/bdump/aric_psp0_866.trc:
ORA-27300: OS system dependent operation:fork failed WITH STATUS: 11
ORA-27301: OS failure message: Resource temporarily unavailable
ORA-27302: failure occurred at: skgpspawn3
Tue May 17 22:01:43 2011
Process m000 died, see its trace file
Tue May 17 22:01:43 2011
ksvcreate: Process(m000) creation failed
Tue May 17 22:02:49 2011
Process startup failed, error stack:
Tue May 17 22:02:49 2011
Errors IN file /home/oracle/admin/ARIC/bdump/aric_psp0_866.trc:
ORA-27300: OS system dependent operation:fork failed WITH STATUS: 11
ORA-27301: OS failure message: Resource temporarily unavailable
ORA-27302: failure occurred at: skgpspawn5

从错误信息上也可以清楚的看出，错误出现在OS层面，查询MOS发现是由于当前的Solaris系统设置的进程相关参数过低造成的。
根据Oracle的推荐，可以修改系统/etc/system文件，添加下面的内容：

# vi /etc/system
SET maxuprc=60000 
SET pidmax=70000 
SET max_nprocs=65000 
SET maxusers=4096
# reboot

要想是修改的参数生效需要重启数据库服务器。

Posted in ORACLE | Tagged , , , , | Leave a comment

ORA-600(kghstack_underflow_internal_3)错误

Posted on 2011/11/07 by yangtingkun

客户的数据库环境中出现ORA-600(kghstack_underflow_internal_3)错误。

详细错误信息为：

Errors IN file /home/oracle/admin/db1/bdump/db1_dw05_18423.trc:
ORA-00600: internal error code, arguments: [kghstack_underflow_internal_3], [0xFFFFFD7FFB6D5FC0], [rpi ROLE SPACE], [], [], [], [], []
ORA-19502: WRITE error ON file "/oradata03/dmp /exp05.20100916.dmp", blockno 11292695 (blocksize=4096)
ORA-27063: NUMBER OF bytes READ/written IS incorrect
Solaris-AMD64 Error: 28: No SPACE LEFT ON device
Additional information: -1
Additional information: 262144

从错误信息不难判断，虽然这时一个ORA-600错误，但是问题肯定和数据泵导出时空间不足有直接的关系。

ksedmp: internal OR fatal error
ORA-00600: internal error code, arguments: [kghstack_underflow_internal_3], [0xFFFFFD7FFB6D5FC0], [rpi ROLE SPACE], [], [], [], [], []
ORA-19502: WRITE error ON file "/oradata03/dmp/exp05.20100916.dmp", blockno 11292695 (blocksize=4096)
ORA-27063: NUMBER OF bytes READ/written IS incorrect
Solaris-AMD64 Error: 28: No SPACE LEFT ON device
Additional information: -1
Additional information: 262144
----- PL/SQL Call Stack -----
  object      line  object
  handle    NUMBER  name
5f8fb8b80        14  package body SYS.KUPD$DATA_INT
5f75ca850      1263  package body SYS.KUPD$DATA
5f8963a88     10716  package body SYS.KUPW$WORKER
5f8963a88      2575  package body SYS.KUPW$WORKER
5f8963a88      6868  package body SYS.KUPW$WORKER
5f8963a88      1259  package body SYS.KUPW$WORKER
5d8f07c38         2  anonymous block
----- Call Stack Trace -----
calling              CALL     entry                argument VALUES IN hex      
location             TYPE     point                (? means dubious VALUE)     
-------------------- -------- -------------------- ----------------------------
ksedst()+23          ?        0000000000000000     0017B341C 000000000 0FFDEDDA0
                                                   0FFFFFD7F
ksedmp()+636         ?        0000000000000000     0017B1EB1 000000000 0FB6D5FC0
                                                   0FFFFFD7F
ksfdmp()+16          ?        0000000000000000     0017F4FF5 000000000 0FFDEDDE0
                                                   0FFFFFD7F
kgerinv()+257        ?        0000000000000000     0040D2E2E 000000000 0FB6D5F88
                                                   0FFFFFD7F
kgeasnmierr()+170    ?        0000000000000000     0040D3A5F 000000000 005F71AD8
                                                   000000000
kghstack_underflow_  ?        0000000000000000     0040CBA2F 000000000 000000001
internal()+330                                     000000000
kghstack_free()+90   ?        0000000000000000     0040CADBF 000000000 005F5F848
                                                   000000000
ksmfrs()+19          ?        0000000000000000     0018C6E38 000000000 0FFDEDFF0
                                                   0FFFFFD7F
kluucln()+95         ?        0000000000000000     0038BCD84 000000000 0FC0E01F0
                                                   0FFFFFD7F
kluabort()+224       ?        0000000000000000     0038C7235 000000000 0FFDF38D8
                                                   0FFFFFD7F
kpodpmop()+930       ?        0000000000000000     0036CCFE7 000000000 000000000
                                                   000000000
opiodr()+1087        ?        0000000000000000     000E97C5C 000000000 005F84678
                                                   000000000
kpoodr()+459         ?        0000000000000000     002900D90 000000000 0FC02BFF0
                                                   0FFFFFD7F
upirtrc()+801        ?        0000000000000000     003C7E56E 000000000 000000000
                                                   000000000
kpurcsc()+107        ?        0000000000000000     003C02670 000000000 000000000
                                                   000000000
kpudprc()+361        ?        0000000000000000     003C1E48E 000000000 000000000
                                                   000000000
kpudpxa_ctxAbort()+  ?        0000000000000000     003C156BA 000000000 0FC45E8D0
645                                                0FFFFFD7F
OCIDirPathAbort()+6  ?        0000000000000000     003C578DB 000000000 0FFDF3960
                                                   0FFFFFD7F
kupd_finish()+183    ?        0000000000000000     00360EF4C 000000000 000000000
                                                   000000000

从详细TRACE信息中，没有找到进一步有价值的信息，随后查询了MOS，发现ORA-600 [Kghstack_underflow_internal_3], [Rpi Role Space] ORA-19502 ORA-27072 [ID 862398.1]文档和当前的描述最为借鉴，虽然最后一个错误信息并不一致，但是问题和现象基本上都和MOS中记录的十分相似。不同之处在于，MOS的中的文章是在进行RMAN备份时，而当前的问题是在进行数据泵导出。由于最后的错误都与操作系统上的具体错误有关，而MOS中的系统是Linux，而当前是Solaris 10，所以二者存在一定的差异是很正常的。
由于是空间不足引发的错误，因此借鉴问题的方法也很简单，删除不需要的对象，确保导出路径下有空闲的既可避免这个错误的。

Posted in BUG | Tagged , , | Leave a comment

ORA-600(kcrrupirfs.20)错误

Posted on 2011/11/06 by yangtingkun

在客户的数据库告警日志中发现这个错误。
错误信息如下：

Thu Sep 29 14:29:26 2011
ALTER DATABASE force logging
Thu Sep 29 14:29:26 2011
ALTER DATABASE FORCE LOGGING command IS waiting FOR existingdirect writes TO finish. This may take a long TIME.
Completed: ALTER DATABASE force logging
LAST_CHECK
Thu Sep 29 14:32:54 2011
ALTER SYSTEM SET log_archive_dest_2='service=dbnamepri lgwr async valid_for=(ONLINE_LOGFILES,PRIMARY_ROLE) db_unique_name=dbnamepri' SCOPE=BOTH;
Thu Sep 29 14:33:08 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_262532.trc:
ORA-16057: DGID FROM server NOT IN DATA Guard configuration
Thu Sep 29 14:33:08 2011
PING[ARC0]: Heartbeat failed TO CONNECT TO standby 'dbnamepri'. Error IS 16057.
Thu Sep 29 14:34:01 2011
ALTER SYSTEM SET log_archive_config='DG_CONFIG=(dbnamedb,dbnamepri)' SCOPE=BOTH;
Thu Sep 29 14:34:11 2011
ALTER SYSTEM SET fal_client='dbnamedb' SCOPE=BOTH;
Thu Sep 29 14:34:12 2011
ALTER SYSTEM SET fal_server='dbnamepri' SCOPE=BOTH;
Thu Sep 29 14:34:23 2011
ALTER SYSTEM SET standby_file_management='auto' SCOPE=BOTH;
Thu Sep 29 14:34:33 2011
ARC0: STARTING ARCH PROCESSES
Thu Sep 29 14:34:33 2011
ALTER SYSTEM SET log_archive_max_processes=3 SCOPE=BOTH;
Thu Sep 29 14:34:33 2011
ALTER SYSTEM SET db_file_name_convert='/dev/','/dev/' SCOPE=SPFILE;
ARC2: Archival started
ARC0: STARTING ARCH PROCESSES COMPLETE
ARC2 started WITH pid=83, OS id=1020046
Thu Sep 29 14:34:34 2011
ALTER SYSTEM SET log_file_name_convert='/dev/','/dev/' SCOPE=SPFILE;
Thu Sep 29 14:37:28 2011
ALTER SYSTEM SET log_archive_dest_state_1='enable' SCOPE=BOTH;
Thu Sep 29 14:37:29 2011
ALTER SYSTEM SET log_archive_dest_state_2='enable' SCOPE=BOTH;
Thu Sep 29 14:38:16 2011
ARCH: Possible network disconnect WITH PRIMARY DATABASE
LNS1 started WITH pid=133, OS id=745664
Thu Sep 29 15:12:11 2011
Thread 1 advanced TO log SEQUENCE 58300
CURRENT log# 2 seq# 58300 mem# 0: /dev/ryredodbs02
Thu Sep 29 15:12:12 2011
******************************************************************
LGWR: Setting 'active' archival FOR destination LOG_ARCHIVE_DEST_2
******************************************************************
LNS: Standby redo logfile selected FOR thread 1 SEQUENCE 58300 FOR destination LOG_ARCHIVE_DEST_2
Thu Sep 29 15:15:02 2011
Thread 1 advanced TO log SEQUENCE 58301
CURRENT log# 1 seq# 58301 mem# 0: /dev/ryredodbs01
Thu Sep 29 15:15:03 2011
LNS: Standby redo logfile selected FOR thread 1 SEQUENCE 58301 FOR destination LOG_ARCHIVE_DEST_2
Thu Sep 29 15:15:51 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_262532.trc:
ORA-00600: internal error code, arguments: [kcrrupirfs.20], [3], [0], [], [], [], [], []
Thu Sep 29 15:15:53 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_262532.trc:
ORA-00600: internal error code, arguments: [kcrrupirfs.20], [3], [0], [], [], [], [], []
Thu Sep 29 15:15:53 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_262532.trc:
ORA-00600: internal error code, arguments: [kcrrupirfs.20], [3], [0], [], [], [], [], []
Thu Sep 29 15:15:53 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_262532.trc:
ORA-00600: internal error code, arguments: [kcrrupirfs.20], [3], [0], [], [], [], [], []
Thu Sep 29 15:15:53 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_262532.trc:
ORA-00600: internal error code, arguments: [kcrrupirfs.20], [3], [0], [], [], [], [], []
Thu Sep 29 15:15:53 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_262532.trc:
ORA-00600: internal error code, arguments: [kcrrupirfs.20], [3], [0], [], [], [], [], []
Thu Sep 29 15:15:55 2011
ARCH: Detected ARCH process failure
ARCH: STARTING ARCH PROCESSES
ARC0: Archival started
ARCH: STARTING ARCH PROCESSES COMPLETE
ARC0 started WITH pid=112, OS id=1052728
ARC0: Becoming the heartbeat ARCH

客户的10G DATA GUARD环境，在新增一个物理DATA GUARD配置的时候出现了ORA-600错误。
这个ORA-600[kcrrupirfs.20]的错误在metalink上的记录并不多，绝大部分都是和归档相关，不过具体分析对于当前错误的借鉴并不大。
不过仔细看了一下错误发生之前所进行的修改，就基本清楚导致问题的原因了。
客户在配置新的DATA GUARD的时候，先设置了LOG_ARCHIVE_DEST_N参数，然后才设置LOG_ARCHIVE_CONFIG参数。而Oracle会在配置LOG_ARCHIVE_DEST_N参数的时候，根据DB_UNIQUE_NAME的值到LOG_ARCHIVE_CONFIG的DG_CONFIG配置中寻找对应的值，如果没有找到，就会引发错误。而随后设置LOG_ARCHIVE_CONFIG参数的时候并不会引发LOG_ARCHIVE_DEST_N参数重新解析，所以这个问题一直没有解决。
以前这种错误碰到过很多次了，但是出现ORA-600错误的还是第一次。解决方法很简单，只需要设置LOG_ARCHIVE_DEST_STATE_N参数就可以使得LOG_ARCHIVE_DEST_N重新进行解析：

Thu Sep 29 15:44:24 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_803104.trc:
ORA-00600: internal error code, arguments: [kcrrupirfs.20], [3], [0], [], [], [], [], []
Thu Sep 29 15:44:24 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_803104.trc:
ORA-00600: internal error code, arguments: [kcrrupirfs.20], [3], [0], [], [], [], [], []
Thu Sep 29 15:44:25 2011
ARCH: Detected ARCH process failure
ARCH: STARTING ARCH PROCESSES
ARC0: Archival started
ARCH: STARTING ARCH PROCESSES COMPLETE
ARC0 started WITH pid=112, OS id=876882
ARC0: Becoming the heartbeat ARCH
Thu Sep 29 15:44:25 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_876882.trc:
ORA-00317: file TYPE 0 IN header IS NOT log file
ORA-00334: archived log: '/arch/1_58212_665274343.dbf'
Thu Sep 29 15:44:25 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_876882.trc:
ORA-00317: file TYPE 0 IN header IS NOT log file
ORA-00334: archived log: '/arch/1_58212_665274343.dbf'
FAL[server, ARC0]: FAL archive failed, see trace file.
Thu Sep 29 15:44:25 2011
Errors IN file /oracle/admin/dbnamedb/bdump/dbnamedb_arc0_876882.trc:
ORA-16055: FAL request rejected
ARCH: FAL archive failed. Archiver continuing
Thu Sep 29 15:44:25 2011
ORACLE Instance dbnamedb - Archival Error. Archiver continuing.
Thu Sep 29 15:44:39 2011
ALTER SYSTEM SET log_archive_dest_state_2='reset' SCOPE=BOTH;
Thu Sep 29 15:44:45 2011
Errors IN file /oracle/admin/dbnamedb/udump/dbnamedb_fal_1024178.trc:
ORA-00317: file TYPE 0 IN header IS NOT log file
ORA-00334: archived log: '/arch/1_58212_665274343.dbf'
Thu Sep 29 15:44:46 2011
FAL[server]: Fail TO queue the whole FAL gap
GAP - thread 1 SEQUENCE 58212-58212
DBID 381481151 branch 665274343
Thu Sep 29 15:55:49 2011
ALTER SYSTEM SET log_archive_dest_state_2='enable' SCOPE=BOTH;
Thu Sep 29 16:02:48 2011
Thread 1 advanced TO log SEQUENCE 58302
CURRENT log# 3 seq# 58302 mem# 0: /dev/ryredodbs03
Thu Sep 29 16:02:49 2011
******************************************************************
LGWR: Setting 'active' archival FOR destination LOG_ARCHIVE_DEST_2
******************************************************************
LNS: Standby redo logfile selected FOR thread 1 SEQUENCE 58302 FOR destination LOG_ARCHIVE_DEST_2
Thu Sep 29 16:17:06 2011
Thread 1 advanced TO log SEQUENCE 58303
CURRENT log# 2 seq# 58303 mem# 0: /dev/ryredodbs02
Thu Sep 29 16:17:07 2011
LNS: Standby redo logfile selected FOR thread 1 SEQUENCE 58303 FOR destination LOG_ARCHIVE_DEST_2
Thu Sep 29 16:47:40 2011
Thread 1 advanced TO log SEQUENCE 58304
CURRENT log# 1 seq# 58304 mem# 0: /dev/ryredodbs01
Thu Sep 29 16:47:41 2011
LNS: Standby redo logfile selected FOR thread 1 SEQUENCE 58304 FOR destination LOG_ARCHIVE_DEST_2

可以看到，设置LOG_ARCHIVE_DEST_STATE_2参数后，问题解决。
对于物理DATA GUARD在设置参数时，一定要注意顺序，LOG_ARCHIVE_CONFIG参数要在LOG_ARCHIVE_DEST_N之前进行设置。

Posted in BUG | Tagged , , , , , | Leave a comment