Frederick Tang Weblog

In my last post, I have setup in Java different insert methods to a database. In this post, I will post what I found in the Oracle trace files / tkprof output and the different response times:

1. Multiple Inserts using java.sql.Statement
2. Multiple Inserts using java.sql.PreparedStatement, using Bind Variables
3. Multiple Inserts using java.sql.Statement, with addBatch() & executeBatch()
4. Multiple Inserts using java.sql.PreparedStatement, using Bind Variables with addBatch() & executeBatch()

For the impatient readers, the response times when I execute my Java code with each insert method is as follows:

Please do not place too much judgments on these timings, they may be affected by the network latency, CPU spikes at the time of testing. However, this study is intended to show the relative amount of work and time spent for each INSERT method.

#1. Multiple Inserts using java.sql.Statement

Oracle trace file / tkprof output:

INSERT INTO insert_test (str)
values
 (:"SYS_B_0")

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     1000      0.09       0.08          0          0          0           0
Execute   1000      0.31       0.23          2       1006       3065        1000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     2000      0.40       0.32          2       1006       3065        1000

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         2        0.00          0.00
  SQL*Net message to client                    1002        0.00          0.00
  SQL*Net message from client                  1002        0.04          8.17
********************************************************************************

* The parse count is 1000, and execute count is also 1000 – a 1:1 ratio.
* Some CPU resources were used to parse the statement, and consumed 9ms of CPU time.
* Times waited is 1002 – (my guess) – 1000 for executeUpdate(); 1 for stmt.close(); 1 for commit?
* Oracle waited 8.17s for Java client to issue 1002 calls, one by one.

#2. Multiple Inserts using java.sql.PreparedStatement, using Bind Variables

Oracle trace file / tkprof output:

INSERT INTO insert_test (str)
values
 (:1)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute   1000      0.16       0.18          3          7       1065        1000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     1001      0.16       0.18          3          7       1065        1000

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         3        0.00          0.00
  SQL*Net message to client                    1002        0.00          0.00
  SQL*Net message from client                  1002        0.06          8.52
********************************************************************************

* Parse to Execute is a 1:1000 ratio. Almost negligible CPU resource and time spent on parsing.
* Oracle waited 8.52s for Java client to issue 1002 calls, one by one.

#3. Multiple Inserts using java.sql.Statement, with addBatch() & executeBatch()

Oracle trace file / tkprof output:

INSERT INTO insert_test (str)
values
 (:"SYS_B_0")

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     1000      0.09       0.08          0          0          0           0
Execute   1000      0.31       0.23          2       1006       3065        1000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total     2000      0.40       0.32          2       1006       3065        1000

Misses in library cache during parse: 1
Optimizer goal: CHOOSE
Parsing user id: 23  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                         2        0.00          0.00
  SQL*Net message to client                    1002        0.00          0.00
  SQL*Net message from client                  1002        0.04          8.17

* The statistics are similar to Method #1: Multiple Inserts using java.sql.Statement.
* This is because Oracle9i does not support batch updating with java.sql.Statement:

The Oracle implementation of standard update batching does not implement true batching for generic statements and callable statements. Although Oracle JDBC supports the use of standard batching syntax for Statement and CallableStatement objects, you will see performance improvement for only PreparedStatement objects. [source]

#4. Multiple Inserts using java.sql.PreparedStatement, using Bind Variables with addBatch() & executeBatch()

Oracle trace file / tkprof output:

INSERT INTO insert_test (str)
values
 (:1)

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.02       0.04          0         27         89        1000
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.02       0.04          0         27         89        1000

Misses in library cache during parse: 0
Optimizer goal: CHOOSE
Parsing user id: 23  

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net more data from client                  12        0.01          0.03
  SQL*Net message to client                       3        0.00          0.00
  SQL*Net message from client                     3        0.00          0.02

* The response time is 0.16secs.
* A (soft) parse of the SQL statement is made, with 1 execute to insert 1000 rows.
* 1 execute saves more time than the 1000 executes in previous methods.
* Communication between the Java client and Oracle is reduced to a minimum, as shown by 3 SQL*Net message from client.
* The 1000 bind values are sent in bulk using SQL*Net more data from client.

This week, I decided to do some simple exercises in Java to test the performance of different Oracle database table insert methods, and observe how much work the database do for each method. Part 1 of this post will demonstrate my Setup, and the Java code I used for each Insert method. Part 2 will show a detailed analysis of the tkprof output, the response times.

1. Multiple Inserts using java.sql.Statement
2. Multiple Inserts using java.sql.PreparedStatement, using Bind Variables
3. Multiple Inserts using java.sql.Statement, with addBatch() & executeBatch()
4. Multiple Inserts using java.sql.PreparedStatement, using Bind Variables with addBatch() & executeBatch()

Test Environment:

* WinXP laptop; JDK1.3; Oracle9i 9.2.0.8 database with (cursor_sharing=similar); Oracle JDBC Thin Driver.

Please note all the statistics and timing shown in this blog will vary with different environment (e.g. performance of my laptop, JDK version, network speed and database configuration… etc.), do not treat the figures produced here as benchmarks. The Java code provided here are my test codes, and may contain unidentified faults, please use at your own risks.

