Recently, I resolved a weird Spring JDBC problem related to stored procedure compilation on multi-threading environment.
On production server, we see SP error when server starts up as below:
2015-01-23 07:40:13,454 INFO [TokenStore] Failed to find access token for token bbd333e9-f02a-4b89-99a7-75929a99c4d4
org.springframework.jdbc.BadSqlGrammarException: CallableStatementCallback; bad SQL grammar [{call AUTH_PKG.GET_TOKEN(?, ?, ?, ?, )}, ?]; nested exception is java.sql.SQLException: ORA-06550: line 1, column 64:
PLS-00103: Encountered the symbol ")" when expecting one of the following:
It is very strange because the Spring generated SQL is wrongly formatted! When look at the log files for the bad and good starts of the server, I found the problem is the proc is not compiled properly when it is called when the server starts up.
Usually we put compile() method in the SP constructor to allow Spring to compile the proc before it is referred/executed. But we didn’t do that for the proc classes in this package. This will delay the proc compilation until its execution time. When it is done correctly, we should see this log:
2015-01-26 14:42:04,147 DEBUG () [RefreshToken] [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] SQL operation not compiled before execution - invoking compile
2015-01-26 14:42:04,148 DEBUG () [RefreshToken] [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] Compiled stored procedure. Call string is [{call AUTH_PKG.GET_TOKEN(?, ?, ?, ?, ?)}]
2015-01-26 14:42:04,148 DEBUG () [RefreshToken] [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] RdbmsOperation with SQL [AUTH_PKG.GET_TOKEN] compiled
But at times when we have trouble we don’t see the above. We see the proc execute time exception immediately without the “proc compiled” log line. Seems like Spring executed the proc before it was compiled.
Looking at Spring source code of StoredProcedure class, we found the “isCompiled()” method is not synchronized/thread safe. When the same proc being called by multiple threads, the proc compilation is messed up. This causes failure for all the future calls to the proc.
Because this proc is a frequent call when the server starts up, we always see trouble in this proc but not in the others. Also because weblogic will queue up the requests during server starts up, we always end up with multiple threads calling to the same proc when the class initialization is done.
The fix would be always put “compile()” statement in the SP class constructor to allow Spring initialize/compile it before it can be referred/used.
On production server, we see SP error when server starts up as below:
2015-01-23 07:40:13,454 INFO [TokenStore] Failed to find access token for token bbd333e9-f02a-4b89-99a7-75929a99c4d4
org.springframework.jdbc.BadSqlGrammarException: CallableStatementCallback; bad SQL grammar [{call AUTH_PKG.GET_TOKEN(?, ?, ?, ?, )}, ?]; nested exception is java.sql.SQLException: ORA-06550: line 1, column 64:
PLS-00103: Encountered the symbol ")" when expecting one of the following:
It is very strange because the Spring generated SQL is wrongly formatted! When look at the log files for the bad and good starts of the server, I found the problem is the proc is not compiled properly when it is called when the server starts up.
Usually we put compile() method in the SP constructor to allow Spring to compile the proc before it is referred/executed. But we didn’t do that for the proc classes in this package. This will delay the proc compilation until its execution time. When it is done correctly, we should see this log:
2015-01-26 14:42:04,147 DEBUG () [RefreshToken] [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] SQL operation not compiled before execution - invoking compile
2015-01-26 14:42:04,148 DEBUG () [RefreshToken] [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] Compiled stored procedure. Call string is [{call AUTH_PKG.GET_TOKEN(?, ?, ?, ?, ?)}]
2015-01-26 14:42:04,148 DEBUG () [RefreshToken] [[ACTIVE] ExecuteThread: '2' for queue: 'weblogic.kernel.Default (self-tuning)'] RdbmsOperation with SQL [AUTH_PKG.GET_TOKEN] compiled
But at times when we have trouble we don’t see the above. We see the proc execute time exception immediately without the “proc compiled” log line. Seems like Spring executed the proc before it was compiled.
Looking at Spring source code of StoredProcedure class, we found the “isCompiled()” method is not synchronized/thread safe. When the same proc being called by multiple threads, the proc compilation is messed up. This causes failure for all the future calls to the proc.
Because this proc is a frequent call when the server starts up, we always see trouble in this proc but not in the others. Also because weblogic will queue up the requests during server starts up, we always end up with multiple threads calling to the same proc when the class initialization is done.
The fix would be always put “compile()” statement in the SP class constructor to allow Spring initialize/compile it before it can be referred/used.