记一次exp hang故障处理

今天早上上班，刚刚上QQ，就有客户发来了离线消息。
[quote]*** 8:26:38
ora9i 8585370 33161666 0 02:00:00 - 0:00 exp '/ as sysdba' full=y compress=n consistent=y feedback=100000 direct=y file=/bak9i/backup/logical/full01.dmp,/bak9i/backup/logical/full02.dmp,/bak9i/backup/logical/full03.dmp,/bak9i/backup/logical/full04.dmp,/bak9i/backup/logical/full05.dmp,/bak9i/backup/logical/full06.dmp,/bak9i/backup/logical/full07.dmp,/bak9i/backup/logical/full08.dmp,/bak9i/backup/logical/full09.dmp,/bak9i/backup/logical/full10.dmp,/bak9i/backup/logical/full11.dmp,/bak9i/backup/logical/full12.dmp,/bak9i/backup/logical/full13.dmp,/bak9i/backup/logical/full14.dmp,/bak9i/backup/logical/full15.dmp,/bak9i/backup/logical/full16.dmp,/bak9i/backup/logical/full17.dmp,/bak9i/backup/logical/full18.dmp,/bak9i/backup/logical/full19.dmp,/bak9i/backup/logical/full20.dmp,/bak9i/backup/logical/full21.dmp,/bak9i/backup/logical/full22.dmp,/bak9i/backup/logical/full23.dmp,/bak9i/backup/logical/full24.dmp buffer=52428800 filesize=2000M log=/bak9i/backup/logical/full.log
ora9i 22937640 28180504 0 Mar 14 - 0:00 exp '/ as sysdba' full=y compress=n consistent=y feedback=100000 direct=y file=/bak9i/backup/logical/full01.dmp,/bak9i/backup/logical/full02.dmp,/bak9i/backup/logical/full03.dmp,/bak9i/backup/logical/full04.dmp,/bak9i/backup/logical/full05.dmp,/bak9i/backup/logical/full06.dmp,/bak9i/backup/logical/full07.dmp,/bak9i/backup/logical/full08.dmp,/bak9i/backup/logical/full09.dmp,/bak9i/backup/logical/full10.dmp,/bak9i/backup/logical/full11.dmp,/bak9i/backup/logical/full12.dmp,/bak9i/backup/logical/full13.dmp,/bak9i/backup/logical/full14.dmp,/bak9i/backup/logical/full15.dmp,/bak9i/backup/logical/full16.dmp,/bak9i/backup/logical/full17.dmp,/bak9i/backup/logical/full18.dmp,/bak9i/backup/logical/full19.dmp,/bak9i/backup/logical/full20.dmp,/bak9i/backup/logical/full21.dmp,/bak9i/backup/logical/full22.dmp,/bak9i/backup/logical/full23.dmp,/bak9i/backup/logical/full24.dmp buffer=52428800 filesize=2000M log=/bak9i/backup/logical/full.log
*** 8:26:44
看来我只有kill掉了
*** 8:28:55
ora9i@p750:/ora9i/admin/ytyy/bdump$ ps -ef | grep exp
ora9i 8585370 33161666 0 02:00:00 - 0:00 exp '/ as sysdba' full=y compress=n consistent=y feedback=100000 direct=y file=/bak9i/backup/logical/full01.dmp,/bak9i/backup/logical/full02.dmp,/bak9i/backup/logical/full03.dmp,/bak9i/backup/logical/full04.dmp,/bak9i/backup/logical/full05.dmp,/bak9i/backup/logical/full06.dmp,/bak9i/backup/logical/full07.dmp,/bak9i/backup/logical/full08.dmp,/bak9i/backup/logical/full09.dmp,/bak9i/backup/logical/full10.dmp,/bak9i/backup/logical/full11.dmp,/bak9i/backup/logical/full12.dmp,/bak9i/backup/logical/full13.dmp,/bak9i/backup/logical/full14.dmp,/bak9i/backup/logical/full15.dmp,/bak9i/backup/logical/full16.dmp,/bak9i/backup/logical/full17.dmp,/bak9i/backup/logical/full18.dmp,/bak9i/backup/logical/full19.dmp,/bak9i/backup/logical/full20.dmp,/bak9i/backup/logical/full21.dmp,/bak9i/backup/logical/full22.dmp,/bak9i/backup/logical/full23.dmp,/bak9i/backup/logical/full24.dmp buffer=52428800 filesize=2000M log=/bak9i/backup/logical/full.log
ora9i 22937640 28180504 0 Mar 14 - 0:00 exp '/ as sysdba' full=y compress=n consistent=y feedback=100000 direct=y file=/bak9i/backup/logical/full01.dmp,/bak9i/backup/logical/full02.dmp,/bak9i/backup/logical/full03.dmp,/bak9i/backup/logical/full04.dmp,/bak9i/backup/logical/full05.dmp,/bak9i/backup/logical/full06.dmp,/bak9i/backup/logical/full07.dmp,/bak9i/backup/logical/full08.dmp,/bak9i/backup/logical/full09.dmp,/bak9i/backup/logical/full10.dmp,/bak9i/backup/logical/full11.dmp,/bak9i/backup/logical/full12.dmp,/bak9i/backup/logical/full13.dmp,/bak9i/backup/logical/full14.dmp,/bak9i/backup/logical/full15.dmp,/bak9i/backup/logical/full16.dmp,/bak9i/backup/logical/full17.dmp,/bak9i/backup/logical/full18.dmp,/bak9i/backup/logical/full19.dmp,/bak9i/backup/logical/full20.dmp,/bak9i/backup/logical/full21.dmp,/bak9i/backup/logical/full22.dmp,/bak9i/backup/logical/full23.dmp,/bak9i/backup/logical/full24.dmp buffer=52428800 filesize=2000M log=/bak9i/backup/logical/full.log
ora9i 31916520 13173082 0 08:25:29 pts/0 0:00 grep exp
ora9i@p750:/ora9i/admin/ytyy/bdump$ kill -9 8585370
ora9i@p750:/ora9i/admin/ytyy/bdump$ kill -9 22937640
ora9i@p750:/ora9i/admin/ytyy/bdump$ ps -ef | grep exp
ora9i 24445036 13173082 0 08:27:58 pts/0 0:00 grep exp
*** 8:29:15
9i上逻辑导出不成功[/quote]
于是我让他查看/bak9i/backup/logical/full.log看看是什么内容，日志显示
[quote]. exporting database links
. exporting sequence numbers
. exporting directory aliases
. exporting context namespaces
. exporting foreign function library names
. exporting PUBLIC type synonyms
. exporting private type synonyms
. exporting object type definitions
. exporting system procedural objects and actions
. exporting pre-schema procedural objects and actions
. exporting cluster definitions[/quote]
也就意味着Oracle 9208在exp cluster定义的时候hang住了。我感觉这个问题，比较怪异，于是上metalink搜寻了一番，只有Bug 5035017: EXPORT HANGS ON CLUSTER DEFINITIONS - ORA-4021和此案例比较类似，此bug是发生在Oracle 10.1.0.4.0版本上，但目前的数据库是Oracle 9208且运行在AIX 6106之上。而且此bug exp错误时还伴随着ORA-4021产生。
[quote]EXP-56: ORACLE error 4021 encountered
ORA-4021: timeout occurred while waiting to lock object
ORA-6512: at "SYS.DBMS_METADATA", line 1511
ORA-6512: at "SYS.DBMS_METADATA", line 1548
ORA-6512: at "SYS.DBMS_METADATA", line 1864
ORA-6512: at "SYS.DBMS_METADATA", line 3707
ORA-6512: at "SYS.DBMS_METADATA", line 3689
ORA-6512: at line 1
EXP-0: Export terminated unsuccessfully[/quote]
这和本案例中有较大不同，但据bug描述，此问题和xml组件有一定的关系。于是进一步查看其生产库xml组件状态，果然处于invliad状态。
[quote]Oracle9i Catalog Views 9.2.0.8.0 VALID
Oracle9i Packages and Types 9.2.0.8.0 VALID
Oracle Workspace Manager 9.2.0.1.0 VALID
JServer JAVA Virtual Machine 9.2.0.8.0 VALID
Oracle XDK for Java 9.2.0.10.0 VALID
Oracle9i Java Packages 9.2.0.8.0 VALID
Oracle interMedia 9.2.0.8.0 VALID
Spatial 9.2.0.8.0 VALID
Oracle Text 9.2.0.8.0 VALID
[color=red]Oracle XML Database 9.2.0.8.0 INVALID[/color]
Oracle Ultra Search 9.2.0.8.0 VALID
Oracle Data Mining 9.2.0.8.0 VALID
OLAP Analytic Workspace 9.2.0.8.0 UPGRADED
Oracle OLAP API 9.2.0.8.0 UPGRADED
OLAP Catalog 9.2.0.8.0 VALID[/quote]
但这只能怀疑exp hang和xml有关。于是我又再次让客户运行exp脚本，观察v$session_wait等待事件出现library cache pin 事件。进一步细分查询
select * from v$lock where block=1;为空
[quote]select sid, event, p1raw, seconds_in_wait, wait_time from v$session where event='library cache pin';
333 library cache pin 07000003DD14C3A0 26530 0
387 library cache pin 07000003B8E14D60 255 0
646 library cache pin 07000003DD14C3A0 35987 0[/quote]
进一步查询x$kglob，查看其等待对象，出现关键字XM
[quote]col object for a200
SELECT kglnaown AS owner, kglnaobj as Object,kglhdadr
FROM sys.x$kglob
WHERE kglhdadr='07000003DD14C3A0';
1 SELECT VALUE(KU$) [color=red]XM[/color] 07000003DD14C3A0[/quote]
是以至此，基本上可以判断此问题和xml组件失效有关系。于是询问客户是否可以将此组件删除，确定之后执行以下脚本：
[quote]SQL> set echo on
SQL> set echo on
SQL> spool xdb_remove.log
SQL> @?/rdbms/admin/catnoqm.sql
SQL> Rem
SQL> Rem $Header: catnoqm.sql 03-jan-2002.17:32:31 spannala Exp $
SQL> Rem
SQL> Rem catnoqm.sql
SQL> Rem
SQL> Rem Copyright (c) 2001, 2002, Oracle Corporation. All rights reserved.
SQL> Rem
SQL> Rem NAME
SQL> Rem catnoqm.sql - CATalog script for removing (NO) XDB
SQL> Rem
SQL> Rem DESCRIPTION
SQL> Rem this script drops the metadata created for SQL XML management
SQL> Rem This scirpt must be invoked as sys. It is to be invoked as
SQL> Rem
SQL> Rem @@catnoqm
SQL> Rem NOTES
SQL> Rem
SQL> Rem MODIFIED (MM/DD/YY)
SQL> Rem spannala 01/03/02 - tables are not handled by xdb
SQL> Rem spannala 01/02/02 - registry
SQL> Rem spannala 12/20/01 - passing in the resource tablespace name
SQL> Rem tsingh 11/17/01 - remove connection string
SQL> Rem tsingh 06/30/01 - XDB: XML Database merge
SQL> Rem amanikut 02/13/01 - Creation
SQL> Rem
SQL> Rem
SQL>
SQL> execute dbms_registry.removing('XDB');

