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.

Advertisements

About Taral
I am Rookie to Oracle Technology so let's see where it goes

One Response to Library Cache Revalidation

  1. Domagoj says:

    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.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: