Wednesday, May 7, 2014

java stored procedure calls and latch: row cache objects

Frequent calls of java stored procedure by PL/SQL causes heavy latch: row cache objects.

(A previous Blog: dbms_aq.dequeue - latch: row cache objects on AIX  talked about dbms_aq.dequeue and latch: row cache objects)

As a concrete test example, appended code contains two different implementations of PL/SQL - Java interface when calling XML Pull Parser (XmlPullParser).
  1.  Case_1: for each TAG and text, make one java call.
  2.  Case_2: make one single java call for whole XML Document.
 
All tests are done on AIX Power7 System with Entitled Capacity 4, SMT=4 and Oracle 11.2.0.3.0.
It is also reproducible on Solaris Operating System (x86-64) with 16 virtual processors (2 8-Cores physical processors).

Case_1  32 Jobs


At first, run Case_1 for 10 minutes with 32 Jobs:
 
  exec xpp_test.run_job(p_case => 1, p_job_cnt => 32, p_dur_seconds => 600); 
 
and look the top 5 events in AWR report:
 

Top 5 Timed Foreground Events

EventWaitsTime(s)Avg wait (ms)% DB timeWait Class
DB CPU 2,410 6.70 
latch: row cache objects7,0261,3011853.62Concurrency
library cache: mutex X3,756111300.31Concurrency
log file sync321410.00Commit
control file sequential read3,700100.00System I/O

we can see a noticeable "latch: row cache objects" with average wait of 185 ms.

During the job running, pick the hex address of 'latch: row cache objects' by:

SQL> select p1raw from v$session v where p2=280 or event = 'latch: row cache objects';

    0X7000000B412F9F0

To look Oracle internal data structure, dump 16 bytes starting from this address by:

SQL> oradebug peek  0X7000000B412F9F0 16

   [7000000B412F9F0, 7000000B412FA10) = 00000000 00000026 2ED50834 01180000

where
    00000026 is Oracle PID (38 in hex) which is currently holding the latch.
    2ED50834 is v$latch.gets (785713204 in hex) where name='row cache objects'.
    0118     is v$latch.latch# (280 in hex).

If dumping address further, you can also find v$latch.misses, sleeps and other columns.

Case_1  16 Jobs


If reducing Jobs to 16,

 exec xpp_test.run_job(p_case => 1, p_job_cnt => 16, p_dur_seconds => 600);

AWR shows:

Top 5 Timed Foreground Events

EventWaitsTime(s)Avg wait (ms)% DB timeWait Class
DB CPU 2,385 14.19 
library cache: mutex X9,989100.01Concurrency
control file sequential read3,588100.00System I/O
db file sequential read839000.00User I/O
latch: row cache objects27020.00Concurrency


Case_2  32 Jobs


Then repeating the above two calls with Case_2:

 exec xpp_test.run_job(p_case => 2, p_job_cnt => 32, p_dur_seconds => 600);

Top 5 Timed Foreground Events

EventWaitsTime(s)Avg wait (ms)% DB timeWait Class
DB CPU 2,401 6.66 
log file sync402390.00Commit
control file sequential read3,700100.00System I/O
cursor: pin S wait on X201300.00Concurrency
SQL*Net break/reset to client54040.00Application


Case_2  16 Jobs


exec xpp_test.run_job(p_case => 2, p_job_cnt => 16, p_dur_seconds => 600);

Top 5 Timed Foreground Events

EventWaitsTime(s)Avg wait (ms)% DB timeWait Class
DB CPU 2,416 11.12 
log file sync885520.02Commit
latch: shared pool119780.00Concurrency
control file sequential read3,588100.00System I/O
library cache: mutex X169160.00Concurrency


We can hardly see any "latch: row cache objects" in other three AWR reports.


TestCode


create or replace type xpp_array_obj as object (
    evt_type    number(12)
   ,name        varchar2(32767)
   ,namespc     varchar2(4000)
   ,attr_cnt    number(12)
   ,text        varchar2(32767)
);
/

create or replace type xpp_array_tab as table of xpp_array_obj;
/

drop table test_stats;

create table test_stats (ts timestamp, case number, job_cnt number, dur number, run_cnt number, java_cnt number, java_nano number);

drop table rc_latch_stats;

create table rc_latch_stats as
select timestamp'2013-11-22 10:20:30' ts, 'start' step, 0 case, 0 job_cnt, v.*
from   v$latch v where 0=1 and name = 'row cache objects';

drop java source "XmlPullParserJava";

create or replace and resolve java source named "XmlPullParserJava" as
  import java.util.LinkedList;
  import java.util.Vector;
  import java.sql.Connection;
  import java.sql.Clob;
  import oracle.jdbc.driver.OracleDriver;
  import oracle.sql.ARRAY;
  import oracle.sql.ArrayDescriptor;
  import oracle.sql.STRUCT;
  import oracle.sql.StructDescriptor;
  import org.xmlpull.mxp1.MXParser;
  import org.xmlpull.v1.XmlPullParser;

