Monday, August 1, 2016

Blog List

ORA-04025 library object lock on AQ queue and SQL cursor

AQ dequeue throws:
     ORA-04025: maximum allowed library object lock allocated for S.KSUN_QUEUE
in an Oracle 12c batch application when number of concurrent jobs greater than 65, where KSUN_QUEUE is the queue name, and DB is set up with following relevant parameters:
  _session_cached_instantiations       integer     1001
  cursor_sharing                       string      exact
  cursor_space_for_time                boolean     FALSE
  open_cursors                         integer     800
  session_cached_cursors               integer     600


Adhere to Oracle Documentation on ORA-04025:
  Cause:  Too many active locks for the object has been allocated.
               This error can be a result of too many cursors kept open per session.
  Action: Close cursors, reduce session_cached_cursors value.

Halving session_cached_cursors from 600 to 300 does not make the error disappear.

This Blog will try to demonstrate:
(a). there probably exists a hard limit of 65535 locks per library object:
             LIBRARY OBJECT LOCK: MAXIMUM 65535
       internally it could be implemented by a 16-bits u16.
(b). locks per Oracle session is imposed by
             _session_cached_instantiations
(c). maximum number of concurrent sessions to avoid ORA-04025 is
             floor(65535/_session_cached_instantiations)
      It is 65 for above settings.

Tests done on Solaris and AIX with Oracle 12.1.0.2.0.
See Blog appended Test Code.
Note: to make the test reproducible, before each test, restart DB to remove any un-released locks.

1. Library object lock on AQ queue


1.1 Single session dequeue/enqueue test:


SQL> exec test_deq(1200, 0, 0, true);
 deq_cnt: 1, lock_cnt: 1
 deq_cnt: 2, lock_cnt: 2
 deq_cnt: 3, lock_cnt: 3
 ...
 deq_cnt: 1000, lock_cnt: 1000
 deq_cnt: 1001, lock_cnt: 1001
 deq_cnt: 1002, lock_cnt: 1002
 deq_cnt: 1003, lock_cnt: 1002
 ...
 deq_cnt: 1199, lock_cnt: 1002
 deq_cnt: 1200, lock_cnt: 1002

It shows that number of locks on the queue object is increased for each dequeue call till 1002,
and then maintained at 1002.

Open a new session, make a similar enqueue test.

  SQL> exec test_enq(1200, 0, true);

The lock behavior is similar to dequeue. Therefore all the discussion on dequeue applies to enqueue as well.

1.2   66 Batch sessions dequeue test


In this test, we will start 66 dequeue sessions to provoke ORA-04025. All 3 monitoring queries can be run during whole tests to watch the progress of locks. Once total number of locks on KSUN_QUEUE is approaching to 65535, some sessions raise ORA_04025.

(A). Launch 66 concurrent Jobs by:


  SQL> exec test_deq_jobs(66, 2000);  

After about 18 minutes (1003 times of one-second dequeue wait), we will see some trace files like:

 ORA-12012: error on auto execute of job 86367
 ORA-04025: maximum allowed library object lock allocated for S.KSUN_QUEUE
 ORA-06512: at "S.TEST_DEQ", line 40
 ORA-06512: at line 1

(B). Watch total number of locks on KSUN_QUEUE:


SQL> select name, locks, pins, locked_total, pinned_total
       from v$db_object_cache l
      where hash_value = 3868150627 or name = 'KSUN_QUEUE';

 NAME         LOCKS  PINS LOCKED_TOTAL PINNED_TOTAL
 ----------- ------ ----- ------------ ------------
 KSUN_QUEUE   65106     0       321935       428400

SQL> select kglnaobj||'('||kglobtyd||')' name, object_handle, type, mode_held, mode_requested, count(*) cnt
       from v$libcache_locks l, x$kglob o
      where o.kglnaobj = 'KSUN_QUEUE'
        and l.object_handle = o.kglhdadr
      group by object_handle, kglnaobj, kglobtyd, type, mode_held, mode_requested;

 NAME               OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED    CNT
 ------------------ ---------------- ---- ---------- -------------- ------
 KSUN_QUEUE(QUEUE)  0000000167A4B2E0 LOCK          1              0  65224

(C). Watch number of locks per session on KSUN_QUEUE:


SQL> with sq as
          (select /*+ materialize */ sid, program, saddr, event
              ,to_char(p1, 'xxxxxxxxxxxxxxx') p1, p1text
              ,to_char(p2, 'xxxxxxxxxxxxxxx') p2, p2text
              ,to_char(p3, 'xxxxxxxxxxxxxxx') p3, p3text
           from v$session
          where program like '%(J%' or module like '%deq%')
     select s.sid, holding_user_session, object_handle, l.type, mode_held, mode_requested,
            count(*) lock_cnt     -- it goes up to maximum 1003, and then back 1002
       from v$libcache_locks l, x$kglob o, sq s
      where o.kglnaobj = 'KSUN_QUEUE'
        and l.object_handle = o.kglhdadr
        and l.holding_user_session = s.saddr
     group by s.sid, holding_user_session, object_handle, l.type, mode_held, mode_requested
     order by lock_cnt desc, s.sid, holding_user_session, l.type, mode_held, mode_requested;

   SID HOLDING_USER_SES OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED   LOCK_CNT
 ----- ---------------- ---------------- ---- ---------- -------------- ----------
     6 000000018FA49D60 0000000167A4B2E0 LOCK          1              0       1003
    70 000000018FA93AA0 0000000167A4B2E0 LOCK          1              0       1003
 ...
  1058 000000018FE84A60 0000000167A4B2E0 LOCK          1              0       1002
  1059 000000018D19A168 0000000167A4B2E0 LOCK          1              0       1002
   173 000000018ED35840 0000000167A4B2E0 LOCK          1              0        739
  1025 000000018D177398 0000000167A4B2E0 LOCK          1              0        739        

66 rows selected.        

Examining maximum number of locks per session, they oscillate between 1002 and 1003.

There exist sessions whose LOCK_CNT is not able to reach 1002 because
    66 x 1002 > 65535
hence ORA-04025.

(D). Match Oracle parameters with value like '100%':


To figure out what is the limit of 1003, run:

SQL> select name, value from v$parameter where value like '100%';

 NAME                             VALUE
 -------------------------------- -----
 _session_cached_instantiations   1001

That is _session_cached_instantiations.

(E). Finally clean-up all jobs

  SQL> exec clean_jobs;

1.3   65 Batch sessions dequeue test


Repeat the same test by launching 65 concurrent Jobs. No ORA-04025 occurs.

  SQL> exec test_deq_jobs(65, 2000);

Wait about 18 minutes, run above 3 monitoring queries.
Here the output:

SQL> query_1

 NAME         LOCKS  PINS LOCKED_TOTAL PINNED_TOTAL
 ----------- ------ ----- ------------ ------------
 KSUN_QUEUE   65130     0      2493796      3324170

SQL> query_2

 NAME               OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED    CNT
 ------------------ ---------------- ---- ---------- -------------- ------
 KSUN_QUEUE(QUEUE)  0000000167A4B2E0 LOCK          1              0  65130
 
SQL> query_3
 
   SID HOLDING_USER_SES OBJECT_HANDLE    TYPE  MODE_HELD MODE_REQUESTED   LOCK_CNT
 ----- ---------------- ---------------- ---- ---------- -------------- ----------
     6 000000018FA49D60 0000000167A4B2E0 LOCK          1              0       1003
    40 000000018FA6CB30 0000000167A4B2E0 LOCK          1              0       1003
 ...   
  1027 000000018D1752C8 0000000167A4B2E0 LOCK          1              0       1002
  1058 000000018FE84A60 0000000167A4B2E0 LOCK          1              0       1002

65 rows selected.        

All sessions can own a minimum LOCK_CNT of 1002 because
    65 x 1002 < 65535
hence no ORA-04025.

To terminate the test, clean-up all jobs

  SQL> exec clean_jobs;

1.4 _session_cached_instantiations