Test Method:

* Create a simple table in my database,

SQL> create table insert_test (str varchar2(100));

Table created.

* Use Java to instantiate a String array of 1000 random strings (not very pretty I know),

String[] randStrings = new String[1000];
for(i = 0; i < randStrings.length; i++) {
   randStrings[i] = “token” + Math.random();
}

* Trigger a Oracle trace using Java, the trace file generated can be found in $ORACLE_BASE/admin/$ORACLE_SID/udump directory on the database server. Trace files can get hugh very quickly, do not keep a trace running for a long duration. It is best used under the supervision of a DBA.

Statement strace = conn.createStatement();
try {
   strace.executeUpdate(“ALTER SESSION SET EVENTS ‘10046 trace name context forever, level 12′”);
   strace.executeUpdate(“ALTER SESSION SET STATISTICS_LEVEL=all”);
} catch (SQLException t1) {
   t1.printStackTrace();
} finally {
   strace.close();
}

* Use each insert method to insert these strings into the table,

* Measure response times using java.lang.System.currentTimeMillis();

* Analyze Oracle trace files using tkprof.

Multiple Inserts using java.sql.Statement

   try {
     long start_ts = System.currentTimeMillis();
     Statement stmt = conn.createStatement();
     for (int i = 0; i < randStrings.length; i++) {
        stmt.executeUpdate(“INSERT INTO insert_test (str) values (‘”+randStrings[i]+”‘)”);
     }
     conn.commit();
     long end_ts = System.currentTimeMillis();
     long sw = end_ts – start_ts;
     System.out.println((double)sw/1000 + “secs”);
  } catch (SQLException e) {
     System.out.println(e.getMessage());
  } finally {
     stmt.close();
  }

Multiple Inserts using java.sql.PreparedStatement, using Bind Variables

  PreparedStatement stmt = conn.prepareStatement(“INSERT INTO insert_test (str) values (?)”);
  try {
     long start_ts = System.currentTimeMillis();
     for (int i = 0; i < randStrings.length; i++) {
        stmt.setString(1, randStrings[i]);
        stmt.executeUpdate();
     }
     conn.commit();
     long end_ts = System.currentTimeMillis();
     long sw = end_ts – start_ts;
     System.out.println((double)sw/1000 + “secs”);
  } catch (SQLException e) {
     System.out.println(e.getMessage());
  } finally {
     stmt.close();
  }

Multiple Inserts using java.sql.Statement, with addBatch() & executeBatch()

    try {
     long start_ts = System.currentTimeMillis();
     Statement stmt = conn.createStatement();
     for (int i = 0; i < randStrings.length; i++) {
        stmt.addBatch(“INSERT INTO insert_test (str) values (‘”+randStrings[i]+”‘)”);
     }
     stmt.executeBatch();
     conn.commit();
     long end_ts = System.currentTimeMillis();
     long sw = end_ts – start_ts;
     System.out.println((double)sw/1000 + “secs”);
  } catch (SQLException e) {
     System.out.println(e.getMessage());
  } finally {
     stmt.close();
  }

Multiple Inserts using java.sql.PreparedStatement, using Bind Variables with addBatch() & executeBatch()

    PreparedStatement stmt = conn.prepareStatement(“INSERT INTO insert_test (str) values (?)”);
  try {
     long start_ts = System.currentTimeMillis();
     for (int i = 0; i < randStrings.length; i++) {
        stmt.setString(1, randStrings[i]);
        stmt.addBatch();
     }
     stmt.executeBatch();
     conn.commit();
     long end_ts = System.currentTimeMillis();
     long sw = end_ts – start_ts;
     System.out.println((double)sw/1000 + “secs”);
  } catch (SQLException e) {
     System.out.println(e.getMessage());
  } finally {
     stmt.close();
  }

Results will be documented in Part 2.

Found an interesting Oracle9i bug today, and it is easily reproduced (I am using 9.2.0.8 below). The bug is fixed in 10g (> 10.1.0.2).

SQL> create table timestamp_test (ts timestamp(5));

Table created.

SQL> desc timestamp_test;
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 TS                                                 TIMESTAMP(5)

SQL> drop database link dblink_to_self;

Database link dropped.

SQL> create database link dblink_to_self
  2     connect to fredt identified by fredt
  3     using 'FOOMDB';

Database link created.

SQL> create table timestamp_test_ctas
  2  as
  3  select * from timestamp_test@dblink_to_self;

Table created.

SQL> desc timestamp_test_ctas;
 Name                                      Null?    Type
 ----------------------------------------- -------- ----------------------------
 TS                                                 TIMESTAMP(5)

SQL> select table_name, data_type from user_tab_cols
  2  where table_name like 'TIMESTAMP%';

TABLE_NAME                     DATA_TYPE
------------------------------ ---------------
TIMESTAMP_TEST                 TIMESTAMP(5)
TIMESTAMP_TEST_CTAS            TIMESTAMP(0)

See Metalink Bug 2417643 for further reference.