One Mutex Collision Test

Inspired by the recent Higgs boson-hunting experiments at CERN, this Blog is trying to make some Oracle Mutex collision test on Oracle 11.2.0.3.0, and to watch what new "particles" can be detected.

We start the test by (see appended Test Code):

begin
  ksun_mutex_test_jobs(64, 2);
end;

which launches 64 sessions running ksun_mutex_testp1 and 2 ksun_mutex_testp2.

ksun_mutex_testp1 runs the same sql statement by varying the NLS settings.

ksun_mutex_testp2 runs a query over v$sql in order to simulate some monitoring applications on sql statements. v$sql is chosen also because it is derived from x$kglcursor_child, which means any select on it will touch all child_cursors.

ksun_mutex_testp2 accelerates the collision, but does not play a decisive role in the test.


Here is the observed "particles":

1. Number of child_cursors

In theory, ksun_mutex_testp1 generates at most 800 (40 nls_language multiplied 20 nls_territory) child_cursors for the statement (sql_id: '754r1k9db5u80'):
    select id into l_id from testt where name = :B1;
but
   select count(*) from v$sql where sql_id ='754r1k9db5u80';
   >>> 66'510
 (with certain fluctuations, but more than 10'000)


10Jan2013 Update: Tested on new Oracle 11.2.0.3.0,

select count(*), min(child_number), max(child_number) from v$sql where sql_id ='754r1k9db5u80';
=> 23'027  0  99

count(*) can no more reach 66'510.

select count(*), min(child_number), max(child_number) from v$sql where sql_id ='754r1k9db5u80' and is_obsolete = 'N';

=> 78  0  77
It seems that "_cursor_obsolete_threshold" is active.      

 

2. Shared memory

select sharable_mem, persistent_mem, runtime_mem from v$sqlarea where sql_id ='754r1k9db5u80';

    >>> 845'643'351  292'590'880  226'019'744

3. Reason for child_cursors

 

select extract (xmltype ('<kroot>' || reason || '</kroot>'), '//ChildNumber').getStringVal ()   child
      ,extract (xmltype ('<kroot>' || reason || '</kroot>'), '//reason').getStringVal ()        reason
  from v$sql_shared_cursor
 where sql_id ='754r1k9db5u80';

>>> <ChildNumber>x</ChildNumber>    <reason>NLS Settings(0)</reason>

where x is the child_cursor number.

4. New MUTEX_TYPE: "hash table"

select * from v$mutex_sleep where mutex_type = 'hash table' order by sleeps;

    >>> hash table  kkshGetNextChild [KKSHBKLOC1]  1289912  0

I wonder if this is related to db_block_hash_buckets subpool in shared pool:

select * from v$sgastat where pool = 'shared pool' and name = 'db_block_hash_buckets';

   >>> shared pool  db_block_hash_buckets  2920448

Update in 18Mar2013:
 db_block_hash_buckets is for database block hash buckets. It is allocated in shared pool.
 It takes about 1% of db_cache_size for db_block_size = 8192, or 70 Bytes for each database block hash bucket (chain).
 For example, a DB with db_cache_size=262GB, db_block_hash_buckets needs 2848MB in shared pool.

5. System frozen

The most astonishing detection is that all started sessions are blocked after dozens of hours or even a couple of days by one session which is waiting either for an event:

       "library cache: mutex X"
or
    "library cache lock".
   
The waiters can be either "library cache: mutex X" or "library cache lock".

By dumping systemstate for the case of final blocker: library cache lock, we can see:

sid: 446 ser: 2025
    Current Wait Stack:
      Not in wait; last wait ended 1118 min 2 sec ago
    There are 65 sessions blocked by this session.
    Dumping one waiter:
      inst: 1, sid: 42, ser: 1249
      wait event: 'library cache lock'
        p1: 'handle address'=0xde5d11a8
        p2: 'lock address'=0xe019ed68
        p3: '100*mode+namespace'=0x520002

sid: 42 ser: 1249
    Current Wait Stack:
     0: waiting for 'library cache lock'
        handle address=0xde5d11a8, lock address=0xe019ed68, 100*mode+namespace=0x520002
        wait_id=78226 seq_num=20283 snap_id=347
        wait times: snap=51.136124 sec, exc=1118 min 2 sec, total=1118 min 2 sec
        wait times: max=infinite, heur=1118 min 2 sec
        wait counts: calls=22362 os=22362
        in_wait=1 iflags=0x15a2
    There is at least one session blocking this session.
      Dumping 1 direct blocker(s):
        inst: 1, sid: 446, ser: 2025
 
v$locks lists that final blocker session 446 holds 3 locks of type: CU, AE, JQ, and does not request any locks. Further check shows that only this session holds one CU lock. CU means "Recovers cursors in case of death while compiling",  so this final blocker is probably falling into an endless loop of cursor rescuing process.

If one tries to deblock the situation by killing the blocking session, one of the blocked sessions will take over its role, and the original blocking session joins to the blocked sessions. So the only fix could be to reboot the DB.

On the UNIX level, we can see this process is more than 95% on Usr CPU.

As checked from time to time, the system is getting gradually slower and finally totally hanging on one single session.

The whole tests were carried out on Solaris(x86-64) and AIX. Similar blocking behaviors were also reported by some real Oracle 11gR2 applications.

Probably these "particles" will not need 45-year to be confirmed by Oracle.

By the way, with Oracle 11.2.0.3.0, a new parameter is introduced:

Name:              _cursor_obsolete_threshold      
Description:     Number of cursors per parent before obsoletion.             
Default value:  100

Addendum (2015.03.25): Looking at Oracle 11.2.0.4.0, the default value is increased to 1024.

It seems Oralce does not strictly follow this threshold, and eventually can cause Shared Pool explosion due to number of child cursor versions.

Test Code (Oralce 11.2.0.3.0):

drop table testt;

create table testt as select 1 id, 'ksun' name from dual;

create table ksun_mutex_sleep as select * from v$mutex_sleep where 1=2;

create or replace procedure ksun_mutex_testp1 as
  l_id       number;
  l_name     varchar2(10) := 'ksun';
  type       tab is table of varchar2(100);
  l_tab_lang tab;
  l_tab_terr tab;
begin
  select value bulk collect into l_tab_lang from v$nls_valid_values where parameter='LANGUAGE';
  select value bulk collect into l_tab_terr from v$nls_valid_values where parameter='TERRITORY';
 
  for j in 1..least(40, l_tab_lang.count) loop
    --execute immediate q'[alter session set nls_language=']'||l_tab_lang(j)||q'[']';
    dbms_session.set_nls('nls_language', ''''||l_tab_lang(j)||'''');
    for k in 1..least(20, l_tab_terr.count) loop
      --execute immediate q'[alter session set nls_territory=']'||l_tab_terr(k)||q'[']';
      dbms_session.set_nls('nls_territory', ''''||l_tab_terr(k)||'''');
      select id into l_id from testt where name = l_name;
    end loop;
  end loop;
end;
/

create or replace procedure ksun_mutex_testp2 as
begin
  for c in (select * from v$sql) loop
    null;
  end loop;
end;
/

create or replace procedure ksun_mutex_test_jobs(p_job_cnt1 number, p_job_cnt2 number)
as
   l_job_id pls_integer;
begin
    for i in 1.. p_job_cnt1 loop
      dbms_job.submit(l_job_id, 'ksun_mutex_testp1;', interval => 'sysdate');
    end loop;
   
    for i in 1.. p_job_cnt2 loop
      dbms_job.submit(l_job_id, 'ksun_mutex_testp2;', interval => 'sysdate');
    end loop;
    commit;
end;   
/

Why shared pool is doubled ?

Problem:

There is an Oracle application which divides the whole work as front-end and back-end. Both are performing the similar tasks. Front-end is for GUI online processing of small and urgent work;
whereas back-end is for large and normal case settled by Oracle background Jobs.

The system is set up with default value of WORKAREA_SIZE_POLICY = AUTO. From time to time, back-end hits error of ORA-04030, i.e. Operating system process private memory has been exhausted. So the developers decided that they should have a better control of *_AREA_SIZE parameters, for example, by regulating HASH_AREA_SIZE, SORT_AREA_SIZE, they can somehow avoid such error. Hence, they decided to put a:

    execute immediate 'alter session set workarea_size_policy = manual';

at the beginning of background Jobs (see Test Code).

For a while, system gets stable and no more ORA-04030 occurs.

Following the progress of development and workload on the system, application gets bigger and bigger (more code too). The consequence is that DBA is obliged to increase shared pool memory with each rollout of new release. For the moment, it is more than 12 GB. However the performance was continuously degraded, probably due to the huge cursor cache and library cache, which overwhelm managing and seeking time for cursors.

By dumping library_cache with:

    alter session set events 'immediate trace name library_cache level 15';

One can see frequent CursorDiagnosticsNodes and AgedOutCursorDiagnosticNodes marked as

    reason=Optimizer mismatch(12) size=2x216
      workarea_size_policy= manual auto
      _smm_auto_cost_enabled= false true

which caused enormous cursor reloads and invalids.

And even worse, there are some SGA memory resizing, that means: Shared Pool steals memory from Buffer Cache.

One can check this resizing by (or check AWR - Memory Dynamic Components):

select component, current_size, user_specified_size, oper_count, last_oper_type
from v$memory_dynamic_components;

The output looks like:

COMPONENT                 CURRENT_SIZE      USER_SPECIFIED_SIZE        OPER_COUNT        LAST_OPER_TYPE
shared pool                        2'785'017'856            2'415'919'104                            5                                GROW
DEFAULT buffer cache    2'936'012'800            3'305'111'552                            5                                SHRINK

The above says same amount(369'098'752 Bytes) stolen by shared pool from DEFAULT buffer cache (v$sga_resize_ops, v$memory_resize_ops also provide the similar information).

During such operation, the entire system looks jammed. It seems well known by Oracle, so they have designated a new hidden parameter: "_memory_imm_mode_without_autosga" (Allow immediate mode without sga/memory target) to prevent such resizing.

MOS also made a clear claim:

set the parameter _MEMORY_IMM_MODE_WITHOUT_AUTOSGA=false (default is TRUE) in the instance to disable this feature with the consequence that in future an ORA-4031 error would be raised.

    alter system set "_memory_imm_mode_without_autosga"=FALSE;

That is also true. Since then the system occasionally hits ORA-04031.

Analysis:

With Oracle 11g Release 2 (11.2.0.2), a new column: REASON is available to reveal the root cause of cursor boost.

select sql_id, optimizer_mismatch
      ,extract (xmltype ('<kroot>' || reason || '</kroot>'), '//workarea_size_policy').getStringVal ()   wasp
      ,extract (xmltype ('<kroot>' || reason || '</kroot>'), '//_smm_auto_cost_enabled').getStringVal () sace
      ,v.*
from v$sql_shared_cursor v
where sql_id in (select sql_id from v$sql_shared_cursor where optimizer_mismatch='Y')
order by v.sql_id, wasp, sace;

It shows that there are paired child cursors for each sql_id due to optimizer_mismatch,
and the reason is workarea_size_policy.

00hxpd7rjygxq       N
  <workarea_size_policy>   auto manual </workarea_size_policy>   
  <_smm_auto_cost_enabled> true false  </_smm_auto_cost_enabled>
00hxpd7rjygxq       Y
  <workarea_size_policy>   manual auto </workarea_size_policy>   
  <_smm_auto_cost_enabled> false  true </_smm_auto_cost_enabled>

Note that a top Node <kroot> is specially appended since reason column can contain more than one <ChildNode> and it requires a top Node to group them before using xpath query (again confirmed that new Features need a long way to go before perfect).

This Blog demonstrates that a tiny unconscious change could provoke a dramatic impact.

Fix:

Remove:
    'alter session set workarea_size_policy = manual' 
and use dynamic code to adjust to back-end jobs.

If we check again "SQL AREA", we find that memory consumption is only half of original:

    select bytes from v$sgastat where name = 'SQLA';

Test Code (Oralce 11.2.0.2 or later):

create table testt as
select level x, rpad ('abc', 100, 'k') y from dual connect by level <= 1000;


create or replace procedure tasks as
  y   number;
begin
  for j in 1 .. 500 loop
    for i in 1 .. 1000 loop
      execute immediate 'select /*' || (rpad ('x', i, 'y')) || '*/ x from testt where x = :i'
      into y using i;
    end loop;
  end loop;
end;
/

create or replace procedure auto_run as
begin
  execute immediate 'alter session set workarea_size_policy = auto';
  tasks;
end;
/

create or replace procedure manual_run as
begin
  execute immediate 'alter session set workarea_size_policy = manual';
  tasks;
end;
/

create or replace procedure start_work (p_job_cnt number) as
  l_job_id   pls_integer;
begin
  for i in 1 .. p_job_cnt loop
      dbms_job.submit (l_job_id, 'begin auto_run; end;');
      dbms_job.submit (l_job_id, 'begin manual_run; end;');
  end loop;
  commit;
end;
/

exec start_work(32);

High system time utilization on fast machine

Problem:

Recently we hit some performance problem on a system running a heavy Oracle application. Occasionally when more than 100 "end of day" batch jobs are automatically submitted by a Job control system in the early morning, no more new users can login into Oracle (alert log shows many lines of ORA-609: that is, could not attach to incoming connection).

By only concentrating on Oracle performance, it could not figure out any particular clue.
The already logged in users and applications can still work, Oracle workload is not high.

Then we asked UNIX administrator to send us some snapshots of vmstat(AIX NMON report even better),  immediately it turns out that Runqueues, Kernel thread context switches, system cpu utilization are extremely high in comparing to normal operation.

Here are two entries of vmstat, one is in normal time, another is during batch (problem) time.

kthr  faults         cpu        time

----- ------------  ---------  --------

  r       sy     cs  us sy id   hr mi se

 37   250806   7412  34  2 64   09:53:39  << normal time

185    87914  34261  12 80  8   02:52:44  << batch  time

At the end of this Blog, a complete simplified test codes are appended and can be tested on AIX and Solaris.

Analysis:

The application is running on high end IBM AIX server with many cores(Physical CPUs).
When 100 batch jobs are submitted, most of them can be scheduled to "Running" state,
however, there is a single config file to be read, hence inherently creating a single point of contention (bottleneck). IO is normal not fast as CPU. The faster the CPU, the higher contention.

Here is what AIX default Scheduler (SCHED_OTHER) would do. When a "New" process is inserted into system, it is first put into "Ready". Then scheduler brings it to "Running" state, in this case, it has to wait IO, thus switches to "Preempted" state, and later back again to "Ready" state, eventually waits scheduler to bring into "Running" state again.  Thus it yields CPU to other processes. Since all these processes have the same characteristics,  they will go through many such life cycles. Therefore system ends up spending majority of time in frequent Kernel thread context switches instead of applications work. This phenomenon of "thrashing" causes high system CPU utilization because of single file competing.

The problem occurs only when system baseload (the load when launching batch jobs) achieves certain high.

As tools, vmstat and sar are used for CPU, filemon for file IO. In AIX, nmon report could provide much rich information. By using "ps -efl" (or Berkeley Standards "ps glew"), one can see many <defunct> and <exiting> processes (more than 50 each) during problem time. This is because batchload forks loadconf into background and it quits before children processes terminate, and children processes becomes "orphan".

When monitoring the CPU performance, it is better to check CPU utilization instead of RunQueue since CPU utilization is an average over an interval, whereas RunQueue is a sampling (for example in vmstat),  normally by a frequency of 100 microseconds, however, today’s CPU ticks in nanosecond. Thus RunQueue can not be very precise. For instance, submitting 100 jobs does not mean RunQueue showing 100. In fact, Nyquist sampling theorem requires the sampling should be double fast.

On Solaris, paper (http://www.solarisinternals.com/wiki/images/2/28/Technocrat-util.pdf)
has a profound discussion on run queues and demonstrates how to
tracks the insertion of runnable threads onto CPU run queues with a DTrace script.

One thing I noticed is that "System calls" in vmstat does not necessarily coincide
with Runqueues and context switches. That is still not clear to me.

This Blog also shows that finding the root cause is paramount for Oracle Performance troubleshooting.

Fix:

A quick fix is to insert a sleep after sending each job so that CPU power is mitigated to reduce the IO burden.

Test Codes:

1.  Script-1 creates a config file, which looks like JAVA's properties file.
2.  Script-2 reads the config file.
3.  Script-3 launches N batch jobs in background.

Test can be performed by calling on one UNIX session:
      batchload 100
and at same time running vmstat on a second session.

Script-1 confcreate

#!/bin/ksh

#    usage:  confcreate

count=0

max=1000

configfile="conf"

while [[ $count -lt $max ]]

do

  print "name$count=val$count" >> $configfile

  count=$((count + 1))

done

Script-2 loadconf

#!/bin/ksh

#    usage:  loadconf

count=0

max=1000

configfile="conf"

while [[ $count -lt $max ]]

do

 val=$(awk -F"=" "/^(name$count)=/"'{print $2}' conf)

  count=$((count + 1))

# some Sqlplus script to do the business 

done

Script-3 batchload

#!/bin/ksh

#    usage:   . ./batchload 100

count=0

max=$1

while [[ $count -lt $max ]]

do

 ./loadconf &

 print batchload $count at $(date)

#  sleep 2                            # sleep to relent CPU

  count=$((count + 1))

done

Is latch misses statistic gathered or deduced ?

---

Correction (2017-Sep-23):

One very experienced Oracle specialist pointed out my error in this Blog. The formula given by Book: Oracle Core: Essential Internals for DBAs and Developers (Page 72–73) is:

       sleeps + spin_gets – misses 
     = recurrent_sleeps

Blog Latch, mutex and beyond has a deep research of above formula.

---

If you run the first query and see majority of rows with "delta_perc" column less than 1 (1 percent), continue to read this Blog.

select name, misses, sleeps, spin_gets
      ,sign((sleeps + spin_gets) - misses) miss_deduced_sign
      ,((sleeps + spin_gets) - misses)     delta
      ,trunc((abs((sleeps + spin_gets) - misses) / nullif(misses, 0)) * 100 ,2)*100 delta_perc
from v$latch where misses > 1000
order by misses desc;

This Blog is trying to state:
    latch misses statistic is deduced, and not gathered in Oracle kernel code.

By observing very small "perc" value, I assume the equation:
    misses = Sleeps + Spin_gets
approximately holds for most of latches.

If this is a fact, Oracle would not record all the 3 statistics by sacrificing high performance latch algorithm just to verify the above equation.

Further perceiving "miss_deduced_sign" mostly of 0 or 1 (positive), "misses" statistics is probably deduced from (sleeps + spin_gets), not really gathered in the kernel code (so efficiently implemented by the Oracle developers). Probably Oracle records only "sleeps" and "spin_gets" because both signify "get" not succeeded, and will take longer time, so the time to record both would less expensive than the "get" itself (the time to both statistics can be negligible. A disciplined programmer would not let the auxiliary actions take more time than real actions). The not popular "miss_deduced_sign" of 1 could be explained due to update latency on "misses" by (sleeps + spin_gets). As observed, the not popular "miss_deduced_sign" of -1 or 1 would appear when system is heavily loaded, once system is stable, "miss_deduced_sign" would tentatively return back to 0. This is also a good optimization, function first, statistics later.
   
A large minus "delta" (miss_deduced_sign = -1) could be a residual from DB start up since they stay almost constant.

Some books contain pseudo-codes to explain the Oracle latch algorithm, I hope they can match the aforementioned equation (see Book Expert Oracle Database Architecture Page 222, and Oracle Performance Firefighting Page 79).

One Oracle 12g Pre-announce of bug fix in dbms_debug_jdwp

4 years ago, I filed a bug of dbms_debug_jdwp in 10gR2, after 2 years of pingpong playing, Oracle finally acknowledged the reproducibility of submitted testcase, but only promised to fix it in Oracle 12g.

Here the test code:

alter system set plsql_optimize_level = 1;

CREATE OR REPLACE PACKAGE ksun_nocopy_called
IS
   type t_rec is record(
    a                    number := 100
   ,b                    number
   );
  PROCEDURE called(
    o_rec     OUT NOCOPY t_rec
  );
END ksun_nocopy_called;
/

CREATE OR REPLACE PACKAGE BODY ksun_nocopy_called
IS
  PROCEDURE called(
    o_rec     OUT NOCOPY t_rec
  )
  IS
  BEGIN
    null;
  END called;
END ksun_nocopy_called;
/

CREATE OR REPLACE PACKAGE ksun_nocopy_caller
IS
  PROCEDURE caller;
END ksun_nocopy_caller;
/

CREATE OR REPLACE PACKAGE BODY ksun_nocopy_caller
IS
  b_rec_old                   ksun_nocopy_called.t_rec;
  PROCEDURE caller
  IS
  BEGIN
    ksun_nocopy_called.called(b_rec_old);
  END caller;
END ksun_nocopy_caller;
/

To run the testcase, start JDeveloper (Version 10.1.3.2.0), set a breakpoint at the line in ksun_nocopy_called.called:
    null;
   
Open a Sqlplus window, run the following code:

exec dbms_debug_jdwp.connect_tcp('pc-123', 4000);
exec ksun_nocopy_caller.caller
exec dbms_debug_jdwp.disconnect;

Then get the following message:

*********START PLSQL RUNTIME DUMP************
***Got internal error Exception caught in pl/sql run-time while running PLSQL***
***Got ORA-6544 while running PLSQL***
PACKAGE BODY K.KSUN_NOCOPY_CALLER:

Due to my impatience and their reluctance, two alternative approaches were worked out.

One is to substitute the package body variable with a procedure local variable as:

CREATE OR REPLACE PACKAGE BODY ksun_nocopy_caller
IS
  b_rec_old                   ksun_nocopy_called.t_rec;
  PROCEDURE caller
  IS
    l_rec_copy                ksun_nocopy_called.t_rec;
  BEGIN
    l_rec_copy := b_rec_old;
    ksun_nocopy_called.called(l_rec_copy);
    b_rec_old := l_rec_copy;
  END caller;
END ksun_nocopy_caller;

Another is to eliminate initial assignment in record declaration as:

   type t_rec is record(
    a                    number
   ,b                    number
   );
  
Probably Oracle was either encouraged by the simplicity of testcase, or inspired by the intuitive workarounds, they finally recognized the bug and projected to fix it in Oracle 12g.

By the way, DEBUG parameters are not updated in Oracle 12c.

Addendum (2015.10.19):  Oracle 12c document said:
   The PLSQL_DEBUG parameter is deprecated. It is retained for backward compatibility only (see PLSQL_DEBUG)

 it is replaced by:
   PLSQL_OPTIMIZE_LEVEL = 1

However 12c DBMS_TRACE document wrote:
   You can enable a program unit by compiling it debug.
       alter session set plsql_debug=true;
(see Database PL/SQL Packages and Types Reference)



 

Oracle 11gR2 single session "library cache pin"

Abstract:

Recently we encountered a single session cyclic  "library cache pin" during upgrade to 11.2.0.3.0 from a lower version, in which the application generated types (in SYS schema) are cleaned out by:

     drop type sys.SYS_PLSQL_X_Y_Z force;

Addendum (2015.11.02): Above drop is done by SMON (see Section CLEANUP_NON_EXIST_OBJ Task of follow-up Blog: Oracle 12c single session "library cache lock (cycle)" deadlock).

In order to understand this special deadlock case, run the attached the test code (at the end of this Blog). which consists of three code parts (SYS_PLSQL_3238_382_1 is a package generated sys type):

   create package spec and package body
   drop type sys.SYS_PLSQL_3238_382_1 force
   alter package suk_lc_pin# compile body

and session is waiting for "library cache pin" for a duration of 15 minutes, which can be observed by:

   select * from v$session where event like 'library cache pin';
   select * from v$wait_chains; 

After 15 minutes, session throws:

      ORA-04021: timeout occurred while waiting to lock object

15 minutes timeout is the default value of "_kgl_time_to_wait_for_locks" (time to wait for locks and pins before timing out).

We can break the blocked session and remove all invalids by:

      alter package lc_pin# compile;

The attached testcase is based on dba_tables, but it is reproducible with dba_segments, dba_objects, dba_indexes.     

Affected Oracle Version:

      11.2.0.1.0, 11.2.0.2.0, 11.2.0.3.0, but not 10.2.0.4.0.

Reasoning:

The problem seems caused by the "with" factoring clause (see attached testcase at the end of this Blog).

When Oracle parses "with" factoring clause, it acquires a "library cache pin" in the Share Mode (S) on the dependent objects, in this case, it is "t_vc", then it proceeds to main clause,  in which it realizes that the dependent object: "t_dba_row_tab" is invalid. In order to resolve this invalid, Oracle attempts to recompile package spec, which requests Exclusive Mode (X) on the related objects.

Since the already held mode (S) on "t_vc" is not consistent with requesting mode (X), Oracle session spins on the wait event "library cache pin". By default, Oracle throws an error:
    ORA-04021: timeout occurred while waiting to lock object
after 15 minutes.

In theory, this single session cyclic lock should be detected as a deadlock, however, Oracle "library cache pin" is not deadlock sensitive. That is probably the reason why the waiting event is controlled by a 15 minute timeout in Oracle implementation.

A further query:

select (select kglnaobj||'('||kglobtyd||')'
          from x$kglob v
         where kglhdadr = object_handle and rownum=1) kglobj_name
       ,v.*
from v$libcache_locks v
where v.holding_user_session  =
         (select saddr from v$session
           where event ='library cache pin' and rownum = 1)
  and object_handle in (select object_handle from v$libcache_locks where mode_requested !=0)
order by kglobj_name, holding_user_session, type, mode_held, mode_requested;

shows there are two rows on SYS_PLSQL_263602_21_1(TYPE) with TYPE: PIN, in which the HOLDING_USER_SESSION and HOLDING_SESSION are different in the row with
        MODE_REQUESTED = 3 (Exclusive mode)

KGLOBJ_NAME	TYPE	ADDR	HOLDING_USER_SESSION	HOLDING_SESSION	OBJECT_HANDLE	LOCK_HELD	REFCOUNT	MODE_HELD	MODE_REQUESTED	SAVEPOINT_NUMBER
SYS_PLSQL_263602_21_1(TYPE)	PIN	07000000A5C224E0	07000000C09CE610	07000000C1A399B0	07000000A8AEFD20	0	0	0	3	7504
SYS_PLSQL_263602_21_1(TYPE)	PIN	07000000A7243838	07000000C09CE610	07000000C09CE610	07000000A8AEFD20	07000000A7243938	1	2	0	6235

From the query result, we can see that HOLDING_USER_SESSION already held a PIN mode of 2(Share mode), but at the same time designates a different recursive session to request a PIN mode of 3(Exclusive mode). The column SAVEPOINT_NUMBER seems recording the sequence of PIN get and request.

This probably explains why Oracle can't detect such deadlock case.

In Oracle, HOLDING_USER_SESSION is the session we see in v$session, whereas HOLDING_SESSION is the recursive session when both are not the same. Normally recursive session is spawned out when HOLDING_USER_SESSION requires "SYS" user privilege to perform certain tasks.

By the way, recursive session is not exported in v$session because of filter predicate:
       bitand("s"."ksuseflg",1)<>0
on x$ksuse, where bitand (s.ksuseflg, 19) = 1 for 'USER' session; = 17 for 'BACKGROUND', = 2 for 'RECURSIVE'.
(Tanel has a Blog on recursive session in Recursive sessions…)

A quick workaround is to recompile the package spec by:
   
    alter package lc_pin# compile;

The new recompiled sources can be listed by:

    select * from dba_objects order by last_ddl_time desc;
   
from which one can see the t_vc is recompiled even it was valid before (this confirms the Exclusive Mode (X) request on t_vc).

Further statistics shows that Oracle is continuously enriching its library cache with the newer versions, for example, v$db_object_cache contains 13 columns in 10.2.0.4.0, 21 in 11.2.0.1.0 and 11.2.0.2.0, and now 23 in 11.2.0.3.0.

Once all are valid, you can run the query:

   select * from table(lc_pin#.soo);   
   

Fundamentals:

   
I would like to share the basics I used to approach this problem.

The Oracle generated representations for package defined types are denoted as:

    SYS_PLSQL_263602_9_1  for t_dba_row_tab
    SYS_PLSQL_3238_382_1  for sys.dba_tables%rowtype
    SYS_PLSQL_263602_31_1 for t_vc_tab
    SYS_PLSQL_263602_21_1 for t_vc
   
where 263602 is the object_id of lc_pin# (package spec, not package body) in dba_objects, 3238 is that of DBA_TABLES.
   
Additionally a type

    SYS_PLSQL_263602_DUMMY_1 as table of number;
   
is created, probably to index the two PL/SQL nested tables: t_dba_row_tab and t_vc_tab, even though both are not declared as associative array (formerly called PL/SQL table or index-by table). We can also guess that PL/SQL nested table is internally implemented as conventional index-by table.

The generated sources can be listed by:

select * from dba_source where name in (
     'SYS_PLSQL_263602_9_1'
     ,'SYS_PLSQL_3238_382_1'
     ,'SYS_PLSQL_263602_31_1'
     ,'SYS_PLSQL_263602_21_1'
     ,'SYS_PLSQL_263602_DUMMY_1');
   
One can also notice that after:

    drop type sys.SYS_PLSQL_3238_382_1 force;

SYS_PLSQL_3238_382_1 is no more registered in dba_objects, but still retained in sys.obj$. In sys.obj$, however, it is altered from type# 13 (TYPE) to type# 10 object  (also named NON-EXISTENT object in Oracle).

v$libcache_locks contains rich details on pin and lock (refcount, mode_held, mode_requested).

After the first publication of this Blog, Tanel's powerful kglpn.sql (TPT_public.zip) showed me the following output:

PIN_MODE REQ_MODE PINNED_BLOCKS  OBJECT_NAME
-------- -------- -------------- -----------------------
Share     None     0 6           SYS.SYS_PLSQL_263602_21_1
None      Excl                   SYS.SYS_PLSQL_263602_21_1

This confirms again the self-deadlock caused by:
   SYS.SYS_PLSQL_263602_21_1
since its PIN_MODE = Share, and REQ_MODE = Excl.

AIX Trace

On AIX, running trace command with session's PID: 28246034 for 20 seconds by:

trace -a -A 28246034 -o trc_raw; sleep 20; trcstop; trcrpt -O "exec=on,pid=on" trc_raw

we get the output (some details are removed):

ID   PID       ELAPSED_SEC     DELTA_MSEC   SYSCALL KERNEL  INTERRUPT
001  16318614  0.000000000       0.000000           TRACE ON channel 0
200  28246034  1.243906765    1243.906765           resume  oracletestdb iar=DF09C cpuid=FFFFFFFF
104  28246034  1.243909585       0.002820   return from system call
101  28246034  1.243953916       0.044331   _poll LR = 9000000012D75D4
252  28246034  1.243956337       0.002421   SOCK soo_select fp=xx so= corl=0 reqevents= rtneventsp=
252  28246034  1.243956876       0.000539   SOCK return from soo_select fp= so= error=0
104  28246034  1.243957916       0.001040   return from _poll [4 usec]
101  28246034  1.243965021       0.007105   _thread_wait LR = 90000000129C2AC
200  28246034  4.243980259    3000.015238           resume  oracletestdb iar=DF09C cpuid=FFFFFFFF
104  28246034  4.243982353       0.002094   return from _thread_wait [3.000017 sec]
101  28246034  4.244031337       0.048984   _thread_wait LR = 90000000129C2AC
200  28246034  7.244053839    3000.022502           resume  oracletestdb iar=DF09C cpuid=FFFFFFFF
104  28246034  7.244055822       0.001983   return from _thread_wait [3.000024 sec]
101  28246034  7.244095943       0.040121   _thread_wait LR = 90000000129C2AC
200  28246034 10.244111460    3000.015517           resume  oracletestdb iar=DF09C cpuid=FFFFFFFF

it shows that session resumes after each 3 seconds of thread_wait (v$wait_chains is also refreshed each 3 seconds).

------------------------- TestCase -------------------------
-- This test is with dba_tables.
-- It is also reproducible with dba_segments, dba_objects, dba_indexes.

drop package lc_pin#;

-- Create Package and Package Body
create or replace package lc_pin#
as
  type t_dba_row_tab is table of sys.dba_tables%rowtype; 
  type t_vc          is record (name varchar2(30));
  type t_vc_tab      is table of t_vc;
   
  function foo return t_vc_tab pipelined;
  function koo return t_dba_row_tab pipelined;
  function soo return t_dba_row_tab pipelined;
end lc_pin#;
/

create or replace package body lc_pin#
as

  function foo return t_vc_tab pipelined
  is
    l_result  t_vc;
  begin
    l_result.name     := 'lc_test';
    pipe row(l_result);
    return;
  end foo;  
   
  function koo return t_dba_row_tab pipelined
  is
  begin
    for c in (select * from dba_tables where  rownum = 1) loop
      pipe row(c);
    end loop;
  end koo;
 
  function soo return t_dba_row_tab pipelined
  is
  begin
    for c in (
      with sq as (select * from table(foo))
      select nt.*
      from   sq 
            ,(select * from table(koo)) nt
     
      -- following re-write works
      -- select nt.* from (select * from table(foo)) sq, (select * from table(koo)) nt
    ) loop
      pipe row(c);
    end loop;
  end soo;
 
end lc_pin#;
/

-- Generate "drop type sys.SYS_PLSQL_3238_382_1 force;" and execute
declare
    l_stmt    varchar2(100);
begin
    select 'drop type sys.' || object_name || ' force' drop_stmt
    into   l_stmt
    from   dba_objects
    where  object_name like
            (select 'SYS_PLSQL_' || object_id || '%_1'
             from   dba_objects
             where  owner = 'SYS' and object_name = 'DBA_TABLES' and object_type = 'VIEW')
      and  object_name not like '%DUMMY%'
    ;
   
    dbms_output.put_line('Run l_stmt: ' || l_stmt);
   
    execute immediate l_stmt;
end;
/

-- Compile Package Body, session is in wait event "library cache pin" for 15 minutes,
-- then throws "ORA-04021: timeout occurred while waiting to lock object"
alter package lc_pin# compile body;
 

Redo/Undo explosion from thick declared table insert

This blog presents a Redo/Undo explosion caused by thick declared table insert. Originally there is a thin table (thin_tab) consisting of two columns: a number and a 40 char varchar2. Later two new columns with 1000 char varchar2 each are required to store some seldom occurred message, so a new table (thick_tab) is created by adding these two new columns.

The test code is performed on 10gR2 and 11gR2 on a NOARCHIVELOG-mode database with
   undo_management=AUTO,
   db_block_size=8192,
   nls_characterset=AL32UTF8.

First we insert 10000 rows into the thin_tab, then we insert the same content into the thick_tab. The two new columns in thick_tab are not used at all. Table test_stats is used to store the test statistics for each step.

drop table test_stats;

create table test_stats
    (step  varchar2(10),
     name  varchar2(30),
     value number       );

drop table thin_tab;

create table thin_tab
(
  num    number,
  txt    varchar2(40 char)
)
tablespace sysaux
pctused    0
pctfree    10
initrans   1
maxtrans   255
storage    (
            initial          64k
            next             1m
            minextents       1
            maxextents       unlimited
            pctincrease      0
            buffer_pool      default
           )
logging
nocompress
nocache
noparallel
monitoring;

drop table thick_tab;

create table thick_tab
(
  num    number,
  txt    varchar2(40 char),
  txtn1  varchar2(1000 char),
  txtn2  varchar2(1000 char)
)
tablespace sysaux
pctused    0
pctfree    10
initrans   1
maxtrans   255
storage    (
            initial          64k
            next             1m
            minextents       1
            maxextents       unlimited
            pctincrease      0
            buffer_pool      default
           )
logging
nocompress
nocache
noparallel
monitoring;

---- step_1 ----
insert into test_stats
select 'step_1' step, vn.name, vs.value
from   v$sesstat  vs
     , v$statname vn
where  vs.sid = userenv('sid')
  and  vs.statistic# = vn.statistic#
  and  vn.name in ('redo size', 'undo change vector size');

---- step_2 insert into thin_tab ----
insert into thin_tab(num, txt)
select level, 'abc' from dual connect by level <= 10000;

insert into test_stats
select 'step_2' step, vn.name, vs.value
from   v$sesstat  vs
     , v$statname vn
where  vs.sid = userenv('sid')
  and  vs.statistic# = vn.statistic#
  and  vn.name in ('redo size', 'undo change vector size');

---- step_3 insert into thick_tab ----
insert into thick_tab(num, txt)
select level, 'abc' from dual connect by level <= 10000;

insert into test_stats
select 'step_3' step, vn.name, vs.value
from   v$sesstat  vs
     , v$statname vn
where  vs.sid = userenv('sid')
  and  vs.statistic# = vn.statistic#
  and  vn.name in ('redo size', 'undo change vector size');
 
select step, name, value,
       (value - lag(value) over (partition by name order by step)) diff
from   test_stats;

commit;

select segment_name, blocks, bytes
from   dba_segments
where  segment_name in ('THIN_TAB', 'THICK_TAB');

Output:

STEP    NAME                     VALUE       DIFF
------- ------------------------ ----------  ----------
step_1  redo size                11'592'572 
step_2  redo size                11'793'484     200'912
step_3  redo size                14'335'284   2'541'800
step_1  undo change vector size   3'011'440 
step_2  undo change vector size   3'037'820      26'380
step_3  undo change vector size   3'720'120     682'300

SEGMENT_NAME  BLOCKS  BYTES
------------- ------  -------
THICK_TAB         24  196'608
THIN_TAB          24  196'608

Above output demonstrates thick_tab insert generated 10 times redo,and 30 times undo than thin_tab even though the two new columns in thick_tab have nothing inserted. But both data segments have the similar size.

By dumping the redo logfile, it turns out that Oracle uses row array allocation for thin_tab, but single row allocation for thick_tab. Probably that is an Oracle internal optimization.

If using direct-path insert (insert /*+ append */ ), there will be no big difference for both inserts, and redo and undo will be much less (redo size = 10K, undo change vector size = 2K).

For partitioned table, when multiple sessions concurrently make the direct-path(with append hint) for each partition per session, the PARTITION clause is mandatory:

 insert /*+ append */ into test_table_1 PARTITION (part_1) select *  from test_table_2;

Otherwise there is a TM lock contention among the sessions on global table.
The reason is because without PARTITION clause, direct-path makes:

 TM lock with LMODE 6 on global table;
 TM lock with LMODE 3 on the specified partition;

however, with PARTITION clause, they are:

  TM lock with LMODE 3 on global table;
 TM lock with LMODE 6 on the specified partition;

For non direct-path, with or without PARTITION clause are the same:

 TM lock with LMODE 3 on global table;
 TM lock with LMODE 3 on the specified partition;

By the way, Oracle official document about:
   Locking Considerations with Direct-Path INSERT
states:
  During direct-path INSERT, the database obtains exclusive locks on the table (or on all partitions of a partitioned table).
(see Oracle® Database Administrator's Guide 11g Release 2 (11.2)

This claim only holds when no PARTITION clause is specified.