public class XmlPullParserJava {
  private static XmlPullParser XPP = new MXParser();
  public static void setInput(Clob inputClob) {
    try {
      XPP.setInput(inputClob.getCharacterStream());
    } catch (Exception t) {
      System.out.println("\n Message: " + t.getMessage() + "\n Cause: " + t.getCause());
    }
  }
  public static int next(String[] name, String[] namespace, int[] attributeCount, String[] text, long[] elapsed) {
    try {
      long startTime    = System.nanoTime();
      int next          = XPP.next();
      name[0]           = XPP.getName();
      namespace[0]      = XPP.getNamespace();
      attributeCount[0] = XPP.getAttributeCount();
      text[0]           = XPP.getText();
      elapsed[0]        = System.nanoTime() - startTime;
      return next;
    } catch (Throwable t) {
      System.out.println("\n Message: " + t.getMessage() + "\n Cause: " + t.getCause());
      return -1;
    }
  }
  public static void nextAll(ARRAY retAllArray[], long[] elapsed) {
    try {
      Connection conn         = new OracleDriver().defaultConnection();
      ArrayDescriptor  aDescr = ArrayDescriptor.createDescriptor("XPP_ARRAY_TAB", conn);
      StructDescriptor sDescr = StructDescriptor.createDescriptor("XPP_ARRAY_OBJ", conn);
      String [] lineContent   = new String[5];
      STRUCT lineObj = null;
      Vector retAll  = new Vector();
      long startTime = System.nanoTime();
      String name;
      String nameSpace;
      int    attributeCount;
      String text;
      int eventType = XPP.next();
      while (eventType != XmlPullParser.END_DOCUMENT) {
        lineContent[0] = String.valueOf(eventType);
        lineContent[1] = XPP.getName();
        lineContent[2] = XPP.getNamespace();
        lineContent[3] = String.valueOf(XPP.getAttributeCount());
        lineContent[4] = XPP.getText();
        lineObj = new STRUCT(sDescr, conn, lineContent);
        retAll.add(lineObj);
        eventType = XPP.next();
      }
     elapsed[0] = System.nanoTime() - startTime;
     retAllArray[0] = new ARRAY(aDescr, conn, retAll.toArray());
    } catch (Throwable t) {
      System.out.println("\n Message: " + t.getMessage() + "\n Cause: " + t.getCause());
    }
  }
}
/

create or replace package k.xpp_test as
  type xpp_rec is record (
    evt_type   pls_integer
   ,name       varchar2(32767)
   ,namespc    varchar2(4000)
   ,attr_cnt   pls_integer := -1
   ,text       varchar2(32767)
   ,elapsed    pls_integer
  );
  v_xpp_rec        xpp_rec;
  v_xml_doc        varchar2(32767);
  v_java_call_nano number := 0;
  v_java_call_cnt  number := 0;
  ---------------------------------------------------------------------------
  function  xml_gen(p_limit number) return varchar2;
  procedure set_input(p_clob clob);
  function  next return integer;
  function  nextall return xpp_array_tab;
  procedure run_next;
  procedure run_nextall;
  procedure run_cnt(p_case number, p_job_cnt number, p_dur_seconds number);
  procedure run_job(p_case number, p_job_cnt number, p_dur_seconds number);
  procedure run_var(p_case number, p_job_var number, p_dur_seconds number);
end xpp_test;
/

