Monday, July 30, 2012

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;   
/