Lowering _session_cached_instantiations from 1001 to 401, restart DB:
   alter system set "_session_cached_instantiations"=401 scope=spfile;
repeat the test, no more error even for 100 Jobs; but error reappears with 200 Jobs.

Since not clear what is the limit of "_session_cached_instantiations", it is worth of gambling its extreme behavior with two additional tests, one with 65535, another with 65536.

alter system set "_session_cached_instantiations"=65535 scope=spfile;

restart DB

SQL> exec test_deq(65536, 0, 0);

 deq_cnt: 65536, lock_cnt: 65535
 ORA-04025: maximum allowed library object lock allocated for S.KSUN_QUEUE

Then make some unrealistic adventure:

alter system set "_session_cached_instantiations"=65536 scope=spfile;

restart DB

SQL> exec test_deq(65536, 0, 0);

 deq_cnt: 65536, lock_cnt: 65535
 ORA-04025: maximum allowed library object lock allocated for K.KSUN_QUEUE


Both identical outputs show that sessions raise ORA-04025 at limit 65535, otherwise they violate the condition:
   floor(65535/_session_cached_instantiations) >= 1

1.5   12c vs. 11g dequeue behavior


Running the same tests in 11.2.0.4.0, number of locks per session on KSUN_QUEUE is constantly kept as 1. Hence, 12c dequeue behavior is perturbed, in which each dequeue call opens a new lock on the queue, but never release it till ceiling _session_cached_instantiations. One can wonder if that can be classified as a library object lock leak.

Oracle Database Advanced Queuing 12c seems introduced some new AQ background architecture, for example, AQPC (GV$AQ_BACKGROUND_COORDINATOR).

1.6 MOS Note


Resorting to MOS, there is one hit of 65535 hinting to ORA-4025.

MOS Bug 14542720 - ORA-4025 with CURSOR_SHARING / Dynamic Sampling (Doc ID 14542720.8) said:
  Look for the ActiveLocks value of some cursor to show very high values  (when it reaches 65535 the ora-4025 is raised)

2. SQL cursor and ORA-04025


As a general understanding of ORA-04025, it is necessary to examine its original designation for SQL Cursors. Pick the JAVA test code provided by Oracle MOS, we will make 3 tests.

Note: the same Java code is tested on both 11.2.0.4.0 and 12.1.0.2.0, the behaviors are identical.

At first, set open_cursors:
  alter system set open_cursors=50000 scope=both;

2.1 Single session


Start one single session, monitor by:

SQL> select sid, sql_id, sql_text, count(*) cnt
       from v$open_cursor
      where cursor_type in ('OPEN')
      group by sid, sql_id, sql_text
      order by cnt desc;

when opened cursors reaching 50000, it hits:
 ORA-01000: maximum open cursors exceeded
    
$1 > java OracleJdbcExample4025
 Count=49998, Date : 2016-07-21 10:50:17
 Count=49999, Date : 2016-07-21 10:50:17
 Exception in thread "main" java.sql.SQLException: ORA-01000: maximum open cursors exceeded


2.2 Two concurrent sessions


Start two sessions, both throw ORA-04025:

$1 > java OracleJdbcExample4025

 Count=25115, Date : 2016-07-21 11:46:45.0
 Count=25116, Date : 2016-07-21 11:46:45.0
 Exception in thread "main" java.sql.SQLException: 
  ORA-04025: maximum allowed library object lock allocated for select sysdate as current_day from dual

$2 > java OracleJdbcExample4025

 Count=40418, Date : 2016-07-21 11:46:45.0
 Count=40419, Date : 2016-07-21 11:46:45.0
 Exception in thread "main" java.sql.SQLException: 
  ORA-04025: maximum allowed library object lock allocated for select sysdate as current_day from dual

Summing two outputs agrees the equality:
   25116 + 40419 = 65535
which confirms "LIBRARY OBJECT LOCK: MAXIMUM 65535".

2.3 Boundary value


According to Oracle Documentation, open_cursors has a legal range of values:
    0 to 65535
what happens when setting open_cursor=65535 ?
Both ORA-01000 and ORA-04025 are satisfied by boundary value 65535, which one is raised at first ? (second will never be presented).

Here the test output:

alter system set open_cursors=65535 scope=both;

$1 > java OracleJdbcExample4025

  Count=65533, Date : 2016-07-22 08:01:49.0
  Count=65534, Date : 2016-07-22 08:01:49.0
  Exception in thread "main" java.sql.SQLException: ORA-01000: maximum open cursors exceeded


So we can guess that ORA-04025 is ordered after ORA-01000 in the code path. That is also why to provoke ORA-04025 for SQL cursor, minimum two sessions are required.

Summary


Recapping all the tests, we can draw a few possible observations, but I would be careful to have any earlier conclusions before Oracle says.

1. SQL cursor is a library object, but not each library object is a SQL cursor, for example, AQ queue.

2. OPEN_CURSORS specifies the maximum number of open cursors per session can have at each instant. HARD Limit.

3. SESSION_CACHED_CURSORS specifies the number of cursors to cache per session, an optimization advice. SOFT Limit.

4. OPEN_CURSORS, SESSION_CACHED_CURSORS are parameters applied to SQL cursor.

5. "LIBRARY OBJECT LOCK: MAXIMUM 65535" specifies limit per library object. HARD Limit.

6. 12c _SESSION_CACHED_INSTANTIATIONS specifies number of library object lock on AQ queue per session.
    HARD Limit, but not raising error.

7. "LIBRARY OBJECT LOCK: MAXIMUM 65535" and _SESSION_CACHED_INSTANTIATIONS together defines
     maximum number of concurrent sessions to avoid ORA-04025:
            floor(65535/_session_cached_instantiations)

References


1. open_cursors, session_cached_cursors: cursordump

2. Oracle 12c single session "library cache lock (cycle)" deadlock

3. Foreign Keys and Library Cache Locks: Analysis

Test Code



------------------------------------- AQ dequeue ---------------------------------
--alter system set "_session_cached_instantiations"=1001 scope=spfile;
--alter system set open_cursors=800 scope=both;
--alter system set session_cached_cursors=600 scope=spfile;

drop type Q_OBJ force;

create or replace type Q_OBJ is object (id number, name varchar2(100));
/       

begin sys.dbms_aqadm.drop_queue_table(queue_table => 'Q_TAB', force=> TRUE); end;
/

begin
  sys.dbms_aqadm.create_queue_table
  (queue_table        => 'Q_TAB'
  ,queue_payload_type => 'Q_OBJ'
  ,compatible         => '10.0.0'  
  ,sort_list          => 'PRIORITY,ENQ_TIME'
  ,multiple_consumers =>  false
  ,message_grouping   =>  0
  ,comment            =>  'queue table'
  ,secure             =>  false);
end;
/

begin
  sys.dbms_aqadm.stop_queue (queue_name => 'KSUN_QUEUE');
  sys.dbms_aqadm.drop_queue (queue_name => 'KSUN_QUEUE');
end;
/

begin
  sys.dbms_aqadm.create_queue
  (queue_name     => 'KSUN_QUEUE'
  ,queue_table    => 'Q_TAB'
  ,queue_type     => sys.dbms_aqadm.normal_queue
  ,max_retries    => 100
  ,retry_delay    => 2
  ,retention_time => 604800
  ,comment        => 'ksun queue');
end;
/

begin sys.dbms_aqadm.start_queue(queue_name => 'KSUN_QUEUE', enqueue => true, dequeue => true); end;
/
  
create or replace procedure test_enq(p_cnt number := 1, p_sleep number := 0, p_prt boolean :=false) as
  l_enqueue_options dbms_aq.enqueue_options_t;
  l_msg_properties  dbms_aq.message_properties_t;
  l_msg_handle      raw(16);
  l_msg             q_obj;
  l_lock_cnt        number;
  
  procedure prt(i_cnt number, i_prt boolean) as
   begin
    if i_prt then
     select locks into l_lock_cnt from v$db_object_cache where name = 'KSUN_QUEUE';
     dbms_output.put_line ('deq_cnt: '||i_cnt||', lock_cnt: '||l_lock_cnt);
   end if;
   end;
