DDL Parsing

Normally most DML/Select Statements are processed in like create cursor,parse,execute and fetch.

So, how about DDL statements ,how do they execute ? Answer is they execute in only two pass. creating cursor and parsing. Parse phase itself execute it. Let’s see example and put tracing on.

 


create table taral.test1(col1 number);

PARSING IN CURSOR #33 len=37 dep=0 uid=0 oct=1 lid=0 tim=1663011419048 hv=2791204537 ad='30c534d4' sqlid='ad60h5qm5wtpt'
create table taral.test1(col1 number)
END OF STMT
PARSE #33:c=0,e=3415,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,plh=0,tim=1663011419047

EXEC #33:c=890625,e=2330367,p=855,cr=3343,cu=52,mis=0,r=0,dep=0,og=1,plh=0,tim=1663013749499
WAIT #33: nam='log file sync' ela= 95 buffer#=558 sync scn=7375981 p3=0 obj#=528 tim=1663013749698
WAIT #33: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=528 tim=1663013750627

*** 2010-11-29 15:29:04.822
WAIT #33: nam='SQL*Net message from client' ela= 3531454 driver id=1111838976 #bytes=1 p3=0 obj#=528 tim=1663017282121
CLOSE #33:c=0,e=23,dep=0,type=0,tim=1663017282280

This was the only cursor in trace file. But it did say that it got executed. Let’s see what happend here using another example.


SYS@taral AS SYSDBA> variable x1 number
SYS@taral AS SYSDBA> exec dbms_sql.parse ( : x1 ,'create table taral.test2(col1 number)',dbms_sql.native);
BEGIN dbms_sql.parse ( : x1 ,'create table taral.test2(col1 number)',dbms_sql.native); END;

*
ERROR at line 1:
ORA-29471: DBMS_SQL access denied
ORA-06512: at "SYS.DBMS_SQL", line 1053
ORA-06512: at line 1

Because, we have to open a cursor first.

SYS@taral AS SYSDBA> variable x1 number
SYS@taral AS SYSDBA> exec : x1:=dbms_sql.open_cursor;

PL/SQL procedure successfully completed.
----- Session Cursor Dump -----
Current cursor: 0, pgadep=0

Open cursors(pls, sys, hwm, max): 2(0, 2, 64, 300)
 NULL=1 SYNTAX=0 PARSE=0 BOUND=1 FETCH=0 ROW=0
Cached frame pages(total, free):
 4k(5, 5), 8k(0, 0), 16k(0, 0), 32k(0, 0)
----- Session Open Cursors -----

Lets parse DDL Statement

SYS@taral AS SYSDBA> exec dbms_sql.parse ( : x1 ,'create table taral.test2(col1 number)',dbms_sql.native);

PL/SQL procedure successfully completed.

SYS@taral AS SYSDBA> desc taral.test2;
 Name
 --------------------------------------
 COL1

So, it has created table in parse phase itself.


Cursor#3(0x0D1E0E1C) state=NULL curiob=0x0D6D5970
 curflg=4d fl2=0 par=0x00000000 ses=0x35A25B5C
----- Dump Cursor sql_id=bmv42n748kx2r xsc=0x0D6D5970 cur=0x0D1E0E1C -----

LibraryHandle:  Address=35d2fe4c Hash=c8897457 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=create table taral.test2(col1 number)

    FullHashValue=8eef83d6a3fe2933b9ec82a1c8897457 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3364451415 OwnerIdn=0
  Statistics:  InvalidationCount=1 ExecutionCount=1 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
  ...
  ...
  ...
 cursor instantiation=0x0D6D5970 used=1291067219 exec_id=0 exec=1
 child#0(0x00000000) pcs=0x2FCBD450
  clk=0x00000000 ci=0x00000000 pn=0x00000000 ctx=0x00000000
 kgsccflg=0 llk[0x0D6D5974,0x0D6D5974] idx=0
 xscflg=80002036 fl2=4060000 fl3=2042008 fl4=8000
 Frames pfr 0x0D6D5114 siz=0 efr 0x0D6D50C4 siz=0
 Cursor frame dump
 kxscphp=0x0D6D0034 siz=1000 inu=140 nps=140

We can see that executioncount is 1 here. Let’s check for select statement what happen


SYS@taral AS SYSDBA> variable y1 number

SYS@taral AS SYSDBA> exec : y1 := dbms_sql.open_cursor;
PL/SQL procedure successfully completed.

SYS@taral AS SYSDBA> exec dbms_sql.parse ( : y1 ,'select * from scott.emp where ename in(7369,7499,7521)',dbms_sql.native);
PL/SQL procedure successfully completed.

Cursor#6(0x0D1E0F3C) state=BOUND curiob=0x0D2819C8
 curflg=4d fl2=0 par=0x00000000 ses=0x35A25B5C
