On Oracle: September 2024

Sunday, September 22, 2024

In this Blog, we will make 5 different scenario tests of Java Stored Procedure running in Oracle RDBMS embedded JVM, and collect their stats from Oracle V$SESS_TIME_MODEL and V$SYS_TIME_MODEL.

Note: Tested in Oracle 19.24 with single user session.

1. Test Run

We run 5 different Scenarios (see Blog appended Test Code), each for 100 seconds.


  set serveroutput on size 50000
  -- Enable java println output on Sqlplus Window
  exec dbms_java.set_output(50000);   

  exec TestOraJvmRun2_call(plsqlSleepSeconds=> 100);
  exec TestOraJvmRun2_call(plsqlRunSeconds=> 100);    
  exec TestOraJvmRun2_call(javaPlsqlMixRunSeconds=> 100);
  exec TestOraJvmRun2_call(javaSleepSeconds=> 100);
  exec TestOraJvmRun2_call(javaRunSeconds=> 100);

2. Test Output

2.1 plsqlSleepSeconds


SQL >  exec TestOraJvmRun2_call(plsqlSleepSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 100, plsqlRunSeconds = 0, javaPlsqlMixRunSeconds = 0, javaSleepSeconds = 0, javaRunSeconds = 0

====== 1 Start plsqlSleepSeconds  ========= at 16:09:06.699
====== 1   End plsqlSleepSeconds  ========= at 16:10:47.252

====== 2 Start plsqlRunSeconds  ========= at 16:10:47.252
====== 2   End plsqlRunSeconds  ========= at 16:10:47.253

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:10:47.253
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:10:47.253

====== 4 Start javaSleepSeconds  ========= at 16:10:47.255
====== 4   End javaSleepSeconds  ========= at 16:10:47.255

====== 5 Start javaRunSeconds  ========= at 16:10:47.255
====== 5   End javaRunSeconds  ========= at 16:10:47.255

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=1)               val
------------------------------------------------------------
DB time                                                 1.04
sql execute elapsed time                                1.03

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
background elapsed time                                 3.00
background cpu time                                     2.12
DB time                                                 1.04
sql execute elapsed time                                1.04

Elapsed: 00:01:41.23

2.2 plsqlRunSeconds


SQl >  exec TestOraJvmRun2_call(plsqlRunSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 0, plsqlRunSeconds = 100, javaPlsqlMixRunSeconds = 0, javaSleepSeconds = 0, javaRunSeconds = 0

====== 1 Start plsqlSleepSeconds  ========= at 16:10:47.457
====== 1   End plsqlSleepSeconds  ========= at 16:10:47.458

====== 2 Start plsqlRunSeconds  ========= at 16:10:47.458
====== 2   End plsqlRunSeconds  ========= at 16:12:27.515

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:12:27.516
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:12:27.516

====== 4 Start javaSleepSeconds  ========= at 16:12:27.516
====== 4   End javaSleepSeconds  ========= at 16:12:27.516

====== 5 Start javaRunSeconds  ========= at 16:12:27.516
====== 5   End javaRunSeconds  ========= at 16:12:27.516

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=2)               val
------------------------------------------------------------
DB time                                                99.81
sql execute elapsed time                               99.81
DB CPU                                                 99.38
PL/SQL execution elapsed time                          54.10

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
DB time                                                99.81
sql execute elapsed time                               99.81
DB CPU                                                 99.38
PL/SQL execution elapsed time                          54.10
background elapsed time                                50.32
background cpu time                                    18.25

Elapsed: 00:01:40.11

2.3 javaPlsqlMixRunSecond


