Friday, March 13, 2009

We recently found and resolved an issue at work that was sufficiently tricky I felt that notes should be shared for anyone else who runs into the problem.

Background

We are a Java shop using an AS/400 (iSeries V5R4) as our backend. That means we're using the jt400.jar for our JDBC driver.

The Problem

We recently encountered a problem where our database calls would start failing intermittently. The problem manifests under load. That is, when a few hundred JDBC calls are made, eventually they will start to "fail". This failure can take several forms, but most often appears as either an ArrayIndexOutOfBoundsException inside the jt400 driver code, or some other exception indicating the data passed to/returned from the AS/400 is malformed. Alternately, the call can succeed without an error, but the data is wrong. For example: - With the our login stored procedure, when it failed, it returned errors indicating the username couldn't be found. - With another stored procedure it threw SQLException: Descriptor index not valid. Debug logging indicated this was a wrapper exception around an ArrayIndexOutOfBoundsException - A simple INSERT call would eventually fail complaining that one of the integers being inserted was malformed even though all tracing indicated it was a valid integer. This behavior only appeared under a limited set of circumstances:
  • JDK 1.6 (1.6.0_12) - The problem never appeared with 1.5
  • Multiple prepared statements. The problem appeared was related to preparing statements repeatedly. I was able to work around the issue in one application by upgrading our version of iBATIS from 2.2 to 2.3. That release caches prepared statements. This doesn't solve the problem for another app due to the way that Spring and iBATIS interact that prevents iBATIS from caching statements.
  • JVM HotSpot optimization ON (-server). One of the things I learned in tracking this down is that the HotSpot VM is enabled by default in Solaris and disabled (-client) by default on PCs. This problem went away when we disabled HotSpot optimization.
The problem does not appear related to a particular version of the jt400.jar.


Solution

One solution is to disable HotSpot entirely. We didn't want to take this drastic step and lose the performance gains, so we figured out how to disable HotSpot optimization for a specific class. [1] Our method was to turn on -XX:+PrintCompilation to have the JVM tell us every time it optimized a class/method. Then, we looked for the most recent optimizations before a failure and told the JVM to exclude those. Exclusion can be done through a command line parameter, so we used the following to exclude commonExecuteBefore() method of AS400JDBCPreparedStatement. The option is:

-XX:CompileCommand=exclude,com/ibm/as400/access/AS400JDBCPreparedStatement,commonExecuteBefore




[1] The Print Compilation Flag and how to read it's output

8 comments:

-nic- said...

Thank you very much for publishing this article. We had the same problem! :)

Greetings from South Africa,
nic de sousa

snake007uk said...

I think you might have saved my sanity!!!

Luismi said...

Muchas gracias, nos has salvado la vida. Teníamos el mismo problema y no dábamos con la causa ¡¡¡ Hurra !!!

Wolfgang said...

You saved my day!! Many thanks for sharing this info!!

Greetings from Austria

Masashi said...

we had almost the same problem with yours.
but there is only one difference.
we use IBM Java 1.4.XX.
do you think our problem is the same cause?
if you have any information or solution about that, please tell me.
i think you can save our company. please help us.

from japan

KC Baltz said...

Masashi,

It's hard to say if the IBM JVM would have the same problem, but I would doubt it. The problem is caused by the Sun JVM optimizer, HotSpot, which I don't think the IBM JVM would have. That said, if the IBM JVM accepts the same command line arguments, you could try them and see if it solves your problem. If it has its own optimizer, you'll have to read the documentation to figure out how to exclude com.ibm.as400.access.AS400JDBCPreparedStatement.commonExecuteBefore() from optimization.

Masashi said...

thank you for your reply.
i'll try them.

thank you very much!

Anonymous said...

Thanks for the info.

Got the same problem with JRE 1.6.0_39 and MyBatis 3.1.1.

(and not with OpenJDK and IBM JRE)