begin 
 dbms_application_info.set_module(module_name => 'enq session', action_name => 'enqueue');
  for i in 1..p_cnt loop
    l_msg := q_obj(i, rpad(i, 10, 'X'));
            
    dbms_aq.enqueue(queue_name         => 'KSUN_QUEUE',
                    enqueue_options    => l_enqueue_options,
                    message_properties => l_msg_properties,
                    payload            => l_msg,
                    msgid              => l_msg_handle);
    prt(i, p_prt);
    
    commit;
    
    if p_sleep > 0 then
      dbms_lock.sleep(p_sleep);
    end if;
  end loop;
end;
/

create or replace procedure test_deq(p_cnt number := 1, p_sleep number := 0, p_wait number := 1, 
                                     p_prt boolean :=false) as
 l_dequeue_options     dbms_aq.dequeue_options_t;
 l_msg_properties      dbms_aq.message_properties_t;
 l_msg_handle          raw(16);
 l_msg                 q_obj;
 l_lock_cnt            number;
 no_messages_excp      exception;
 pragma exception_init (no_messages_excp, -25228);
  
  procedure prt(i_cnt number, i_prt boolean) as
   begin
    if i_prt then
     select locks into l_lock_cnt from v$db_object_cache where name = 'KSUN_QUEUE';
     dbms_output.put_line ('deq_cnt: '||i_cnt||', lock_cnt: '||l_lock_cnt);
   end if;
   end;
begin
 dbms_application_info.set_module(module_name => 'deq session', action_name => 'dequeue');
 l_dequeue_options.wait := p_wait;
  for i in 1..p_cnt loop
  begin 
   if p_sleep > 0 then
    dbms_lock.sleep(p_sleep);
   end if;
   
    dbms_aq.dequeue(queue_name            => 'KSUN_QUEUE',
                    dequeue_options       => l_dequeue_options,
                    message_properties    => l_msg_properties,
                    payload               => l_msg,
                    msgid                 => l_msg_handle);
          
    dbms_output.put_line ('MSG id: '||l_msg.id||', name: '||l_msg.name);
    
    prt(i, p_prt);
    
    commit;
      exception when no_messages_excp then prt(i, p_prt);
         when others then prt(i, true); 
                  raise;  
   end;
 end loop;
end;
/    

create or replace procedure test_deq_jobs (p_jobs number := 66, p_cnt number := 2000) as
 l_job_id pls_integer;
begin
  for i in 1..p_jobs loop
  dbms_job.submit(l_job_id, 'begin while true loop test_deq('||p_cnt||'); end loop; end;');
  commit;
  dbms_output.put_line(l_job_id);
 end loop;
end;
/        

