Home
> Troubleshooting > Library Cache Revalidation
Library Cache Revalidation
Today got ticket from user saying when he tries to run some package from pl/sql developer he was getting ORA-0600 error. This is a rac environment. And looking into logs it shows like this.
Errors in file /app/u01/oracle/admin/xxxxxxxx/udump/xxxxxxxx1_ora_10546.trc: ORA-00600: internal error code, arguments: [17069], [0x3AD0EFA28], [], [], [], [], [], [] Tue Nov 9 17:00:20 2010 Errors in file /app/u01/oracle/admin/xxxxxxxx/udump/xxxxxxxx1_ora_10546.trc: ORA-00600: internal error code, arguments: [17069], [0x3AD0EFA28], [], [], [], [], [], [] Tue Nov 9 17:03:19 2010 Errors in file /app/u01/oracle/admin/xxxxxxxx/udump/xxxxxxxx1_ora_19153.trc: ORA-00600: internal error code, arguments: [17069], [0x3AD0EFA28], [], [], [], [], [], [] Tue Nov 9 17:11:29 2010 Errors in file /app/u01/oracle/admin/xxxxxxxx/udump/xxxxxxxx1_ora_7585.trc: ORA-00600: internal error code, arguments: [17069], [0x3AD0EFA28], [], [], [], [], [], [] Inside one of the trace file this was the actual reason for ORA-0600 ksedmp: internal or fatal error ORA-00600: internal error code, arguments: [17069], [0x3AD0EFA28], [], [], [], [], [], [] Current SQL statement for this session: ALTER PACKAGE X_PKG COMPILE DEBUG BODY ----- Call Stack Trace -----
Good thing was this was reproducable. Let’s see whats happening (Removed Some lines)
Sys@xxxxxxxx-Db> @sw 109
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
109 WORKING On CPU / runqueue 158 2 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 2 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 2 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 2 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 5 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 5 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 5 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 5 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 5 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 8 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 8 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 8 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 8 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 11 file#= 1 block#= 50421 class#= 1
109 WORKING On CPU / runqueue 158 11 file#= 1 block#= 50421 class#= 1
Sys@xxxxxxxx-Db> @sw 109
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
109 WORKING On CPU / runqueue 158 11 file#= 1 block#= 50421 class#= 1
Sys@xxxxxxxx-Db> @sw 109
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
109 WAITING library cache revalidation 230 0 = 0 = 0 = 0
109 WAITING library cache revalidation 230 0 = 0 = 0 = 0
109 WAITING library cache revalidation 233 3 = 0 = 0 = 0
109 WAITING library cache revalidation 242 0 = 0 = 0 = 0
109 WAITING library cache revalidation 245 0 = 0 = 0 = 0
109 WAITING library cache revalidation 245 0 = 0 = 0 = 0
Sys@xxxxxxxx-Db> @sw 109
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
109 WAITING library cache revalidation 248 0 = 0 = 0 = 0
Sys@xxxxxxxx-Db> @sw 109
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------ ------------------ ------------------ ------------------------------------------
109 WORKING On CPU / runqueue 250 3 handle address= pin address= 100*mode+namespace 0x00000003AD0EFA28
0x00000003AD0EFA28 0x00000003D88E3AE0 = 301
If you can see last part of above output it's of library cache pin address. Hmmm what's that
EVENT# EVENT_NAME WAIT_CLASS PARAMETER1 PARAMETER2 PARAMETER3
------ ------------------------------------------------------- ---------------------------------------------------------------- -------------------- -------------------- --------------------
828 library cache revalidation Other
Nothing much it revealed but just a guess that it would be doing some revalidation while pinning. So, may be this can say something.
NAMESPACE GETS GETHITS GETHITRATIO PINS PINHITS PINHITRATIO RELOADS INVALIDATIONS DLM_LOCK_REQUESTS DLM_PIN_REQUESTS DLM_PIN_RELEASES DLM_INVALIDATION_REQUESTS DLM_INVALIDATIONS
--------------- ---------- ---------- ----------- ---------- ---------- ----------- ---------- ------------- ----------------- ---------------- ---------------- ------------------------- -----------------
SQL AREA 2820321 2761475 .979134999 26958768 25610914 .950003131 599427 420656 0 0 0 0 0
TABLE/PROCEDURE 1234142 1226753 .994012845 8896006 8501055 .95560356 131353 0 2573846 1443656 125622 761931 41
BODY 140838 140630 .998523126 2196806 2196367 .999800164 104 0 4132 354 174 256 0
TRIGGER 7387 7268 .983890619 8950 8831 .986703911 0 0 716 119 113 30 0
INDEX 2899 1535 .529492929 13914 11288 .811269225 398 0 13905 5457 1767 4091 0
CLUSTER 37045 37034 .999703064 47543 47522 .999558295 10 0 47514 103 25 50 0
OBJECT 0 0 1 0 0 1 0 0 0 0 0 0 0
PIPE 0 0 1 0 0 1 0 0 0 0 0 0 0
JAVA SOURCE 361 271 .750692521 780 687 .880769231 0 0 748 90 88 1 0
JAVA RESOURCE 361 271 .750692521 780 688 .882051282 0 0 748 90 88 1 0
JAVA DATA 634 631 .995268139 693 689 .994227994 0 0 0 1327 0 1 0
So, it might be related to dlm or some bug. We have trace file which might give some information.
last wait for 'library cache pin' blocking sess=0x0 seq=228 wait_time=147 seconds since wait started=0
handle address=3ad0efa28, pin address=3d9f462b8, 100*mode+namespace=12d
Dumping Session Wait History
for 'library cache pin' count=1 wait_time=147
handle address=3ad0efa28, pin address=3d9f462b8, 100*mode+namespace=12d
for 'library cache lock' count=1 wait_time=816
handle address=3ad0efa28, lock address=3d8fc8d60, 100*mode+namespace=1f5
for 'library cache revalidation' count=1 wait_time=976592
=0, =0, =0
for 'library cache pin' count=1 wait_time=169
handle address=3ad0efa28, pin address=3d876f030, 100*mode+namespace=12d
for 'library cache lock' count=1 wait_time=798
handle address=3ad0efa28, lock address=3d8fc8d60, 100*mode+namespace=1f5
for 'library cache revalidation' count=1 wait_time=976593
=0, =0, =0
for 'library cache pin' count=1 wait_time=70
handle address=3ad0efa28, pin address=3d8fd1b18, 100*mode+namespace=12d
for 'library cache lock' count=1 wait_time=874
handle address=3ad0efa28, lock address=3d8fc8d60, 100*mode+namespace=1f5
for 'library cache revalidation' count=1 wait_time=976593
=0, =0, =0
for 'library cache pin' count=1 wait_time=159
handle address=3ad0efa28, pin address=3d9f46010, 100*mode+namespace=12d
temporary object counter: 0
---------------------------------------------
SO: 3d9f4cf50, type: 53, owner: 3dbf58278, flag: INIT/-/-/0x00
LIBRARY OBJECT LOCK: lock=3d9f4cf50 handle=3ad0efa28 mode=S
call pin=0 session pin=0 hpc=0000 hlc=0000
htl=3d9f4cfd0[3d876cde0,3d876cde0] htb=3d876cde0 ssga=3d876c5b8
user=3df3e78c8 session=3df3e78c8 count=1 flags=[0000] savepoint=0x78e
LIBRARY OBJECT HANDLE: handle=3ad0efa28 mtx=3ad0efb58(0) cdp=0
name=Y_PKG@P_LINK
hash=a6c4275f9f4a0c129193d936da96e571 timestamp=11-09-2010 15:48:24
namespace=TABL flags=REM/KGHP/TIM/XLR/[00020020]
kkkk-dddd-llll=0000-0005-0005 lock=S pin=S latch#=3 hpc=0028 hlc=0028
lwt=3ad0efad0[3ad0efad0,3ad0efad0] ltm=3ad0efae0[3ad0efae0,3ad0efae0]
pwt=3ad0efa98[3ad0efa98,3ad0efa98] ptm=3ad0efaa8[3ad0efaa8,3ad0efaa8]
ref=3ad0efb00[3ad0efb00,3ad0efb00] lnd=3ad0efb18[3ae7863e0,3acf5a198]
LOCK INSTANCE LOCK: id=LBa6c4275f9f4a0c12
PIN INSTANCE LOCK: id=NBa6c4275f9f4a0c12 mode=S release=F flags=[00]
LIBRARY OBJECT: object=3af176288
type=PCKG flags=EXS/LOC[0005] pflags=[0000] status=VALD load=0
DATA BLOCKS:
data# heap pointer status pins change whr
----- -------- -------- --------- ---- ------ ---
0 3c7261448 3af1763e0 I/P/A/-/- 0 NONE 00
---------------
D6F8F71A:39A56063 22 111 10425 33 kjss2m skip([0xa6c4275f][0x9f4a0c12],[LB])[owner 65558][held-mode 5]
D6F8F71E:39A56064 22 111 10005 1 KSL WAIT BEG [library cache revalidation] 0/0x0 0/0x0 0/0x0
D707DDF5:39A5626D 22 111 10005 2 KSL WAIT END [library cache revalidation] 0/0x0 0/0x0 0/0x0 time=976595
D707DE45:39A5626E 22 111 10706 6 0x000000001000010B 0x00000000A6C4275F 0x000000009F4A0C12 0x0000000000010020 0x0000000000000005 0x0000000000000000
D707DE85:39A5626F 22 111 10401 1 KSXPVSND: client 2 tid(2,257,0x56292b) buf 0x3dfd0f1b0 sz 128
D707DEE6:39A56270 22 111 10401 66 KSXP_SND_CALLBACK: request 0x0xffffffff7c0225e0, status 30
D707DEEB:39A56271 22 111 10401 71 KSXPWAIT: Send compl suppressed and No requests. proc 0x3df2fb7c0 haswrk 0
D707DEF1:39A56272 22 111 10005 1 KSL WAIT BEG [library cache lock] 15788341800/0x3ad0efa28 16164986736/0x3c3821f70 501/0x1f5
D707E2FA:39A56276 22 111 10005 2 KSL WAIT END [library cache lock] 15788341800/0x3ad0efa28 16164986736/0x3c3821f70 501/0x1f5 time=1034
D707E2FB:39A56277 22 111 10005 3 KSL POST RCVD poster=5 loc='kjata: wake up enqueue owner' id1=0 id2=0 name= type=0 fac#=0 facpost=1
D707E2FE:39A56278 22 111 10706 7 0x00000003DFC03C50 0x0000000000000000 0x00000000000004BA
D707E30D:39A56279 22 111 10005 4 KSL POST SENT postee=19 loc='ksasnd' id1=0 id2=0 name= type=0
D707E31A:39A5627A 22 111 10005 1 KSL WAIT BEG [library cache pin] 15788341800/0x3ad0efa28 16520867032/0x3d8b86cd8 301/0x12d
D707E3C1:39A5628F 22 111 10005 2 KSL WAIT END [library cache pin] 15788341800/0x3ad0efa28 16520867032/0x3d8b86cd8 301/0x12d time=167
D707E3C2:39A56291 22 111 10005 3 KSL POST RCVD poster=19 loc='kqlmbpil: last steps' id1=0 id2=0 name= type=0 fac#=0 facpost=1
D707E3DB:39A56292 22 111 10005 4 KSL POST SENT postee=19 loc='ksasnd' id1=0 id2=0 name= type=0
D707E3EA:39A56295 22 111 10706 15 0x00000003DFC03C50 0x0000000000000000
D707E3F2:39A56298 22 111 10425 33 kjss2m skip([0xa6c4275f][0x9f4a0c12],[LB])[owner 65558][held-mode 5]
D707E416:39A562A7 22 111 10706 6 0x000000001000010B 0x00000000A6C4275F 0x000000009F4A0C12 0x0000000000010020 0x0000000000000003 0x0000000000000000
D707E426:39A562A8 22 111 10706 7 0x00000003DFC03C50 0x0000000000000000 0x000000000000000F
D707E42A:39A562A9 22 111 10706 15 0x00000003DFC03C50 0x0000000000000000
D707E42B:39A562AA 22 111 10425 33 kjss2m skip([0xa6c4275f][0x9f4a0c12],[LB])[owner 65558][held-mode 5]
D707E42F:39A562AB 22 111 10005 1 KSL WAIT BEG [library cache revalidation] 0/0x0 0/0x0 0/0x0
D716CB07:39A564D7 22 111 10005 2 KSL WAIT END [library cache revalidation] 0/0x0 0/0x0 0/0x0 time=976596
So, library cache pin is trying to get exclusive lock while library cahce lock is trying to get shared row exclusive on package/package header. Also, it seems that library cache revalidation event, where most of the time is spent and also that function partially says it’s DLM related ones. Moreover, it likely be something related to inter instance checkup for library cache as this is an rac environment(Just a Guess) and KSL POST event suggest it’s KQLM(invalidation instance lock operation/Pin Instance Lock)
Just to try luck and ofcouse it was development database flushed shared pool and tried to recompile and it worked.(As Users are always in hurry)
So, still this wait is mistery. I will try to re-search more on this and will update this post. May be Tanel can Answer.
Categories: Troubleshooting
Hi,
Have you perhaps found out anything on this topic. We are having same error and waits on our 10.2.0.5 non-RAC database. After we recompiled all packages (one reporting the error and dependant ones), error was gone. But remains a mistery why this happened.
D.