create or replace package body k.xpp_test as
  procedure java_setInput(p_clob clob) as
  language java name 'XmlPullParserJava.setInput(java.sql.Clob)';
  function java_next(p_name out varchar2, p_namespc out varchar2, p_attr_cnt out number, p_text out varchar2, p_elapsed out number)
  return pls_integer as
  language java name 'XmlPullParserJava.next(java.lang.String[], java.lang.String[], int[], java.lang.String[], long[]) return int';
  procedure java_nextall(p_array out xpp_array_tab, p_elapsed out number) as
  language java name 'XmlPullParserJava.nextAll(oracle.sql.ARRAY[], long[])';
  ---------------------------------------------------------------------------
  function xml_gen(p_limit number) return varchar2 as
    l_level_1      varchar2(32767) := '';
    l_level_2      varchar2(32767) := '';
    l_level_3      varchar2(32767) := '';
    l_xml          varchar2(32767);
  begin
    for i in 1..p_limit loop
      l_level_1 := l_level_1||'<TAG_1_'||i||'>text_1_'||i||'</TAG_1_'||i||'>';
    end loop;
    for i in 1..p_limit loop
      l_level_2 := l_level_2||'<TAG_2_'||i||'>'||l_level_1||'</TAG_2_'||i||'>';
    end loop;
    for i in 1..p_limit loop
      l_level_3 := l_level_3||'<TAG_3_'||i||'>'||l_level_2||'</TAG_3_'||i||'>';
    end loop;
    l_xml := q'[<?xml version="1.0" encoding="UTF-8"?>]'||'<root>'||l_level_3||'</root>';
    return l_xml;
  end xml_gen;
  ----------------------------------------------------------------------------
  -- simulate XML processing
  procedure cpu_burning as
    l_cnt number := 10000;
    l_x   number := 0;
  begin
    for i in 1..l_cnt loop
      l_x := i;
    end loop;
  end cpu_burning;
  ----------------------------------------------------------------------------
  procedure set_input(p_clob clob) as
  begin
    java_setInput(p_clob);
  end set_input;
  ----------------------------------------------------------------------------
  function next return integer as
  begin
    return java_next(v_xpp_rec.name, v_xpp_rec.namespc, v_xpp_rec.attr_cnt, v_xpp_rec.text, v_xpp_rec.elapsed);
  end next;
  ---------------------------------------------------------------------------
  function nextall return xpp_array_tab as
    l_xpp_array_tab xpp_array_tab := new xpp_array_tab();
  begin
    java_nextall(l_xpp_array_tab, v_xpp_rec.elapsed);
    return l_xpp_array_tab;
  end nextall;
  ---------------------------------------------------------------------------
  procedure run_next as
    l_evt_type     pls_integer;
    l_name         varchar2(32767);
    l_text         varchar2(32767);
  begin
    set_input(v_xml_doc);
    l_evt_type := next;
    loop
      case l_evt_type
        when 0 then l_name := v_xpp_rec.name;
        when 1 then l_name := v_xpp_rec.name;
        when 2 then l_name := v_xpp_rec.name;
        when 3 then l_name := v_xpp_rec.name;
        when 4 then l_text := v_xpp_rec.text;
        else        null;
      end case;
      l_evt_type := next;
      cpu_burning;          -- generate high 'row cache objects'
      v_java_call_cnt  := v_java_call_cnt + 1;
      v_java_call_nano := v_java_call_nano + v_xpp_rec.elapsed;
      exit when l_evt_type = 1;   -- XPP END_DOCUMENT
    end loop;
  end run_next;
  ---------------------------------------------------------------------------
  procedure run_nextall as
    l_xpp_array_tab xpp_array_tab;
    l_name          varchar2(32767);
    l_text          varchar2(32767);   
  begin
    set_input(v_xml_doc);
    l_xpp_array_tab := nextall;
    v_java_call_cnt  := v_java_call_cnt + 1;
    v_java_call_nano := v_java_call_nano + v_xpp_rec.elapsed;
    for i in 1..l_xpp_array_tab.count loop
      case l_xpp_array_tab(i).evt_type
        when 0 then l_name := l_xpp_array_tab(i).name;
        when 1 then l_name := l_xpp_array_tab(i).name;
        when 2 then l_name := l_xpp_array_tab(i).name;
        when 3 then l_name := l_xpp_array_tab(i).name;
        when 4 then l_text := l_xpp_array_tab(i).text;
        else        null;
      end case;   
      cpu_burning;
    end loop;
  end run_nextall;
  ---------------------------------------------------------------------------
  procedure run_cnt(p_case number, p_job_cnt number, p_dur_seconds number)
  as
    l_cnt        number := 0;
    l_start_time number := dbms_utility.get_time;
  begin
    loop
      case p_case
        when 1 then run_next;
        when 2 then run_nextall;
        else        null;
      end case;
      l_cnt := l_cnt + 1;
      exit when (dbms_utility.get_time - l_start_time) > (p_dur_seconds * 100);
    end loop;
    insert into test_stats values(systimestamp, p_case, p_job_cnt, p_dur_seconds, l_cnt, v_java_call_cnt, v_java_call_nano);
    commit;
  end run_cnt;
  ----------------------------------------------------------------------------
  procedure run_job (p_case number, p_job_cnt number, p_dur_seconds number)
  as
    l_job_id pls_integer;
    l_stmt   varchar2(1000);
  begin
    insert into rc_latch_stats
    select systimestamp, 'start', p_case, p_job_cnt, v.*
    from   v$latch v
    where  name = 'row cache objects';
    commit;
    for i in 1.. p_job_cnt loop
      l_stmt := 'begin xpp_test.run_cnt(' || p_case        ||', '
                                          || p_job_cnt     ||', '
                                          || p_dur_seconds ||
                                        '); end;';
      dbms_output.put_line(l_stmt);
      dbms_job.submit(l_job_id, l_stmt);
    end loop;
    commit;
    dbms_lock.sleep(p_dur_seconds);
    insert into rc_latch_stats
    select systimestamp, 'end', p_case, p_job_cnt, v.*
    from   v$latch v
    where  name = 'row cache objects';
    commit;
    dbms_lock.sleep(5);
  end run_job;
  ----------------------------------------------------------------------------
  procedure run_var(p_case number, p_job_var number, p_dur_seconds number) as
  begin
    for job_cnt in 1..p_job_var loop
      run_job(p_case, job_cnt, p_dur_seconds);
    end loop;
  end run_var;
---------------------------------------------------------------------------
  begin
    v_xml_doc := xml_gen(6);   -- XML Doc with length=6681, Tag + Text = 734
end xpp_test;
/

Posted by at