SQL >  exec TestOraJvmRun2_call(javaPlsqlMixRunSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 0, plsqlRunSeconds = 0, javaPlsqlMixRunSeconds = 100, javaSleepSeconds = 0, javaRunSeconds = 0

====== 1 Start plsqlSleepSeconds  ========= at 16:12:27.578
====== 1   End plsqlSleepSeconds  ========= at 16:12:27.579

====== 2 Start plsqlRunSeconds  ========= at 16:12:27.579
====== 2   End plsqlRunSeconds  ========= at 16:12:27.579

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:12:27.579
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:14:07.698

====== 4 Start javaSleepSeconds  ========= at 16:14:07.698
====== 4   End javaSleepSeconds  ========= at 16:14:07.698

====== 5 Start javaRunSeconds  ========= at 16:14:07.698
====== 5   End javaRunSeconds  ========= at 16:14:07.698

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=3)               val
------------------------------------------------------------
DB time                                                99.75
sql execute elapsed time                               99.75
Java execution elapsed time                            52.99
DB CPU                                                 51.92
PL/SQL execution elapsed time                          19.07

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
DB time                                                99.74
sql execute elapsed time                               99.74
background elapsed time                                68.16
Java execution elapsed time                            52.99
DB CPU                                                 51.91
PL/SQL execution elapsed time                          19.07
background cpu time                                    16.64

Elapsed: 00:01:40.17

2.4 javaSleepSeconds


SQL > exec TestOraJvmRun2_call(javaSleepSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 0, plsqlRunSeconds = 0, javaPlsqlMixRunSeconds = 0, javaSleepSeconds = 100, javaRunSeconds = 0

====== 1 Start plsqlSleepSeconds  ========= at 16:14:07.757
====== 1   End plsqlSleepSeconds  ========= at 16:14:07.758

====== 2 Start plsqlRunSeconds  ========= at 16:14:07.758
====== 2   End plsqlRunSeconds  ========= at 16:14:07.758

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:14:07.758
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:14:07.758

====== 4 Start javaSleepSeconds  ========= at 16:14:07.758
====== 4   End javaSleepSeconds  ========= at 16:15:47.759

====== 5 Start javaRunSeconds  ========= at 16:15:47.759
====== 5   End javaRunSeconds  ========= at 16:15:47.759

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=4)               val
------------------------------------------------------------
sql execute elapsed time                              100.01
DB time                                               100.00
Java execution elapsed time                           100.00

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
DB time                                               100.01
sql execute elapsed time                              100.01
Java execution elapsed time                           100.00
background elapsed time                                 1.80
background cpu time                                     1.71

Elapsed: 00:01:40.05

2.5 javaRunSeconds


SQL > exec TestOraJvmRun2_call(javaRunSeconds=> 100);

***** TestOraJvmRun2: plsqlSleepSeconds = 0, plsqlRunSeconds = 0, javaPlsqlMixRunSeconds = 0, javaSleepSeconds = 0, javaRunSeconds = 100

====== 1 Start plsqlSleepSeconds  ========= at 16:15:47.819
====== 1   End plsqlSleepSeconds  ========= at 16:15:47.820

====== 2 Start plsqlRunSeconds  ========= at 16:15:47.820
====== 2   End plsqlRunSeconds  ========= at 16:15:47.820

====== 3 Start javaPlsqlMixRunSeconds  ========= at 16:15:47.820
====== 3   End javaPlsqlMixRunSeconds  ========= at 16:15:47.820

====== 4 Start javaSleepSeconds  ========= at 16:15:47.820
====== 4   End javaSleepSeconds  ========= at 16:15:47.820

====== 5 Start javaRunSeconds  ========= at 16:15:47.820
====== 5   End javaRunSeconds  ========= at 16:17:27.820

============================================================
SESS_TIME_MODEL-stat_name (Sid=374, Run=5)               val
------------------------------------------------------------
DB time                                               100.01
Java execution elapsed time                           100.01
sql execute elapsed time                              100.01
DB CPU                                                 99.56

============================================================
SYS_TIME_MODEL-stat_name                                 val
------------------------------------------------------------
sql execute elapsed time                              100.01
DB time                                               100.00
Java execution elapsed time                           100.00
DB CPU                                                 99.56
background elapsed time                                 3.74
background cpu time                                     2.17

Elapsed: 00:01:40.05

3. Test Code

3.1 Plsql Code


create table test_tab_1 as select 1 k, 1234 val from dual;

create or replace procedure plsql_run(p_run number := 1e3) as
  l_x          number;
begin
  for f in 1..p_run loop
    update test_tab_1 set val = mod (l_x, p_run/10);
    commit;
  end loop;
  
  for f in 1..p_run*100 loop
    l_x := mod (l_x, p_run) + sqrt (f);
  end loop;
