我们的文章会在微信公众号IT民工的龙马人生和博客网站( www.htz.pw )同步更新 ，欢迎关注收藏，也欢迎大家转载，但是请在文章开始地方标注文章出处，谢谢！
由于博客中有大量代码，通过页面浏览效果更佳。
Oracle故障处理：create table 引起select语句hang住出现library cache lock事件
今天在9i中遇到了library cache lock/pin等待事件，结果是由于出帐还没有完成，用户还在执行create table相关的表，其它一些应用就已经在对表进行查询了，下面是模拟整个事件。测试环境为：DB :RHEL 4.8 OS :10.2.0.4
1，会话1创建一张TEST1表，数据来至于test表，这里test表最好大一些，不然还没有暂停进程就已经创建完成 。
www.htz.pw >create table scott.test1 as select * from scott.test;
2，暂停会话1
www.htz.pw >oradebug setospid 8729
Oracle pid: 15, Unix process pid: 8729, image: oracle@rhel4.htz.pw (TNS V1-V3)
www.htz.pw >oradebug event 10046 trace name context forever,level 12;
Statement processed.
www.htz.pw >oradebug suspend;
Statement processed.
www.htz.pw >oradebug tracefile_name;
/u01/app/oracle/admin/orcl10g/udump/orcl10g_ora_8729.trc
这里的trace 10046主要是想确认进程是否真的没有动了
3，会话2对test1表进行查询，结果hang住
[oracle10g@rhel4 sql]$ sqlplus / as sysdbaSQL*Plus: Release 10.2.0.4.0 - Production on Mon Jun 3 21:56:34 2013Copyright (c) 1982, 2007, Oracle. All Rights Reserved.Connected to:
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing optionswww.htz.pw >select * from scott.test1;
结果hang住了
4，通过dump systemstate来分析
使用library cache来查找PROCESS 20:----------------------------------------SO: 0x79e65108, type: 2, owner: (nil), flag: INIT/-/-/0x00(process) Oracle pid=20, calls cur/top: 0x79faf308/0x79fae7f0, flag: (0) -int error: 0, call error: 0, sess error: 0, txn error 0(post info) last post received: 0 0 0last post received-location: No postlast process to post me: nonelast post sent: 0 0 0last post sent-location: No postlast process posted by me: none(latch info) wait_event=0 bits=0Process Group: DEFAULT, pseudo proc: 0x79ea6808O/S info: user: oracle10g, term: pts/3, ospid: 8867OSD pid info: Unix process pid: 8867, image: oracle@rhel4.htz.pw (TNS V1-V3)
Dump of memory from 0x0000000079E4AAD8 to 0x0000000079E4ACE0
079E4AAD0 00000005 00000000 [........]
079E4AAE0 76BA8B30 00000000 00000010 000313A7 [0..v............]
079E4AAF0 79FAE7F0 00000000 00000003 000313A7 [...y............]
079E4AB00 7958C260 00000000 0000000B 000313A7 [`.Xy............]
079E4AB10 79F72930 00000000 00000004 0003129B [0).y............]
079E4AB20 78E0BB28 00000000 00000007 000313A7 [(..x............]
079E4AB30 00000000 00000000 00000000 00000000 [................]Repeat 26 times(FOB) flags=2 fib=0x78f697c8 incno=6 pending i/o cnt=0fname=/u01/app/oracle/oradata/orcl10g/system01.dbffno=1 lblksz=8192 fsiz=61440----------------------------------------SO: 0x79f72930, type: 4, owner: 0x79e65108, flag: INIT/-/-/0x00(session) sid: 147 trans: (nil), creator: 0x79e65108, flag: (80000041) USR/- BSY/-/-/-/-/-DID: 0001-0014-00000001, short-term DID: 0000-0000-00000000txn branch: (nil)oct: 3, prv: 0, sql: 0x75340208, psql: (nil), user: 0/SYSservice name: SYS$USERSO/S info: user: oracle10g, term: pts/3, ospid: 8866, machine: rhel4.htz.pwprogram: sqlplus@rhel4.htz.pw (TNS V1-V3)application name: sqlplus@rhel4.htz.pw (TNS V1-V3), hash value=3044132538waiting for 'library cache lock' blocking sess=0x(nil) seq=11 wait_time=0 seconds since wait started=270handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9Dumping Session Wait Historyfor 'library cache lock' count=1 wait_time=2933014handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2930481handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2930503handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2932879handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2938262handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2930560handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2930628handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2953161handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2930606handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9for 'library cache lock' count=1 wait_time=2934815handle address=75346180, lock address=76b9b5f0, 100*mode+namespace=c9
通过handle address地址找到了如下信息
PROCESS 15:----------------------------------------SO: 0x79e62980, type: 2, owner: (nil), flag: INIT/-/-/0x00(process) Oracle pid=15, calls cur/top: 0x79fab8d0/0x79fa86f0, flag: (0) -int error: 0, call error: 0, sess error: 0, txn error 0(post info) last post received: 0 0 25last post received-location: ksasnrlast process to post me: 79e5da70 1 6last post sent: 0 0 24last post sent-location: ksasndlast process posted by me: 79e5e258 1 6 (latch info) wait_event=0 bits=0Process Group: DEFAULT, pseudo proc: 0x79ea6808O/S info: user: oracle10g, term: pts/0, ospid: 8729OSD pid info: Unix process pid: 8729, image: oracle@rhel4.htz.pw (TNS V1-V3)Short stack dump: .........................................................................
首先是找到下面的信息，再使用ctrl+b向前找，就可以找到前面的会话信息----------------------------------------SO: 0x79faf308, type: 3, owner: 0x79fae7f0, flag: INIT/-/-/0x00(call) sess: cur 79f72930, rec 0, usr 79f72930; depth: 1----------------------------------------SO: 0x76b9b5f0, type: 53, owner: 0x79faf308, flag: INIT/-/-/0x00LIBRARY OBJECT LOCK: lock=76b9b5f0 handle=75346180 request=Scall pin=(nil) session pin=(nil) hpc=0003 hlc=0000htl=0x76b9b670[0x76f1c7c8,0x76f1c7c8] htb=0x76f1c7c8 ssga=0x76f1b8c0user=79f72930 session=79f72930 count=0 flags=RES/[0010] savepoint=0x20LIBRARY OBJECT HANDLE: handle=75346180 mtx=0x753462b0(0) cdp=0name=SCOTT.TEST1SO: 0x76b24238, type: 54, owner: 0x784d4cb8, flag: INIT/-/-/0x00LIBRARY OBJECT PIN: pin=76b24238 handle=75346180 mode=X lock=0user=79f82a10 session=79f82a10 count=1 mask=0709 savepoint=0x15a615 flags=[00]----------------------------------------SO: 0x76bb7a60, type: 53, owner: 0x784d4cb8, flag: INIT/-/-/0x00LIBRARY OBJECT LOCK: lock=76bb7a60 handle=75346180 mode=Xcall pin=(nil) session pin=(nil) hpc=0000 hlc=0000htl=0x76bb7ae0[0x76b23058,0x76b23058] htb=0x76b23058 ssga=0x76b22150user=79f82a10 session=79f82a10 count=1 flags=[0000] savepoint=0x15a615LIBRARY OBJECT HANDLE: handle=75346180 mtx=0x753462b0(0) cdp=0name=SCOTT.TEST1hash=df25314504e786643e240bf673cd59df timestamp=06-03-2013 21:56:00 previous=NULLnamespace=TABL flags=KGHP/TIM/PTM/SML/[02000000]kkkk-dddd-llll=0000-0709-0201 lock=X pin=X latch#=2 hpc=0004 hlc=0002lwt=0x75346228[0x76b9b620,0x76b9b620] ltm=0x75346238[0x75346238,0x75346238]pwt=0x753461f0[0x753461f0,0x753461f0] ptm=0x75346200[0x75346200,0x75346200]ref=0x75346258[0x75346258,0x75346258] lnd=0x75346270[0x75346270,0x75346270]LIBRARY OBJECT: object=74f77a58
这一段进程的开始部分以" name="就可以找到下面的SQL语句
LIBRARY OBJECT HANDLE: handle=7534ad10 mtx=0x7534ae40(1) cdp=1name=create table scott.test1 as select * from scott.testhash=8ec1c218b47eeb3b9ca907ad0a10a75a timestamp=06-03-2013 21:55:59namespace=CRSR flags=RON/KGHP/TIM/PN0/SML/KST/DBN/MTX/[120100d0]
5，通过手动查询视图
www.htz.pw >set lines 170
www.htz.pw >desc dba_kgllock; Name Null? Type----------------------------------------------------------------------------------------------- -------- ----------------------------------------------------------------KGLLKUSE RAW(8)KGLLKHDL RAW(8)KGLLKMOD NUMBERKGLLKREQ NUMBERKGLLKTYPE VARCHAR2(4)www.htz.pw >select * from dba_kgllock where kgllkreq>0;KGLLKUSE KGLLKHDL KGLLKMOD KGLLKREQ KGLL
---------------- ---------------- ---------- ---------- ----
0000000079F72930 0000000075346180 0 2 Lockwww.htz.pw >select * from dba_kgllock where kgllkhdl='0000000075346180' order by kgllkuse;KGLLKUSE KGLLKHDL KGLLKMOD KGLLKREQ KGLL
---------------- ---------------- ---------- ---------- ----
0000000079F72930 0000000075346180 0 2 Lock
0000000079F82A10 0000000075346180 3 0 Pin
0000000079F82A10 0000000075346180 3 0 Lockwww.htz.pw >select sid,program,command from v$session where saddr='0000000079F82A10';SID PROGRAM COMMAND
---------- ------------------------------------------------ ----------159 sqlplus@rhel4.htz.pw (TNS V1-V3) 1www.htz.pw >select action,name from audit_actions where action=1;ACTION NAME
---------- ----------------------------1 CREATE TABLEwww.htz.pw >select KGLNAOWN ,KGLNAOBJ from x$kglob where kglhdadr='0000000075346180';KGLNAOWN KGLNAOBJ
-------------------- ------------------------------
SCOTT TEST1
如果发现是library cache lock我们可以能x$kgllk等视图我们可以马上查找到一些更详细的信息。
如下。
www.htz.pw >l1* select kgllkses,kgllkhdl,kgllkmod,kgllkreq,user_name,kglnaobj from x$kgllk where kgllkhdl='0000000075346180'
www.htz.pw >.
www.htz.pw >/KGLLKSES KGLLKHDL KGLLKMOD KGLLKREQ USER_NAME KGLNAOBJ
---------------- ---------------- ---------- ---------- ------------------------------ --------------------
0000000079F82A10 0000000075346180 3 0 SYS TEST1
0000000079F72930 0000000075346180 0 2 SYS TEST1
select kgllkses,kgllkhdl,kgllkmod,kgllkreq,user_name,kglnaobj from x$kgllk where kgllkses='0000000079F82A10' and kgllkmod>0;
这样就可以看到是那句话导致的hang住的了。
6，通过写的脚本来直接查询
www.htz.pw >@event_library_cache_pin_9i.sql
Wrote file sqlplussetUSERNAME LOCK
SID:SERIAL:SPID:LAST_CALL_ET STATUS HASH_VALUE HAVE:REQ HANDLE COMMAND LOCK LOGON_TI PROGRAM CLIENT
----------------------------------- -------------------- ------------- -------- ---------------- --------------- ---- -------- -------------------- --------------------
Holder: 1:159:3:8729.2138 SYS:ACTIVE 168863578 3.0 0000000075346180 CREATE TABLE Lock 03 21:43 sqlplus@rhel4.htz.pw oracle10g@rhel4.htz
Holder: 1:159:3:8729.2138 SYS:ACTIVE 168863578 3.0 0000000075346180 CREATE TABLE Pin 03 21:43 sqlplus@rhel4.htz.pw oracle10g@rhel4.htz
Waiter: 1:147:28:8867.2096 SYS:ACTIVE 3526267018 0.2 0000000075346180 SELECT Lock 03 21:56 sqlplus@rhel4.htz.pw oracle10g@rhel4.htzADDR handle KGLHDPAR KGLNAOWN KGLNAOBJ KGLNAHSH KGLHDOBJ
---------------- ---------------- ---------------- -------------------- -------------------- ---------- ----------------
0000002A97420498 0000000075346180 0000000075346180 SCOTT TEST1 1942837727 0000000074F77A58www.htz.pw >select event from v$session_wait where sid=159;EVENT
----------------------------------------------------------------
Data file init writewww.htz.pw >select sql_text from v$sql where hash_value=168863578;SQL_TEXT
--------------------------------------------------------------------------------
create table scott.test1 as select * from scott.test
这里发生通过hash_value找不到sql的具体内容，下面是通过errorstack的方式来查询到的内容
www.htz.pw >select sql_text from v$sql where hash_value=3526267018;no rows selectedwww.htz.pw >oradebug dump errorstack 2;
Statement processed.
www.htz.pw >oradebug tracefile_name;
/u01/app/oracle/admin/orcl10g/udump/orcl10g_ora_8867.trc
www.htz.pw >!vi /u01/app/oracle/admin/orcl10g/udump/orcl10g_ora_8867.trc
/u01/app/oracle/admin/orcl10g/udump/orcl10g_ora_8867.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /u01/app/oracle/product/10.2.0/db_1
System name: Linux
Node name: rhel4.htz.pw
Release: 2.6.9-89.0.0.0.1.ELsmp
Version: #1 SMP Tue May 19 05:31:20 EDT 2009
Machine: x86_64
Instance name: orcl10g
Redo thread mounted by this instance: 1
Oracle process number: 20
Unix process pid: 8867, image: oracle@rhel4.htz.pw (TNS V1-V3)*** 2013-06-03 22:35:00.278
*** ACTION NAME:() 2013-06-03 22:35:00.274
*** MODULE NAME:(sqlplus@rhel4.htz.pw (TNS V1-V3)) 2013-06-03 22:35:00.274
*** SERVICE NAME:(SYS$USERS) 2013-06-03 22:35:00.274
*** SESSION ID:(147.28) 2013-06-03 22:35:00.274
Received ORADEBUG command 'dump errorstack 2' from process Unix process pid: 9029, image:
*** 2013-06-03 22:35:00.278
ksedmp: internal or fatal error
Current SQL statement for this session:
select * from scott.test1
----- Call Stack Trace ----
------------------作者介绍-----------------------
姓名：黄廷忠
个人博客: (http://www.htz.pw)
CSDN地址: (https://blog.csdn.net/wwwhtzpw)
博客园地址: (https://www.cnblogs.com/www-htz-pw)
![P7353 [2020-2021 集训队作业] Tom Jerry 题解](http://pic.xiahunao.cn/P7353 [2020-2021 集训队作业] Tom Jerry 题解)