----- Dump Cursor sql_id=6mbszcqzu6wzp xsc=0x0D2819C8 cur=0x0D1E0F3C -----

LibraryHandle:  Address=2f55bbf4 Hash=bfa373f5 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=select * from scott.emp where ename in(7369,7499,7521)

    FullHashValue=b636966355abdb0569af1f65bfa373f5 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3215160309 OwnerIdn=0
  Statistics:  InvalidationCount=0 ExecutionCount=0 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=1 KeepHandle=1 BucketInUse=0
....
....
cursor instantiation=0x0D2819C8 used=1291068865 exec_id=0 exec=0
 child#0(0x2F55BABC) pcs=0x2E35E450
  clk=0x30C819B4 ci=0x2E35D0E4 pn=0x35DF458C ctx=0x2DFDDCF0
 kgsccflg=0 llk[0x0D2819CC,0x0D2819CC] idx=0
 xscflg=100076 fl2=40000 fl3=2062000 fl4=100
 Frames pfr 0x00000000 siz=3044 efr 0x00000000 siz=3036
 Cursor frame dump
  enxt: 2.0x00000100  enxt: 1.0x00000adc
  pnxt: 1.0x00000008

Now, lets execute it

SYS@taral AS SYSDBA> variable z number
SYS@taral AS SYSDBA> execute : z := dbms_sql.execute (:y1);

----- Dump Cursor sql_id=6mbszcqzu6wzp xsc=0x0D2819C8 cur=0x0D1E0F3C -----

LibraryHandle:  Address=2f55bbf4 Hash=bfa373f5 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=select * from scott.emp where ename in(7369,7499,7521)

    FullHashValue=b636966355abdb0569af1f65bfa373f5 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=3215160309 OwnerIdn=0
  Statistics:  InvalidationCount=0 ExecutionCount=1 LoadCount=2 ActiveLocks=1 TotalLockCount=1 TotalPinCount=1
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=1 KeepHandle=1 BucketInUse=0 HandleInUse=0
  Concurrency:  DependencyMutex=2f55bc5c(0, 0, 0, 0) Mutex=2f55bcac(9, 19, 0, 6)
  Flags=RON/PIN/TIM/PN0/DBN/[10012841]
  WaitersLists:
    Lock=2f55bc4c[2f55bc4c,2f55bc4c]
    Pin=2f55bc54[2f55bc3c,2f55bc3c]
  Timestamp:  Current=11-29-2010 16:14:25
  LibraryObject:  Address=2e35e060 HeapMask=0000-0001-0001 Flags=EXS[0000] Flags2=[0000] PublicFlags=[0000]
    ChildTable:  size='16'
      Child:  id='0' Table=2e35efb0 Reference=2e35e66c Handle=2f55babc
    Children:
      Child:  childNum='0'
        LibraryHandle:  Address=2f55babc Hash=0 LockMode=N PinMode=S LoadLockMode=0 Status=VALD
          Name:  Namespace=SQL AREA(00) Type=CURSOR(00)
          Statistics:  InvalidationCount=0 ExecutionCount=1 LoadCount=1 ActiveLocks=1 TotalLockCount=1 TotalPinCount=2
          Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=0 KeepHandle=0 BucketInUse=0 HandleInUse=0
          Concurrency:  DependencyMutex=2f55bb24(0, 0, 0, 0) Mutex=2f55bcac(9, 19, 0, 6)
          Flags=RON/PIN/PN0/EXP/[10012111]
....
....
....
 cursor instantiation=0x0D2819C8 used=1291069118 exec_id=16777216 exec=1
 child#0(0x2F55BABC) pcs=0x2E35E450
  clk=0x30C819B4 ci=0x2E35D0E4 pn=0x35DF458C ctx=0x2DFDDCF0
 kgsccflg=0 llk[0x0D2819CC,0x0D2819CC] idx=0
 xscflg=c0100076 fl2=4040400 fl3=2262008 fl4=100
 Frames pfr 0x0E0F0610 siz=3044 efr 0x0E0F05B4 siz=3036
 Cursor frame dump
  enxt: 2.0x00000100  enxt: 1.0x00000adc
  pnxt: 1.0x00000008
 kxscphp=0x0DFA10B4 siz=1000 inu=152 nps=152

So, DDL is executed in two pass.

Advertisements

ORA-01732: data manipulation operation not legal on this view

Morning started with user email sending application screenshot showing error ORA-01732: data manipulation operation not legal on this view. It’s 10.2.0.3 DB

So, what this means that we are not able to update some view hmmm. As this was from some application i don’t know where it was happening. So traced DB and ask user to regenerate error and bingo. (All Names and Statement are changed but it should illustrate issue)