end;
/

-- exec plsql_run(1e3);

create or replace procedure plsql_run_seconds(p_run_sec number := 30) as
  l_x          number;
  l_start_time number := dbms_utility.get_time;
begin
  --dbms_session.sleep(p_sleep_sec);
  
  while ((dbms_utility.get_time - l_start_time)/100 < p_run_sec) loop 
    plsql_run(1e3);
  end loop;
end;
/

-- exec plsql_run_seconds(3);

3.2 Java Stored Procedure


create or replace and compile java source named "TestOraJvmRun2" as
import java.io.*;
import java.sql.*;
import java.text.SimpleDateFormat;
import oracle.jdbc.OracleDriver;
public class TestOraJvmRun2
{
  public static String proc(String testName, int plsqlSleepSeconds, int plsqlRunSeconds, int javaPlsqlMixRunSeconds, int javaSleepSeconds, int javaRunSeconds) throws SQLException
  {
    String exceptMessage = "No Exception";
    String test_title = ("\n***** "+ testName + 
                                  ": plsqlSleepSeconds = "      + plsqlSleepSeconds +
                                  ", plsqlRunSeconds = "        + plsqlRunSeconds +
                                  ", javaPlsqlMixRunSeconds = " + javaPlsqlMixRunSeconds    + 
                                  ", javaSleepSeconds = "       + javaSleepSeconds  +
                                  ", javaRunSeconds = "         + javaRunSeconds);
    System.out.println(test_title);
    
    try {
      Connection connection = new OracleDriver().defaultConnection();
      CallableStatement cstmt;
      
      System.out.println("\n====== 1 Start plsqlSleepSeconds  ========= at " + java.time.LocalDateTime.now());
      cstmt = connection.prepareCall("begin dbms_session.sleep(?); end;");
      cstmt.setInt(1, plsqlSleepSeconds);
      cstmt.execute();
      cstmt.close();
      System.out.println("====== 1   End plsqlSleepSeconds  ========= at " + java.time.LocalDateTime.now());
      
      System.out.println("\n====== 2 Start plsqlRunSeconds  ========= at " + java.time.LocalDateTime.now());
      cstmt = connection.prepareCall("begin plsql_run_seconds(?); end;");
      cstmt.setInt(1, plsqlRunSeconds);
      cstmt.execute();
      cstmt.close();
      System.out.println("====== 2   End plsqlRunSeconds  ========= at " + java.time.LocalDateTime.now());
      
      System.out.println("\n====== 3 Start javaPlsqlMixRunSeconds  ========= at " + java.time.LocalDateTime.now());
      long sleepOneSecond = 1000*1000000L; // convert 1 second to nanoseconds
      long startTime;
      for (int i = 0; i < javaPlsqlMixRunSeconds; i++) {    // java loop calling plsql
          startTime = System.nanoTime();
          while ((System.nanoTime() - startTime) < sleepOneSecond) 
            {try {
                 cstmt = connection.prepareCall("begin plsql_run(1e1); end;");
                 Thread.sleep(1);
                 cstmt.execute();
                 cstmt.close();
                 } catch (Exception e) {
            	       exceptMessage = e.toString();
            	       //System.out.println(e);
                 }
            }
      }
      System.out.println("====== 3   End javaPlsqlMixRunSeconds  ========= at " + java.time.LocalDateTime.now());

      System.out.println("\n====== 4 Start javaSleepSeconds  ========= at " + java.time.LocalDateTime.now());
      {try {
            Thread.sleep(javaSleepSeconds*1000);
           } catch (Exception e) {
            	 exceptMessage = e.toString();
            	 //System.out.println(e);
           }
      }
      System.out.println("====== 4   End javaSleepSeconds  ========= at " + java.time.LocalDateTime.now());
      
      System.out.println("\n====== 5 Start javaRunSeconds  ========= at " + java.time.LocalDateTime.now());
      for (int i = 0; i < javaRunSeconds; i++) {
          startTime = System.nanoTime();
          while ((System.nanoTime() - startTime) < sleepOneSecond) 
            {}
      }
      System.out.println("====== 5   End javaRunSeconds  ========= at " + java.time.LocalDateTime.now());
    } catch (Exception e) {
      e.printStackTrace();
    }
    return test_title;
  }
}
/