PL/SQL procedure successfully completed.

SQL> drop user xdb cascade;[/quote]
但是在drop user xdb cascade时又出现hang住现象。继续查询v$session_wait，出现
library cache lock等待事件。
[quote]SQL> select sid,event from v$session_wait where event not like '%SQL%';

SID EVENT
---------- ----------------------------------------------------------------
1 pmon timer
2 rdbms ipc message
3 rdbms ipc message
4 rdbms ipc message
5 rdbms ipc message
10 rdbms ipc message
12 rdbms ipc message
11 rdbms ipc message
9 rdbms ipc message
6 rdbms ipc message
7 rdbms ipc message

SID EVENT
---------- ----------------------------------------------------------------
21 db file sequential read
392 db file sequential read
8 smon timer
652 [color=red]library cache lock[/color]
122 jobq slave wait
462 jobq slave wait
591 jobq slave wait
327 jobq slave wait
457 jobq slave wait

20 rows selected.[/quote]
接下来就轮到解决library cache lock，具体过程看日志了。
[quote]SQL> select spid from v$process where addr =(select paddr from v$session where sid=652);

SPID
------------
15925756

SQL> !ps -ef|grep 15925756
ora9i 41615506 27918796 0 10:19:13 pts/0 0:00 grep 15925756
ora9i 15925756 43254130 0 10:15:22 - 0:00 oracleytyy (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

SQL> select b.sid,a.user_name,a.kglnaobj
from x$kgllk a , v$session b
where a.kgllkhd 2 3 l in
(select p1raw from v$session_wait
where wait_time=0 and event = 'library ca 4 5 che lock')
and a.kgllkmod <> 0
and b.saddr=a.kgllkuse 6 7 ;

SID USER_NAME
---------- ------------------------------
KGLNAOBJ
------------------------------------------------------------
21 SYS
[color=red]XDB$RESOURCE[/color]

392 YTYY
[color=red]XDB$RESOURCE[/color]


SQL> select sid,serial# from v$session where sid in (21,392);

SID SERIAL#
---------- ----------
21 31951
392 5343

SQL> select spid from v$process where addr in (select paddr from v$session where sid in (21,392));

SPID
------------
18547020
23200210

SQL> !ps -ef|grep 18547020
ora9i 38600852 27918796 0 10:23:02 pts/0 0:00 grep 18547020
ora9i 18547020 1 0 Mar 14 - 0:01 oracleytyy (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

SQL> !ps -ef|grep 23200210
ora9i 23200210 1 0 09:06:05 - 0:00 oracleytyy (LOCAL=NO)
ora9i 42140070 27918796 0 10:23:13 pts/0 0:00 grep 23200210

SQL> alter system kill session '21,31951';

alter system kill session '21,31951'
*
ERROR at line 1:
ORA-00031: session marked for kill


SQL> SQL> alter system kill session '392,5343';

alter system kill session '392,5343'
*
ERROR at line 1:
ORA-00031: session marked for kill


SQL> !ps -ef|grep 18547020
ora9i 18547020 1 0 Mar 14 - 0:01 oracleytyy (DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
ora9i 20709834 27918796 0 10:26:22 pts/0 0:00 grep 18547020

SQL> !kill -9 18547020

SQL> !ps -ef|grep 23200210
ora9i 18547022 27918796 0 10:26:48 pts/0 0:00 grep 23200210
ora9i 23200210 1 0 09:06:05 - 0:00 oracleytyy (LOCAL=NO)

SQL> !kill -9 23200210

SQL> select spid from v$process where addr in (select paddr from v$session where sid in (21,392));

SPID
------------
18547020
23200210

SQL> select b.sid,a.user_name,a.kglnaobj
from x$kgllk a , v$session b
where a.kgllkhd 2 3 l in
(select p1raw from v$session_wait
where wait_time=0 and event = 'library cache lock')
and a.kgllkmod <> 0
and b.saddr=a.kgllkuse 4 5 6 7 ;

no rows selected[/quote]

解决了library cache lock，xdb用户也顺利删除。最终exp导出正常。

附：
9201客户端导9208数据库时出现
[quote]Table ODM_PMML_DTD will be exported in conventional path.
. . exporting table ODM_PMML_DTD
EXP-00003: no storage definition found for segment(7, 267)
. . exporting table ODM_P_I_ITEM_RULES[/quote]