PARSE ERROR #23:len=448 dep=0 uid=51 oct=6 lid=51 tim=2007323474938 err=1732
UPDATE "CALL_TABLE" SET "TYPE" = 'TYPE-D' WHERE "ID"=1234567890
WAIT #23: nam='SQL*Net break/reset to client' ela= 2 driver id=1413697536 break?=1 p3=0 obj#=-1 tim=2007323475094
WAIT #23: nam='SQL*Net break/reset to client' ela= 1080 driver id=1413697536 break?=0 p3=0 obj#=-1 tim=2007323476188
WAIT #23: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2007323476202
WAIT #23: nam='SQL*Net message from client' ela= 8881 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2007323485137
XCTEND rlbk=1, rd_only=1
WAIT #0: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2007323485204

So, it was coming from application user (a common user for all connection). Finding more it was synonym which was pointing to some view. And on view there were some policy applied and finally that view was pointing to base table. Moreover, there was no complex things in that view just

create view view_v1 as select * from XYZ.CALL_TABLE

Let’s try manually doing this


Sys@xxxxxxxx> UPDATE "CALL_TABLE" SET "TYPE" = 'TYPE-D' WHERE "ID"=1234567890;

ORA-01732: data manipulation operation not legal on this view

Sys@xxxxxxxx> explain plan for UPDATE "CALL_TABLE" SET "TYPE" = 'TYPE-D' WHERE "ID"=1234567890;

ORA-01732: data manipulation operation not legal on this view

Hmmm let’s see what data is there


Sys@xxxxxxxx> select * from CALL_TABLE WHERE ID=1234567890

Execution Plan
----------------------------------------------------------
Plan hash value: 4166853210

---------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name                     | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |                          |     1 |  2267 |     2   (0)| 00:00:01 |
|   1 |  VIEW                        | VW_CALL_TABLE            |     1 |  2267 |     2   (0)| 00:00:01 |
|   2 |   TABLE ACCESS BY INDEX ROWID| CALL_TABLE               |     1 |   143 |     2   (0)| 00:00:01 |
|*  3 |    INDEX UNIQUE SCAN         | PK_CALL_TABLE            |     1 |       |     1   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------------

So, it did return data. But why can’t we update it. Here is the clue which i got from plan and also from trace


Sys@xxxxxxxx> explain plan for UPDATE "CALL_TABLE" SET "TYPE" = 'TYPE-D' WHERE "ID"=1234567890;

ORA-01732: data manipulation operation not legal on this view

*** 2010-11-10 16:23:36.022
*** SERVICE NAME:(SYS$USERS) 2010-11-10 16:23:36.022
*** SESSION ID:(165.46893) 2010-11-10 16:23:36.022
Registered qb: UPD$1 0xb0662550 (PARSER)
  signature (): qb_name=UPD$1 nbfros=1 flg=0
    fro(0): flg=5 objn=34994 hint_alias="CALL_TABLE"@"UPD$1"
Registered qb: SEL$1 0xb39bd130 (PARSER)
  signature (): qb_name=SEL$1 nbfros=1 flg=0
    fro(0): flg=4 objn=274478 hint_alias="CALL_TABLE"@"SEL$1"
**************************
Predicate Move-Around (PM)
**************************
PM: Considering predicate move-around in UPD$1 (#0).
PM:   Checking validity of predicate move-around in UPD$1 (#0).
JPPD:     JPPD bypassed: View not on right-side of outer join
CBQT: Validity checks failed for dnbuxs53wm06y.
CVM: Considering view merge in query block UPD$1 (#0)
CVM:   Checking validity of merging SEL$1 (#0)
CVM: Considering view merge in query block SEL$1 (#0)

There is nothing more logged in this trace except above. But, here is our clue that it has to do something with view merging while parsing(Where it’s failing). After searching something more on metalink my hunch was right. After changing that parameter “ta da” everything went fine and was able to insert data.  Here is the example.


Sys@xxxxxxxx> create table test (col1 varchar2(1));
Sys@xxxxxxxx> create view test_v as select * from test;

Sys@xxxxxxxx> alter session set "_simple_view_merging"=FALSE;

Session altered.

Sys@xxxxxxxx> insert into test_v values('A');
insert into test_v values('A')
            *
ERROR at line 1:
ORA-01732: data manipulation operation not legal on this view

Sys@xxxxxxxx> alter session set "_simple_view_merging"=TRUE;

Session altered.

Sys@xxxxxxxx> insert into test_v values('A');

1 row created.

And after changing this parameter ta da

Sys@xxxxxxxx> explain plan for UPDATE "CALL_TABLE" SET "TYPE" = 'TYPE-D' WHERE "ID"=1234567890;

-----------------------------------------------------------------------------------------------
| Id  | Operation          | Name                     | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT   |                          |     1 |   143 |     2   (0)| 00:00:01 |
|   1 |  UPDATE            | CALL_TABLE               |       |       |            |          |
|*  2 |   INDEX UNIQUE SCAN| PK_CALL_TABLE            |     1 |   143 |     1   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------------

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.