create or replace procedure clean_jobs as
  begin
   for c in (select job from dba_jobs) loop
      begin
         dbms_job.remove (c.job);
      exception when others then null;
      end;
      commit;
   end loop;

   for c in (select d.job, d.sid, (select serial# from v$session where sid = d.sid) ser 
               from dba_jobs_running d) loop
      begin
         execute immediate
               'alter system kill session '''|| c.sid|| ',' || c.ser|| ''' immediate';
         dbms_job.remove (c.job);
      exception when others then null;
      end;
      commit;
   end loop;
   
   -- select * from dba_jobs;
   -- select * from dba_jobs_running;
end;
/

------------------------------------- SQL curosr and ORA-04025 Test ---------------------------------

import java.sql.Connection; 
import java.sql.DriverManager; 
import java.sql.PreparedStatement; 
import java.sql.ResultSet; 
import java.sql.SQLException;

public class OracleJdbcExample4025 { 

public static void main(String args[]) throws SQLException { 
 System.out.println("--------SQL curosr and ORA-04025 Test ------");
 try {
  Class.forName("oracle.jdbc.driver.OracleDriver");
 } catch (ClassNotFoundException e) {
  System.out.println("Where is your Oracle JDBC Driver?");
  e.printStackTrace();
  return;
 }
 System.out.println("Oracle JDBC Driver Registered!");
 Connection connection = null;
 try {
  connection = DriverManager.getConnection(
    "jdbc:oracle:thin:@testdb:1522:testdb", "s", "s");  // adapt it
 } catch (SQLException e) {
  System.out.println("Connection Failed! Check output console");
  e.printStackTrace();
  return;
 }    
 String sql ="select sysdate as current_day from dual"; 
 int cnt = 0;
 while (true) { 
  //creating PreparedStatement object to execute query 
  PreparedStatement preStatement = connection.prepareStatement(sql); //<<< this opening cursor 
  ResultSet result = preStatement.executeQuery(); 
  while(result.next()){ 
   System.out.println("Count=" + (++cnt) + ", Date : " + result.getString("current_day")); 
  } 
 // preStatement.close();  //<<< if this is uncommented cursor is closed, otherwise not. 
 } 
 // System.out.println("done"); 
 } 
} 

Monday, June 13, 2016

SQL Parsing in serializable transaction throws ORA-08177: can't serialize access for this transaction

Setting serializable isolation level in Oracle 12c (12.1.0.2.0), SQL Parsing can throw:
  ORA-08177: can't serialize access for this transaction

run test (see Blog appended TestCode):
 
SQL (742) > exec ora_08177_test(10, 'ksun_ora_08177_collect_listagg');

Run=1
ERROR at line 1:
ORA-08177: can't serialize access for this transaction
ORA-06512: at "ORA_08177_TEST", line 20
ORA-06512: at line 1

Note: Each time, open a new session, run the test. After first run, subsequent runs in the same session do not hit the error.

According to Oracle documentation: Database Concepts - Data Concurrency and Consistency

The database generates an error when a serializable transaction tries to update or delete data changed by a different transaction that committed after the serializable transaction began:
 ORA-08177: Cannot serialize access for this transaction


Here there exists only one single session, so it does not satisfy the requirement of above documentation.

Reasoning


Refer to the recursive session discussed in Blog: Oracle 12c single session "library cache lock (cycle)" deadlock .

run query:
 
select distinct s.sid, holding_user_session, holding_session
  from v$libcache_locks c, v$session s
 where lnnvl(holding_user_session = holding_session)
   and c.holding_user_session = s.saddr 
   and s.sid = 742;
   
SID HOLDING_USER_SES HOLDING_SESSION 
--- ---------------- ----------------
742 070001010ECF8680 070001010ECFC880    

(742 is the SID of test session)

crosscheck the dump generated by 8177 trace event on AIX (we set this event for the test):

----- Call Stack Trace -----
ktrexc()+3536        call     ksesecl0()           FFFFFFFFFFC9FB0 ? 122F5F490 ?
rpidrv()+3572        call     rpiswu2()            70001010ECFC880 ? 1221BF1E0 ?
kksLoadChild()+3544  call     rpiswu2()            70001010ECF8680 ? 000000090 ?
...
========== FRAME [19] (ktrexc()+3536 -> ksesecl0()) ==========
defined by frame pointers 0xffffffffffca080  and 0xffffffffffc9ee0
CALL TYPE: call   ERROR SIGNALED: yes   COMPONENT: (null)
...
PROCESS STATE
-------------
Process global information:
     process: 0x70001010e8c4078, call: 0x7000100eb0e7bb0, xact: 0x7000101037e9880, 
     curses: 0x70001010ecfc880, usrses: 0x70001010ecf8680
...
KSUSETRN = 0X07000101037E9880
...
(trans) flg = 0x00000004, flg2 = 0x00400000, flg3 = 0x00000040, 
  prx = 0x7000101037e9880, ros = 2147483647, crtses=0x70001010ecf8680

we can establish two equations:

holding_user_session = 070001010ECF8680 = usrses: 0x70001010ecf8680
holding_session      = 070001010ECFC880 = curses: 0x70001010ecfc880

which tellingly indicate the co-existence of two different sessions, usrses(user session) and curses (cursor session), and existence of transaction (0X07000101037E9880) created by user session (crtses=0x70001010ecf8680).

Looking Call Stack Trace, user session calls:
   kksLoadChild()
and then switches to cursor session, which triggers rpi (recursive procedure interface):
 rpidrv()
and finally ERROR SIGNALED at:
  ktrexc()
where ktr means kernel transaction read consistency.

Since user session already started a transaction, any attempt to modify the data by the cursor session resulted in:
 ORA-08177: can't serialize access for this transaction

Run other two tests:

SQL (742) > exec ora_08177_test(10, 'ksun_ora_08177_collect');
SQL (742) > exec ora_08177_test(10, 'ksun_ora_08177_listagg');

there are no errors.

Hence, the error is probably related to certain constellation of collect and listagg.

All tests are performed on AIX, Solaris and Linux with Oracle 12c (12.1.0.2.0).
It is not reproducible in Oracle 11.2.0.4.0.

By the way, the first run of query:

SQL (742)> select collect (y) from ksun_ora_08177;
SYSTPNSRcj9+JXnjgVAAmVdl5Ow==(1, 2, 3, 0, 1, 2, 3, 0, 1)

creates a new TYPE:

TYPE     "SYSTPNSRcj9+JXnjgVAAmVdl5Ow==" AS TABLE OF NUMBER

which is due to "COLLECT" function.

It can be verified by:

select s.*, o.last_ddl_time, o.created, o.*
  from dba_source s, dba_objects o
 where s.name = o. object_name
   and o.object_type = 'TYPE'
   and name = 'SYSTPNSRcj9+JXnjgVAAmVdl5Ow==';

and also documented in Database SQL Language Reference:

COLLECT is an aggregate function that takes as its argument a column of any type
and creates a nested table of the input type out of the rows selected.


Another example of TYPE creation was observed in Blog: Oracle 12c single session "library cache lock (cycle)" deadlock.

TestCode


--------------------
set numformat 99
column y_coll format a10

alter system set events '8177 trace name errorstack level 10';

drop table ksun_ora_08177;

create table ksun_ora_08177 as select mod(level, 2) x, mod(level, 4) y from dual connect by level <= 9; 

select * from ksun_ora_08177;

create or replace type ksun_tab force is table of number;
/

--------------------
create or replace force view ksun_ora_08177_collect_listagg(x, cnt, y_coll) as
with sq as (
  select x, count(*) cnt, cast (collect (distinct y) as ksun_tab) y
  from ksun_ora_08177
  group by x)
select x, cnt,
       (select listagg (column_value, ',') within group (order by column_value)
          from table (y)) y_coll
from sq 
where x is not null;

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

create or replace force view ksun_ora_08177_collect(x, cnt, y_coll) as
select x, count(*) cnt, cast (collect (distinct y) as ksun_tab) y_coll
from ksun_ora_08177
where x is not null
group by x;

--------------------
create or replace force view ksun_ora_08177_listagg(x, cnt, y_coll) as
select x, count(*) cnt, listagg (y, ',') within group (order by y) y_coll
from ksun_ora_08177
where x is not null
group by x;

--------------------
create or replace procedure ora_08177_test(p_cnt number, p_view varchar2) as
 l_cur       integer;
 l_qry       varchar2(300) := 'select * from '||p_view;
 l_idx           pls_integer;
 l_col_desc_tab  dbms_sql.desc_tab;
begin
 l_qry := 'select /* '||p_view ||' */ * from '||p_view;
 for i in 1..p_cnt loop
  dbms_output.put_line('Run='||i);
  execute immediate 'alter system flush shared_pool';

  begin
    commit;
    set transaction isolation level serializable;
    l_cur := dbms_sql.open_cursor;
    dbms_sql.parse(l_cur, l_qry, dbms_sql.native);
    dbms_sql.describe_columns (l_cur, l_idx, l_col_desc_tab);
    dbms_sql.close_cursor(l_cur);
    exception when others then
      dbms_sql.close_cursor(l_cur);
      raise;
  end;
 end loop;
end;
/

-- Note: Each time, open a new session, run the test. After first run, subsequent runs in the same session do not hit the error.
-- exec ora_08177_test(10, 'ksun_ora_08177_collect_listagg');
-- exec ora_08177_test(10, 'ksun_ora_08177_collect');
-- exec ora_08177_test(10, 'ksun_ora_08177_listagg');


Tuesday, May 17, 2016

Oracle Fixed Table Practice

Oracle Fixed Table Practice Fixed objects x$ tables and their indexes are memory structures storing run-time information. They are open to outside as normal tables because every thing is Relation (Table) in relational database, principle founded by Edgar F. Codd ("A relational model of data for large shared data banks"). Similar uniform philosophy in UNIX is every thing is file (notably proc filesystem procfs).

This Blog will try to do expose meta data of x$ tables since they are not handled in a uniform way as normal tables. We also take GV$SQL_OPTIMIZER_ENV and its underlined X$KQLFSQCE as example in the queries because this x$ table is dynamic, big, and longer duration of its stats gathering.


1. List all fixed objects


select * from x$kqfta fxt, sys.fixed_obj$ fobj where fobj.obj# = fxt.kqftaobj and fxt.kqftanam in ('X$KQLFSQCE');


2. List indexes of fixed objects

 
select index_number, column_name from gv$indexed_fixed_column where table_name in ('X$KQLFSQCE');
 1 KQLFSQCE_HASH
 2 KQLFSQCE_SQLID  

We can try to verify them by looking the xplan of following queries:

select * from gv$sql_optimizer_env where hash_value = :hash_value;
 FIXED TABLE FIXED INDEX TABLE (FIXED) SYS.X$KQLFSQCE (ind:1)

select * from gv$sql_optimizer_env where sql_id = :sql_id;
 FIXED TABLE FIXED INDEX TABLE (FIXED) SYS.X$KQLFSQCE (ind:2)

select * from gv$sql_optimizer_env where id = :id;   (KQLFSQCE_PNUM)
 FIXED TABLE FULL TABLE (FIXED) SYS.X$KQLFSQCE


3. List histogram of fixed objects


select column_name, histogram from dba_tab_col_statistics 
 where table_name in ('X$KQLFSQCE') and histogram not in ('NONE');
  INST_ID        FREQUENCY
  KQLFSQCE_FLAGS FREQUENCY
 
select distinct table_name, column_name from dba_tab_histograms where table_name in ('X$KQLFSQCE');
 INST_ID
 KQLFSQCE_FLAGS
 
select dbms_stats.report_gather_fixed_obj_stats(detail_level=>'ALL', format=>'TEXT') from dual;
 INST_ID
 KQLFSQCE_HADD
 KQLFSQCE_SQLID
 KQLFSQCE_FLAGS
 KQLFSQCE_PNUM

The above 3 outputs have differences, and we can try to verify them by looking the xplan of following queries:
                                                                                                        
select * from gv$sql_optimizer_env where inst_id = 1;
  FIXED TABLE FULL TABLE (FIXED) SYS.X$KQLFSQCE QBlock Name: SEL$5C160134
    Cost: 1  Bytes: 32,349,932  Cardinality: 376,162

select * from gv$sql_optimizer_env where inst_id = 9;
  FIXED TABLE FULL TABLE (FIXED) SYS.X$KQLFSQCE QBlock Name: SEL$5C160134
    Cost: 1  Bytes: 86  Cardinality: 1

select * from gv$sql_optimizer_env where id = 1;
  FIXED TABLE FULL TABLE (FIXED) SYS.X$KQLFSQCE QBlock Name: SEL$5C160134
    Cost: 1  Bytes: 68,800  Cardinality: 800

select * from gv$sql_optimizer_env where id = 9;
  FIXED TABLE FULL TABLE (FIXED) SYS.X$KQLFSQCE QBlock Name: SEL$5C160134
    Cost: 1  Bytes: 68,800  Cardinality: 800

We can see that two queries on column ID (KQLFSQCE_PNUM) give the same xplan estimation, probably does not have histogram. It is not clear why dbms_stats.report_gather_fixed_obj_stats lists more columns.


4. List stats gathering performance of fixed tables

                                                                                                  
select v.last_analyzed, table_name, num_rows, sample_size, avg_row_len 
      ,(v.last_analyzed - lag(v.last_analyzed) over (order by v.last_analyzed))*86400 seconds 
      ,(num_rows * avg_row_len) bytes 
      ,(sample_size/nullif(num_rows, 0)) sample_ratio 
      ,v.* 
  from dba_tab_statistics v 
 where object_type in ('FIXED TABLE') 
   and v.last_analyzed between timestamp'2016-05-17 09:00:00' and timestamp'2016-05-17 10:00:00' 
order by seconds desc nulls last;       

As a result of above query, we can find the most time consuming of x$ tables in:
  dbms_stats.gather_fixed_objects_stats;
and hence exclude them in next stats gather by calling
  dbms_stats.lock_table_stats


5. Trace x$ table access


On Solaris, run:
     exec dbms_stats.gather_fixed_objects_stats;
and simultaneously watch kqlfsqce call by dtrace script (8694 is PID of above SQL Session):

sudo dtrace -n \
'BEGIN {printf("dtrace started: %Y\n", walltimestamp);}
pid8694:a.out:kqlfsqce: { @[execname, ustack()] = count();} 
END { trunc(@, 10);}
END { printf("dtrace ended: %Y\n", walltimestamp);}'

and stop the tracing once X$KQLFSQCE is gathered, the output looks as:

dtrace: description 'BEGIN ' matched 111 probes
CPU     ID                    FUNCTION:NAME
 17      1                           :BEGIN dtrace started: 2016 May 17 09:13:01
^C
 21      2                             :END
 21      2                             :END dtrace ended: 2016 May 17 09:42:42

  oracle
              oracle`kqlfsqce+0x2c
              oracle`qerfxFetch+0x125f
              oracle`rwsfcd+0x6f
              oracle`qeruaFetch+0x173
              oracle`rwsfcd+0x6f
              oracle`qerltFetch+0x4c8
              oracle`insdlexe+0x202
              oracle`insExecStmtExecIniEngine+0x6b
              oracle`insexe+0x6eb
              oracle`opiexe+0x179f
              oracle`opipls+0x62a
              oracle`opiodr+0x433
              oracle`rpidrus+0xde
              oracle`skgmstack+0x85
              oracle`rpidru+0x88
              oracle`rpiswu2+0x2fd
              oracle`rpidrv+0x589
              oracle`psddr0+0x138
              oracle`psdnal+0x2cd
              oracle`pevm_EXIM+0xf0
          3290001

Crosschecking with output of above sql query, the row for X$KQLFSQCE shows:
  sample_size = 3281070
  seconds = 1736

Sunday, April 10, 2016

sql_id and idn to shared pool subpool

Oracle shared pool is divided into a few of subpools(maximum 7). Each sql_id is mapped to its subpool by hash function:
    subpool no = mod(mod(dbms_utility.sqlid_to_sqlhash(sql_id), 131072), subpools) + 1
since
    idn=dbms_utility.sqlid_to_sqlhash (sql_id)
the mapping can be written as:
    subpool no = mod(mod(idn, 131072), subpools) + 1
where subpools is the number of used subpools, which can be observed by:
   select * from v$latch_children where name = 'shared pool';
 
The above hash function can be used to monitor sql_id unbalanced distributions of subpools (see Blog: Shared Pool - Memory Allocation - unbalanced ).


For instance, once seeing the error message:
   ORA-04031: unable to allocate 184 bytes of shared memory ("shared pool","SELECT ...","SQLA^de798f19","179.kggfa")
you can find its subpool by:
   mod(mod(to_number('de798f19', 'xxxxxxxx'), 131072), 7)+ 1 = 5

If majority of such errors occurs in subpool 5, it would be a hint pointing to the unbalanced distributions.


The above formula is verified in Oracle 11gR2 and 12c.

Sunday, February 14, 2016

Native Code Files: Ora-7445 [Ioc_pin_shared_executable_object()] Reproducing

PL/SQL and JAVA Native Code Files are used in Oracle to boost performance.

Blog: Remove Stale Native Code Files on AIX discussed the generation and remove of Native Code Files.

Blog: What the heck are the /dev/shm/JOXSHM_EXT_x files on Linux? revealed the contents and lading of Native Code Files.

Both Blogs follow MOS Note Ora-7445 [Ioc_pin_shared_executable_object()] (Doc ID 1316906.1), which said:
  If ORA-7445 [ioc_pin_shared_executable_object] is encountered, one should look into the following:
  1) Is there any user or job that may have tried to clean up files in the directory where the backing store images are located?
  2) Is the location where the backing store files are located out of space?
  3) Is the location where the backing store files are located accessible?

This Blog will try to reproduce the error on Linux with Oracle Version 11.2.0.4.0.

1. PL/SQL Native Code Files


Create Package by:
 alter system set plsql_code_type=native;    
 -- Default  INTERPRETED
 
 create or replace package bla as
   procedure foo;
 end;
 /
 create or replace package body bla as
   procedure foo is begin null; end;
 end;
 /
   
One Native Code File is generated after create package body bla (not generated after create package spec), and stored in tmpfs (/dev/shm/):
   linux: ls -lt /dev/shm/
   -rwx------ 1 oracle dba 424 Feb 12 07:08 PESLD_testdb_56ae0002_b8c1106001000000*

In Sqlplus, run:
 07:09:48 (243,7)>  exec bla.foo;

In Linux, map into the virtual memory of calling process (15022 is PID of Oracle session (243,7)):
  linux: pmap -x 15022
   Address           Kbytes     RSS   Dirty Mode   Mapping
   00007ff61a7cb000       4       4       4 r-x--  PESLD_testdb_56ae0002_b8c1106001000000

  linux: cat /proc/15022/maps
   7ff61a7cb000-7ff61a7cc000 r-xp 00000000 00:0f 21930676  /dev/shm/PESLD_testdb_56ae0002_b8c1106001000000

if we remove it:
  linux: rm /dev/shm/PESLD_testdb_56ae0002_b8c1106001000000

they are marked as "deleted" for PID 15022:

   00007f19bcd64000       4       4       4 r-x--  PESLD_testdb_56ae0002_b8c1106001000000 (deleted)
   7f19bcd64000-7f19bcd65000 r-xp 00000000 00:0f 21618650 /dev/shm/PESLD_testdb_56ae0002_b8c1106001000000 (deleted)

Open a new SQL session, run:
 07:18:07 (325,21) > exec bla.foo;
 ORA-00600: internal error code, arguments: [pesldl01_Get_Object: shm_open failed: errno 2 errmsg No such fil], [/PESLD_testdb_56ae0002_b8c1106001000000]

strace shows:
 open("/dev/shm/PESLD_testdb_56ae0002_b8c1106001000000", O_RDWR|O_NOFOLLOW|O_CLOEXEC) = -1 ENOENT (No such file or directory):
 
occasionally there is incident dump, which shows:
 ORA-07445: exception encountered: core dump [ioc_pin_shared_executable_object()+888] [SIGSEGV] [ADDR:0x0] [PC:0x30E1CD0] [Address not mapped to object] []
 
In the already opened session, it is still OK:
 07:29:48 (243,7) > exec bla.foo;

Native Code Files are stored in tmpfs (/dev/shm/) and there is no locking mechanisms to prevent them from removing by the user. In Linux, tmpfs is one part of cache (see output of command free and vmstat). In case of low memory situations, it could be subject to garbage collection or swapping out.

2. Java JIT Native Code Files


Run
 alter system set java_jit_enabled=true;
 create or replace and compile java source named "Hello" as
  public class Hello {
     public static String world ()
     {
        return "hello world";
     }
  }
 /
 create or replace function helloworld
  return varchar2 as language java
  name 'Hello.world () return java.lang.string';
 /
 select helloworld from dual;

We can see more than 100 files are created after compile java source. They all look like:
 /dev/shm/JOXSHM_EXT_553_testdb_1451786242*


3. Ora-7445 [Ioc_pin_shared_executable_object()] Reproducing


At first restart database by:
 shutdown immediate   
 startup 
 
so that all Native Code Files are cleaned away, no more files under /dev/shm/
(note: "shutdown abort" will not clean up /dev/shm/, see Blog: Remove Stale Native Code Files on AIX).


Open one Plsql session, run a simple query:

 08:07:38 (124,13)> select helloworld from dual;
  hello world
 
and at the same time, one can also watch the process in Linux (51876 id PID of Session 124):

 linux: strace -p 51876 
  open("/dev/shm/JOXSHM_EXT_162_testdb_1454571522", O_RDWR|O_CREAT|O_TRUNC|O_NOFOLLOW|O_CLOEXEC, 0770) = 7
  fchmod(7, 0770)                         = 0
  ftruncate(7, 12288)                     = 0
  write(7, "\0", 1)                       = 1
  lseek(7, 4095, SEEK_CUR)                = 4096
  write(7, "\0", 1)                       = 1
  lseek(7, 4095, SEEK_CUR)                = 8192
  write(7, "\0", 1)                       = 1
  mmap(NULL, 12288, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_SHARED, 7, 0) = 0x7f9f77a52000
  close(7)                                = 0
 
 linux: ls -ltr /dev/shm/* |wc
     167    1503   14258 
     
 linux: pmap -x 51876    
  00007f1fb1b96000       4       4       4 rwxs-  JOXSHM_EXT_47_testdb_1453129730
  ...
  00007f1fb1b97000       4       4       4 rwxs-  JOXSHM_EXT_8_testdb_1453129730
 
Allocate 33GB PGA memory (see Test Code in Blog: Limit PGA Memory Usage):

 08:09:25 (124,13)> exec pga_mem_test.allo(33*1024);
  Start allocate: 3379 > Used/Alloc/Freeable/Max >>> 11/14/1/16
               ------ Category(Alloc/Used/Max) >>> SQL(1/0/5) > PL/SQL(2/2/4) > Other(6//6) > JAVA(4/4/5) > Freeable(1/0/) >
  ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pl/sql vc2)
 
 08:09:36 (124,13)> select helloworld from dual;
  hello world
  
 and the trace dump shows:
  Memory (Avail / Total) = 640.90M / 15943.66M
  Swap (Avail / Total) = 8152.43M /  8187.99M
  ioc_allocate(size: 335927, heap name: *** ??? ***, flags: a0008) caught 4030
 
Run a new query, which requires new mmap:
 08:10:31 (124,13)> select dbms_java.get_compiler_option('', 'encoding')from dual;
  ORA-04030: out of process memory when trying to allocate 262224 bytes (joxcx callheap,f:Class)
  ORA-06512: at "SYS.DBMS_JAVA", line 147

continue running that query, get the same error.

and strace shows:
 linux: strace -p 51876
  unlink("/dev/shm/JOXSHM_EXT_162_testdb_1454571522") = 0
  open("/dev/shm/JOXSHM_EXT_162_testdb_1454571522", O_RDWR|O_CREAT|O_TRUNC|O_NOFOLLOW|O_CLOEXEC, 0770) = 19
  fchmod(19, 0770)                        = 0
  ftruncate(19, 12288)                    = 0
  write(19, "\0", 1)                      = 1
  lseek(19, 4095, SEEK_CUR)               = 4096
  write(19, "\0", 1)                      = 1
  lseek(19, 4095, SEEK_CUR)               = 8192
  write(19, "\0", 1)                      = 1
  mmap(NULL, 12288, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_SHARED, 19, 0) = 0x7f9f77a52000
  close(19)        

Open a new session, run the same select:
 08:13:12 (356,7)> select dbms_java.get_compiler_option('', 'encoding')from dual;
  UTF-8

watch the new loaded files:
 linux: ls -ltr /dev/shm|wc
     317    2846   24555

Back to the error session, run the select again:
 08:15:22 (124,13)> select dbms_java.get_compiler_option('', 'encoding')from dual;
  ORA-03113: end-of-file on communication channel
  Process ID: 51876
  Session ID: 124 Serial number: 13
  ORA-03114: not connected to ORACLE
 
and strace said:
 linux: strace -p 51876
  open("/dev/shm/JOXSHM_EXT_2_testdb_1454571522", O_RDWR|O_NOFOLLOW|O_CLOEXEC) = 8
  mmap(NULL, 4096, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_SHARED, 8, 0) = -1 ENOMEM (Cannot allocate memory)
  ...
  --- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_MAPERR, si_addr=0} ---

The same Native Code File in Session 356 (54806 is PID of Session 356):
 pmap -x 54806 |grep JOXSHM_EXT_2_
  00007ff1785ba000       4       4       4 rwxs-  JOXSHM_EXT_2_testdb_1453719554
  
 (Note that "PROT_READ|PROT_WRITE|PROT_EXEC" are mapped to "rwx", "MAP_SHARED" to "s") 
 

The incident dump of error session shows:
 ORA-07445: exception encountered: core dump [ioc_pin_shared_executable_object()+888] [SIGSEGV] [ADDR:0x0] [PC:0x30E1CD0] [Address not mapped to object] []
 > ioc_pin_shared_executable_object()+888 (0x30e1cd0) mov (%rax),%rdx
 mmap(offset=207478784, len=8192) failed with errno=12 for the file oracletestdb

and the trace dump contains:
 mmap failed with error 12
 error message:Cannot allocate memory
 ORA-04035: unable to allocate 4096 bytes of shared memory in shared object cache "JOXSHM" of size "117440512"
 Assertion failure at joez.c:3422
 Bulk load of method oracle/sql/DatumWithConnection.getPhysicalConnection failed; insufficient shm-object space

(prefix "ioc" in ORA-07445 message could be acronym of "Inversion of Control", something like callbacks)

The same information is also written into MMON_SLAVE dump, for example, M000
 *** MODULE NAME:(MMON_SLAVE) 2016-02-10T07:02:30.076240+01:00
 *** ACTION NAME:(JAVAVM JIT slave action) 2016-02-10T07:02:30.076244+01:00
 ORA-07445: exception encountered: core dump 

With following script, one can watch the allocated size (Kbytes):
  linux: pmap -x 51876 |grep -e PESLD -e JOXSHM |awk '{cnt+=1; Kbytes+=$2; RSS+=$3; Dirty+=$4} END {print "Count=",cnt,",Kbytes=",Kbytes,",RSS=",RSS,",Dirty=",Dirty}'
         Count= 65280 ,Kbytes= 4210688 ,RSS= 4180512 ,Dirty= 4180512


In summary, after a session hits:
  ORA-04030: out of process memory when trying to allocate 262224 bytes (joxcx callheap,f:Class)
and when it wants to load more Native Code Files:
  (1). If the Native Code Files are not found in tmpfs (/dev/shm/), it continues throwing ORA-04030.
  (2). If they are found in tmpfs (which are loaded by other sessions), it throws:
            ORA-07445: exception encountered: core dump [ioc_pin_shared_executable_object()+888] [SIGSEGV]
        and disconnects the session.

Wednesday, January 13, 2016

Performance of Oracle Object Collection Comparisons - Part2

In Blog: Blog Performance of Oracle Object Collection Comparisons - Part1 we discussed two functions: SET, Equal and Not Equal Comparisons. Now we continue to look on other two functions:

COLLECT
    COLLECT is an aggregate function that takes as its argument a column of any type and creates a nested table of the input type out of the rows selected.

Multiset Operators
   Multiset operators combine the results of two nested tables into a single nested table.

1. Setup the test (see appended Test Code)

2. Run the test by:
        truncate table test_stat;
    exec all_test_run_2(4);


3. Wait test finished, query the statistics by:
SET LINES 400
SET NUMWIDTH 12
SET NUMFORMAT 999,999,999
COLUMN TOTAL_COMP_EST_RATIO FORMAT 999.99

select s.*, round(s.total_comp_est/nullif(s.total_comp, 0), 2) total_comp_est_ratio
  from (select t.*, round(10*1000*elapsed/nullif(total_comp, 0), 2) us_per_comp,
         case test_name 
           when 'COLLECT_SORT'                     then round(cnt*ln(cnt)*3)
           when 'COLLECT_SORT_DIST'                then round(cnt*ln(cnt)*3/(greatest(log(10, cnt/disticnt_cnt), 1)))
           when 'COLLECT_DISTINCT'                 then 2*cnt
           when 'COLLECT_DISTINCT_DIST'            then 2*cnt*(greatest(log(10, cnt/disticnt_cnt), 1))
           when 'MULTISET_UNION_ALL'               then 2*cnt
           when 'MULTISET_UNION_ALL_DIST'          then 2*cnt*(greatest(log(10, cnt/disticnt_cnt), 1))
           when 'MULTISET_UNION_DISTINCT'          then 2*cnt
           when 'MULTISET_UNION_DISTINCT_DIST'     then 2*cnt*(greatest(log(10, cnt/disticnt_cnt), 1))
           when 'MULTISET_EXCEPT_ALL'              then 2*cnt
           when 'MULTISET_EXCEPT_ALL_DIST'         then 2*cnt*(greatest(log(10, cnt/disticnt_cnt), 1))
           when 'MULTISET_EXCEPT_DISTINCT'         then 2*cnt
           when 'MULTISET_EXCEPT_DISTINCT_DIST'    then 2*cnt*(greatest(log(10, cnt/disticnt_cnt), 1))
           when 'MULTISET_INTERSECT_ALL'           then 2*cnt
           when 'MULTISET_INTERSECT_ALL_DIST'      then 2*cnt*(greatest(log(10, cnt/disticnt_cnt), 1))
           when 'MULTISET_INTERSECT_DISTINCT'      then 2*cnt
           when 'MULTISET_INTERSECT_DISTINCT_DIST' then 2*cnt*(greatest(log(10, cnt/disticnt_cnt), 1))
         end total_comp_est 
     from test_stat t) s;

returns:

TEST_NAME RUN_ID CNT DISTICNT_CNT ELAPSED TOTAL_COMP SINGLE_COMP US_PER_COMP TOTAL_COMP_EST TOTAL_COMP_EST_RATIO
COLLECT_SORT
1
10
10
0
50
5
0
69
1.38
COLLECT_SORT
2
100
100
2
1278
12.78
15.65
1382
1.08
COLLECT_SORT
3
1000
1000
38
21396
21.396
17.76
20723
0.97
COLLECT_SORT
4
10000
10000
517
302050
30.205
17.12
276310
0.91
COLLECT_SORT_DIST
1
10000
10
117
59990
5.999
19.5
92103
1.54
COLLECT_SORT_DIST
2
10000
100
212
117108
11.7108
18.1
138155
1.18
COLLECT_SORT_DIST
3
10000
1000
322
184044
18.4044
17.5
276310
1.5
COLLECT_SORT_DIST
4
10000
10000
515
302050
30.205
17.05
276310
0.91
COLLECT_DISTINCT
1
10
10
0
26
2.6
0
20
0.77
COLLECT_DISTINCT
2
100
100
1
214
2.14
46.73
200
0.93
COLLECT_DISTINCT
3
1000
1000
5
2020
2.02
24.75
2000
0.99
COLLECT_DISTINCT
4
10000
10000
45
20028
2.0028
22.47
20000
1
COLLECT_DISTINCT_DIST
1
10000
10
105
57968
5.7968
18.11
60000
1.04
COLLECT_DISTINCT_DIST
2
10000
100
200
116242
11.6242
17.21
40000
0.34
COLLECT_DISTINCT_DIST
3
10000
1000
279
164002
16.4002
17.01
20000
0.12
COLLECT_DISTINCT_DIST
4
10000
10000
45
20028
2.0028
22.47
20000
1
MULTISET_UNION_ALL
1
10
10
0
26
2.6
0
20
0.77
MULTISET_UNION_ALL
2
100
100
0
214
2.14
0
200
0.93
MULTISET_UNION_ALL
3
1000
1000
5
2020
2.02
24.75
2000
0.99
MULTISET_UNION_ALL
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_UNION_ALL_DIST
1
10000
10
104
57968
5.7968
17.94
60000
1.04
MULTISET_UNION_ALL_DIST
2
10000
100
199
116242
11.6242
17.12
40000
0.34
MULTISET_UNION_ALL_DIST
3
10000
1000
280
164002
16.4002
17.07
20000
0.12
MULTISET_UNION_ALL_DIST
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_UNION_DISTINCT
1
10
10
0
26
2.6
0
20
0.77
MULTISET_UNION_DISTINCT
2
100
100
1
214
2.14
46.73
200
0.93
MULTISET_UNION_DISTINCT
3
1000
1000
4
2020
2.02
19.8
2000
0.99
MULTISET_UNION_DISTINCT
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_UNION_DISTINCT_DIST
1
10000
10
104
57968
5.7968
17.94
60000
1.04
MULTISET_UNION_DISTINCT_DIST
2
10000
100
199
116242
11.6242
17.12
40000
0.34
MULTISET_UNION_DISTINCT_DIST
3
10000
1000
279
164002
16.4002
17.01
20000
0.12
MULTISET_UNION_DISTINCT_DIST
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_EXCEPT_ALL
1
10
10
1
26
2.6
384.62
20
0.77
MULTISET_EXCEPT_ALL
2
100
100
0
214
2.14
0
200
0.93
MULTISET_EXCEPT_ALL
3
1000
1000
5
2020
2.02
24.75
2000
0.99
MULTISET_EXCEPT_ALL
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_EXCEPT_ALL_DIST
1
10000
10
104
57968
5.7968
17.94
60000
1.04
MULTISET_EXCEPT_ALL_DIST
2
10000
100
199
116242
11.6242
17.12
40000
0.34
MULTISET_EXCEPT_ALL_DIST
3
10000
1000
280
164002
16.4002
17.07
20000
0.12
MULTISET_EXCEPT_ALL_DIST
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_EXCEPT_DISTINCT
1
10
10
0
26
2.6
0
20
0.77
MULTISET_EXCEPT_DISTINCT
2
100
100
1
214
2.14
46.73
200
0.93
MULTISET_EXCEPT_DISTINCT
3
1000
1000
5
2020
2.02
24.75
2000
0.99
MULTISET_EXCEPT_DISTINCT
4
10000
10000
47
20028
2.0028
23.47
20000
1
MULTISET_EXCEPT_DISTINCT_DIST
1
10000
10
104
57968
5.7968
17.94
60000
1.04
MULTISET_EXCEPT_DISTINCT_DIST
2
10000
100
200
116242
11.6242
17.21
40000
0.34
MULTISET_EXCEPT_DISTINCT_DIST
3
10000
1000
280
164002
16.4002
17.07
20000
0.12
MULTISET_EXCEPT_DISTINCT_DIST
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_INTERSECT_ALL
1
10
10
1
26
2.6
384.62
20
0.77
MULTISET_INTERSECT_ALL
2
100
100
0
214
2.14
0
200
0.93
MULTISET_INTERSECT_ALL
3
1000
1000
5
2020
2.02
24.75
2000
0.99
MULTISET_INTERSECT_ALL
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_INTERSECT_ALL_DIST
1
10000
10
105
57968
5.7968
18.11
60000
1.04
MULTISET_INTERSECT_ALL_DIST
2
10000
100
200
116242
11.6242
17.21
40000
0.34
MULTISET_INTERSECT_ALL_DIST
3
10000
1000
281
164002
16.4002
17.13
20000
0.12
MULTISET_INTERSECT_ALL_DIST
4
10000
10000
47
20028
2.0028
23.47
20000
1
MULTISET_INTERSECT_DISTINCT
1
10
10
0
26
2.6
0
20
0.77
MULTISET_INTERSECT_DISTINCT
2
100
100
0
214
2.14
0
200
0.93
MULTISET_INTERSECT_DISTINCT
3
1000
1000
5
2020
2.02
24.75
2000
0.99
MULTISET_INTERSECT_DISTINCT
4
10000
10000
46
20028
2.0028
22.97
20000
1
MULTISET_INTERSECT_DISTINCT_DIST
1
10000
10
105
57968
5.7968
18.11
60000
1.04
MULTISET_INTERSECT_DISTINCT_DIST
2
10000
100
201
116242
11.6242
17.29
40000
0.34
MULTISET_INTERSECT_DISTINCT_DIST
3
10000
1000
280
164002
16.4002
17.07
20000
0.12
MULTISET_INTERSECT_DISTINCT_DIST
4
10000
10000
46
20028
2.0028
22.97
20000
1

Test Code


-- At first run Test Code in precedent Blog: "Performance of Oracle Object Collection Comparisons - Part1"
-- (http://ksun-oracle.blogspot.ch/2016/01/performance-of-oracle-object-collection_13.html)

------------------------------- COLLECT_test ---------------------------------
create or replace procedure collect_test (p_name varchar2, p_size number default 1000, p_dist_val pls_integer := null) as
 l_dist_val  number := coalesce(p_dist_val, p_size);
 l_test_name   varchar2(40);
  l_tobj_tab_1  tobj_tab := tobj_tab();
  l_start_time  number;
  l_elapsed     number;
begin
 helper.p_num1_cnt := 0;
 l_start_time := dbms_utility.get_time;
 
 if p_name in ('COLLECT_SORT', 'COLLECT_SORT_DIST') then
  select cast(collect(tobj(num1, num2) order by tobj(num1, num2) desc) as tobj_tab) into l_tobj_tab_1
    from (select level num1, mod(level, l_dist_val) num2 from dual connect by level <= p_size);
 else
  -- Workaround due to PL/SQL: ORA-30482: DISTINCT option not allowed for this function
  -- DISTINCT option works for SQL, but not for PL/SQL  
  execute immediate q'[
   select cast(collect(distinct tobj(num1, num2)) as tobj_tab)
     from (select level num1, mod(level, :p_dist_val) num2 from dual connect by level <= :p_size)]'
   into l_tobj_tab_1 using l_dist_val, p_size; 
 end if;
    
 l_elapsed := dbms_utility.get_time - l_start_time;
 helper.record(p_name, p_size, l_dist_val,
        l_elapsed, helper.p_num1_cnt, (helper.p_num1_cnt/p_size));
 helper.format(p_name||' count=', l_tobj_tab_1.count);
 helper.format('  Total Number of Object Comparisons=', helper.p_num1_cnt);   
end;
/    

--exec collect_test('COLLECT_SORT', 100, 100);
--exec collect_test('COLLECT_SORT_DIST', 100, 10);
--exec collect_test('COLLECT_DISTINCT', 100, 100);
--exec collect_test('COLLECT_DISTINCT_DIST', 100, 10);

create or replace procedure collect_test_run(p_run number) as
begin
 for i in 1..p_run loop collect_test('COLLECT_SORT', power(10, i), power(10, i)); end loop;
 for i in 1..p_run loop collect_test('COLLECT_SORT_DIST', power(10, p_run), power(10, i)); end loop;
 for i in 1..p_run loop collect_test('COLLECT_DISTINCT', power(10, i), power(10, i)); end loop;
 for i in 1..p_run loop collect_test('COLLECT_DISTINCT_DIST', power(10, p_run), power(10, i)); end loop; 
end;
/ 

--exec collect_test_run(3);

------------------------------- MULTISET_test ---------------------------------
create or replace procedure multiset_test (p_name varchar2, p_size number default 1000, p_dist_val pls_integer := null) as
 l_dist_val  number := coalesce(p_dist_val, p_size);
 l_test_name   varchar2(40);
  l_tobj_tab_1  tobj_tab := tobj_tab();
  l_tobj_tab_2 tobj_tab := tobj_tab();
  l_tobj_tab_3 tobj_tab := tobj_tab();
  l_start_time  number;
  l_elapsed     number;
begin
 select cast(multiset(select level, mod(level, l_dist_val) from dual connect by level <= p_size) as tobj_tab) 
  into l_tobj_tab_1 from dual;
 select cast(multiset(select level, mod(level, l_dist_val) from dual connect by level <= p_size) as tobj_tab) 
   into l_tobj_tab_2 from dual;
 
  helper.p_num1_cnt := 0;
  l_start_time := dbms_utility.get_time;
  
  case 
  when p_name in ('MULTISET_UNION_ALL', 'MULTISET_UNION_ALL_DIST') then 
     l_tobj_tab_3 := l_tobj_tab_1 MULTISET UNION ALL l_tobj_tab_2;
  when p_name in ('MULTISET_UNION_DISTINCT', 'MULTISET_UNION_DISTINCT_DIST') then 
     l_tobj_tab_3 := l_tobj_tab_1 MULTISET UNION DISTINCT l_tobj_tab_2;
  when p_name in ('MULTISET_EXCEPT_ALL', 'MULTISET_EXCEPT_ALL_DIST') then 
       l_tobj_tab_3 := l_tobj_tab_1 MULTISET EXCEPT ALL l_tobj_tab_2;
  when p_name in ('MULTISET_EXCEPT_DISTINCT', 'MULTISET_EXCEPT_DISTINCT_DIST') then 
       l_tobj_tab_3 := l_tobj_tab_1 MULTISET EXCEPT DISTINCT l_tobj_tab_2;
  when p_name in ('MULTISET_INTERSECT_ALL', 'MULTISET_INTERSECT_ALL_DIST') then 
       l_tobj_tab_3 := l_tobj_tab_1 MULTISET INTERSECT ALL l_tobj_tab_2;
  when p_name in ('MULTISET_INTERSECT_DISTINCT', 'MULTISET_INTERSECT_DISTINCT_DIST') then 
       l_tobj_tab_3 := l_tobj_tab_1 MULTISET INTERSECT DISTINCT l_tobj_tab_2;
 end case;
 
 l_elapsed := dbms_utility.get_time - l_start_time;
 helper.record(p_name, p_size, l_dist_val,
        l_elapsed, helper.p_num1_cnt, (helper.p_num1_cnt/p_size/2));
 helper.format(p_name||' count=', l_tobj_tab_3.count);  
 helper.format('  Total Number of Object Comparisons=', helper.p_num1_cnt);  
end;
/ 

--exec multiset_test('MULTISET_UNION_ALL', 100, 100);
--exec multiset_test('MULTISET_UNION_DISTINCT', 100, 100);
--exec multiset_test('MULTISET_UNION_DISTINCT_DIST', 100, 10);
--exec multiset_test('MULTISET_EXCEPT_ALL', 100, 100);
--exec multiset_test('MULTISET_EXCEPT_DISTINCT', 100, 100);
--exec multiset_test('MULTISET_INTERSECT_ALL', 100, 100);
--exec multiset_test('MULTISET_INTERSECT_DISTINCT', 100, 100);
--exec multiset_test('MULTISET_INTERSECT_DISTINCT_DIST', 100, 100);

create or replace procedure multiset_test_run(p_run number) as
begin
 for i in 1..p_run loop collect_test('MULTISET_UNION_ALL',    power(10, i),     power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_UNION_ALL_DIST', power(10, p_run), power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_UNION_DISTINCT',      power(10, i),     power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_UNION_DISTINCT_DIST', power(10, p_run), power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_EXCEPT_ALL',      power(10, i),     power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_EXCEPT_ALL_DIST', power(10, p_run), power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_EXCEPT_DISTINCT',      power(10, i),     power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_EXCEPT_DISTINCT_DIST', power(10, p_run), power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_INTERSECT_ALL',      power(10, i),     power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_INTERSECT_ALL_DIST', power(10, p_run), power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_INTERSECT_DISTINCT',      power(10, i),     power(10, i)); end loop;
 for i in 1..p_run loop collect_test('MULTISET_INTERSECT_DISTINCT_DIST', power(10, p_run), power(10, i)); end loop;
end;
/ 

--exec multiset_test_run(3);

------------------------------- Test Control 2 ---------------------------------
create or replace procedure all_test_run_2(p_run number) as
begin
 collect_test_run(p_run);
 multiset_test_run(p_run);
end;
/