create or replace function TestOraJvmRun2_proc(testName varchar2, plsqlSleepSeconds number, plsqlRunSeconds number, 
                                               javaPlsqlMixRunSeconds number, javaSleepSeconds number, javaRunSeconds number) 
return varchar2 as language java
name 'TestOraJvmRun2.proc(java.lang.String, int, int, int, int, int) return String';
/

3.3 Plsql Test Call


drop table test_run_tm_stat;

create table test_run_tm_stat as select 0 run, 0 seq, sysdate datetime, sid, stat_name, round(value/1e6, 2) val from  V$SESS_TIME_MODEL where 1=2; 

select * from test_run_tm_stat;

drop sequence TestOraJvmRun_seq;

create sequence TestOraJvmRun_seq;

create or replace procedure TestOraJvmRun2_call (testName VARCHAR2 :='TestOraJvmRun2', plsqlSleepSeconds number :=0, plsqlRunSeconds number :=0, 
                                                 javaPlsqlMixRunSeconds number :=0, javaSleepSeconds number :=0, javaRunSeconds number :=0) as
  l_run number := TestOraJvmRun_seq.nextval;
  l_sid number := sys_context('userenv','sid');
  l_wid number := 60;
  l_ret VARCHAR2(200);
begin
  insert into test_run_tm_stat 
    select l_run, 1, sysdate, sid, stat_name, round(value/1e6, 2) from V$SESS_TIME_MODEL where sid = l_sid order by value desc;
  insert into test_run_tm_stat 
    select l_run, 1, sysdate, -1, stat_name, round(value/1e6, 2) from V$SYS_TIME_MODEL;   -- sid = -1 for V$SYS_TIME_MODEL

  l_ret := TestOraJvmRun2_proc(testName, plsqlSleepSeconds, plsqlRunSeconds, javaPlsqlMixRunSeconds, javaSleepSeconds, javaRunSeconds);   -- sleep or run x seconds
  --dbms_output.put_line(l_ret);
  commit;
  
  insert into test_run_tm_stat 
    select l_run, 2, sysdate, sid, stat_name, round(value/1e6, 2) from V$SESS_TIME_MODEL where sid = l_sid order by value desc;
  insert into test_run_tm_stat 
    select l_run, 2, sysdate, -1, stat_name, round(value/1e6, 2) from V$SYS_TIME_MODEL;   -- sid = -1 for V$SYS_TIME_MODEL
  commit;

  dbms_output.put_line(chr(10)||rpad('=', l_wid, '='));
  dbms_output.put_line(rpad('SESS_TIME_MODEL-stat_name (Sid='||l_sid||', Run='||l_run||')', l_wid-10, ' ')||lpad('val', 10, ' '));
  dbms_output.put_line(rpad('-', l_wid, '-'));
  for c in 
    (select * from 
      (select run, seq, sid, stat_name, val-lag(val, 1) over(partition by stat_name order by run, seq) delta from test_run_tm_stat where run = l_run and sid > 0)
     where delta >= 1 and seq=2 order by delta desc, stat_name)
  loop
    dbms_output.put_line(rpad(c.stat_name, l_wid-10, ' ')||lpad(to_char(c.delta, '999.99'), 10, ' '));
  end loop;
  
  dbms_output.put_line(chr(10)||rpad('=', l_wid, '='));
  dbms_output.put_line(rpad('SYS_TIME_MODEL-stat_name', l_wid-10, ' ')||lpad('val', 10, ' '));
  dbms_output.put_line(rpad('-', l_wid, '-'));
  for c in 
    (select * from 
      (select run, seq, sid, stat_name, val-lag(val, 1) over(partition by stat_name order by run, seq) delta from test_run_tm_stat where run = l_run and sid = -1)
     where delta >= 1 and seq=2 order by delta desc, stat_name)
  loop
    dbms_output.put_line(rpad(c.stat_name, l_wid-10, ' ')||lpad(to_char(c.delta, '999.99'), 10, ' '));
  end loop;
end;
/

On Oracle