Problem / Context
Today, I worked on a performance issue at my customer. The context is a Java app which did a processing and at the end of this processing, the application inserts tons of data on an Oracle database.
The customers was complaining about slow performance on the insertion phase and asked me to have a look on it.
Database was IO Bound, and many sessions were doing some one-row inserts on various tables (INSERT INTO … VALUES (:1, :2, …) ). These one-row insert were off course processed many times, and oracle session’s stats was reporting a high number of executions.
On the Java side
As an Oracle DBA or Developer, we all know that, with PLSQL, it’s easy to write a FORALL loop that will bulk insert the data, and then reduce execution time. To do that, you need to have a cursor which is read in bulkl (BULK COLLECT) and each part is then inserted in the database. This reduces the number of operations, loops etc.
DECLARE
CURSOR s_cur IS
SELECT *
FROM servers;
TYPE fetch_array IS TABLE OF s_cur%ROWTYPE;
s_array fetch_array;
BEGIN
OPEN s_cur;
LOOP
FETCH s_cur BULK COLLECT INTO s_array LIMIT 1000;
FORALL i IN 1..s_array.COUNT
INSERT INTO servers2 VALUES s_array(i);
EXIT WHEN s_cur%NOTFOUND;
END LOOP;
CLOSE s_cur;
COMMIT;
END;
/
Source: http://psoug.org/snippet/FORALL-Insert_499.htm
In Java, the problem can be different because the data processed by your app are not necesseraly coming from a database.
Usually, statements are prepared, variables are attached and the statement is executed. When it’s done in a loop, it looks something like that:
try{
DriverManager.registerDriver (new oracle.jdbc.driver.OracleDriver());
Connection c = DriverManager.getConnection ("jdbc:oracle:thin:@192.168.99.8:1521:orcl","laurent","laurent");
PreparedStatement stmt = c.prepareStatement("insert into emp(employee_id,first_name,last_name,salary) values (?,?,?,?)");
start=System.currentTimeMillis();
for (int i=0 ; i < 50000 ; i++) {
stmt.setInt(1,i);
stmt.setString(2,generateRandomChars("01234567890ABCDEF",16));
stmt.setString(3,generateRandomChars("01234567890ABCDEF",16));
stmt.setInt(4,r.nextInt(10000+1)+5000);
stmt.executeUpdate();
}
stop=System.currentTimeMillis();
System.out.println("time = "+(stop-start));
stmt.close();
c.close();
}
catch(Exception e){
System.err.println(e);
e.printStackTrace();
}
The problem is the statement is sent to the database 50000 times, and then increase number of operation between the database and the application. As a result, execution time is high (this demo has been executed on a VM on my laptop):
[oracle@oel6 JAVA]$ time java -cp $CLASSPATH:ojdbc7.jar:. TestNoBatchedInsert
time = 75430
real 1m16.514s
user 0m5.279s
sys 0m1.080s
As for PLSQL, there is a technique to write a beautiful and powerful java code that will process inserts by batchs, and then reduce the number of loops, calls between database and application etc.
To do that, instead of using executeStatement method X times, we can use the addBatch method that will create a “batch” which will be executed on the database when PreparedStatement’s method “executeBatch” will be called.
If you’re familiar with FORALL in PLSQL, you probably know that, the more the batchsize is big, the more memory you will use. In Java, it will be the same and the result will be a bigger heap size, that’s why it’s recommended to define a batch size and each time your batch will reach a max size, the batch will be executed. This can be done like this:
try{
DriverManager.registerDriver (new oracle.jdbc.driver.OracleDriver());
Connection c = DriverManager.getConnection ("jdbc:oracle:thin:@192.168.99.8:1521:orcl","laurent","laurent");
PreparedStatement stmt = c.prepareStatement("insert into emp(employee_id,first_name,last_name,salary) values (?,?,?,?)");
start=System.currentTimeMillis();
int batchSize=5000;
int count=0;
for (int i=0 ; i < 50000 ; i++) {
stmt.setInt(1,i);
stmt.setString(2,generateRandomChars("01234567890ABCDEF",16));
stmt.setString(3,generateRandomChars("01234567890ABCDEF",16));
stmt.setInt(4,r.nextInt(10000+1)+5000);
stmt.addBatch();
if (++count % batchSize == 0) {
stmt.executeBatch();
}
}
stop=System.currentTimeMillis();
System.out.println("time = "+(stop-start));
stmt.close();
c.close();
}
catch(Exception e){
System.err.println(e);
e.printStackTrace();
}
Now, if I run this program, wall time is not really the same scale:
[oracle@oel6 JAVA]$ time java -cp $CLASSPATH:ojdbc7.jar:. TestBatchedInsert
time = 598
real 0m1.964s
user 0m3.393s
sys 0m0.269s
On the database side
AWR Reports show many things:
- First, if we run the java sample codes as they are described, the no batch mode will commit the database after each execute update. As a result, log file switch event will increase:
Non batched inserts:
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Total Wait Wait % DB Wait
Event Waits Time (sec) Avg(ms) time Class
------------------------------ ----------- ---------- ---------- ------ --------
log file sync 49,999 64 1.28 86.8 Commit
DB CPU 9.3 12.6
db file sequential read 47 0 0.97 .1 User I/O
SQL*Net message to client 50,012 0 0.00 .1 Network
log file switch completion 1 0 27.60 .0 Configur
undo segment extension 2 0 5.16 .0 Configur
direct path write 3 0 1.08 .0 User I/O
direct path sync 1 0 3.15 .0 User I/O
Disk file operations I/O 19 0 0.04 .0 User I/O
control file sequential read 194 0 0.00 .0 System I
Batched inserts:
Top 10 Foreground Events by Total Wait Time
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
Total Wait Wait % DB Wait
Event Waits Time (sec) Avg(ms) time Class
------------------------------ ----------- ---------- ---------- ------ --------
DB CPU .3 72.9
SQL*Net more data from client 268 0 0.17 10.1 Network
log file sync 13 0 3.29 9.5 Commit
db file sequential read 49 0 0.37 4.0 User I/O
Disk file operations I/O 17 0 0.03 .1 User I/O
control file sequential read 134 0 0.00 .1 System I
SQL*Net more data to client 10 0 0.02 .1 Network
SQL*Net message to client 22 0 0.00 .0 Network
log file single write 0 0 .0 System I
asynch descriptor resize 0 0 .0 Other
- Then, due to batched process, number of buffer gets is reduced when batched inserts are used
Non batched inserts:
Segments by Logical Reads DB/Inst: ORCL/orcl Snaps: 200-201
-> Total Logical Reads: 212,288
-> Captured Segments account for 28.4% of Total
-> When ** MISSING ** occurs, some of the object attributes may not be available
Tablespace
Owner Name
-------------------- ----------
Subobject Obj. Logical
Object Name Name Type Obj# Dataobj# Reads %Total
-------------------- ---------- ----- ---------- ---------- ------------ -------
LAURENT USERS
EMP TABLE 93857 93860 52,576 24.77
Batched inserts:
Segments by Logical Reads DB/Inst: ORCL/orcl Snaps: 201-202
-> Total Logical Reads: 11,792
-> Captured Segments account for 83.0% of Total
-> When ** MISSING ** occurs, some of the object attributes may not be available
Tablespace
Owner Name
-------------------- ----------
Subobject Obj. Logical
Object Name Name Type Obj# Dataobj# Reads %Total
-------------------- ---------- ----- ---------- ---------- ------------ -------
LAURENT USERS
EMP TABLE 93857 93860 3,504 29.72
- Same for buffer gets. Execution number is less for batched inserts (number of execution depends on your batch size)
Non batched inserts:
Buffer Gets Elapsed
Gets Executions per Exec %Total Time (s) %CPU %IO SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
152,587 50,000 3.1 71.9 2.1 11.3 0 7c9ws5uvx9nyc
Module: JDBC Thin Client
insert into emp(employee_id,first_name,last_name,salary) values (:1 ,:2 ,:3 ,:4
)
Batched inserts:
Buffer Gets Elapsed
Gets Executions per Exec %Total Time (s) %CPU %IO SQL Id
----------- ----------- ------------ ------ ---------- ----- ----- -------------
3,669 10 366.9 31.1 0.1 57 0 7c9ws5uvx9nyc
Module: JDBC Thin Client
insert into emp(employee_id,first_name,last_name,salary) values (:1 ,:2 ,:3 ,:4)
When developer have to insert tons on data from a java app, it’s better when they used the best way to do it …. batched inserts have to be used in that case, it will help the database to be more powerful.
That’s it for today 😉
Data ... as usual 