Performance Degradation on CallableStatement

Question

I have a stored procedure in Oracle 11g that I'm calling from a Java program using the Oracle thin database driver and a CallableStatement. This stored procedure is invoked thousands of times in a loop on the same connection.

The callableStatement.execute() call returns in < 200ms for the first 10-20 calls, however, performance starts to degrade over time. After 200 calls, callableStatement.execute() is now taking 600ms, and continues to degrade.

If I close the connection periodically, execute times return to the normal < 200ms range. Clearly something is being cached incorrectly in the JDBC connection, although the documentation states that CallableStatements are not cached.

Running the same stored procedure using the Oracle OCI driver in a C program shows no performance degradation, and continuously returns in < 200ms.

Has anyone noticed this behavior or have any thoughts on a workaround for Java?

Edit: This is the section of code that is run numerous times; Connection is shared, CallableStatement is created each loop. No improvement if CallableStatement is cached.

   oracle_conn_time = System.currentTimeMillis();
   OracleConnection oracle_conn = (OracleConnection) conn.getMetaData().getConnection();
   oracle_conn.setStatementCacheSize(1);
   oracle_conn_time = System.currentTimeMillis() - oracle_conn_time;

   list_time = System.currentTimeMillis();
   var_args= oracle_conn.createARRAY("ARG_LIST", args.toArray());
   list_time = System.currentTimeMillis() - list_time;

   sql       = "{? = call perform_work(?,?,?,?)}";

prepare_time = System.currentTimeMillis();
ocs = (OracleCallableStatement) oracle_conn.prepareCall(sql);
prepare_time = System.currentTimeMillis() - prepare_time;

bind_time = System.currentTimeMillis();
    ocs.registerOutParameter(1, OracleTypes.ARRAY, "RESPONSEOBJ");

    ocs.setInt(  2, 77);
    ocs.setInt(  3, 123456);
    ocs.setArray(4, var_args);
    ocs.setInt(  5, 123456789);
    bind_time = System.currentTimeMillis() - bind_time;

//execute_time is the only timer that shows degradation
execute_time = System.currentTimeMillis();
    ocs.execute();
execute_time = System.currentTimeMillis() - execute_time;

results_time = System.currentTimeMillis();
    Array return_objs = ocs.getArray(1);
results_time = System.currentTimeMillis() - results_time;

oracle_time = System.currentTimeMillis() - oracle_time;
    parse_time = System.currentTimeMillis();

    Clob[] clobs = (Clob[]) return_objs.getArray();

    return_objs.free();

//Removed clob management code

parse_time = System.currentTimeMillis() - parse_time;

Answer 1

When the stored proc returned an Array of Clobs, the code was only directly free'ing the Array, and not the underlying Clob objects as well.

Adding a call to free on the Clob object eliminated the performance degradation.

I assume that when the Clob object is garbage collected, free is intrinsically called in finalize, but I suspect that the Oracle Connection object holds a reference to any Clob objects used, thus keeping it from being garbage collected. Silly miss on my part, but hopefully this will help someone from getting tripped up in the future.

Array return_objs = ocs.getArray(1);

Clob[] clobs = (Clob[]) return_objs.getArray();

return_objs.free();

for(int i = 0; i < clobs.length; i++ )
{
    //Utilize clob

    clobs[i].free();
}