Hello,
I have been debugging a problem (for way too long) which has been exhibiting itself by intermittently throwing an OptimisticLockException. After this exception is thrown once, it is no longer possible to save the associated object back to the database. I have an "Optimistic Lock Handler" which: sleeps for a short random amount of time, re-fetches the object, makes the appropriate changes again and attempts to store the newly fetched object. Once I hit one of these "bad" OptimisticLockException's the handler (and later phases of the program) are never able to store a newly selected copy of the object, I just continue to get more OptimisticLockException's on every store attempt. This handler works fine in situations where I encounter a "good" OptimisticLockException (one where the store succeeds on the second attempt). It can be very time consuming to reproduce this problem in my development environment taking many thousands of stores to trigger a "bad" OptimisticLockException.
I finally got around to inserting p6spy into the project and created a detailed trace of the SQL which was flowing between OJB and the Oracle driver. This trace revealed a peculiarity in the "update ... where ..." statement which was sent to the database right before the "bad" OptimisticLockException was thrown. Basically the Timestamp value in the where clause was wrong; the milliseconds portion was not the value which was set in the previous update statement (which is the same as the database value). Every attempted fetch & store of this object after this had a different (seemingly random) Timestamp milliseconds value in the where clause, while the rest of the Timestamp was always the same. A possibly interesting point, the milliseconds value of the Timestamp in the database was 0. Stripped down "pseudo-sql" of what I am seeing in the p6spy trace file looks like this:
success: update set ... lastModified = '2004-06-22 14:38:05.0' where ...
exception: update set ... where ... lastModified = '2004-06-22 14:38:05.928'
exception: update set ... where ... lastModified = '2004-06-22 14:38:05.41'
exception: update set ... where ... lastModified = '2004-06-22 14:38:05.273'
exception: update set ... where ... lastModified = '2004-06-22 14:38:05.453'
exception: update set ... where ... lastModified = '2004-06-22 14:38:05.08'
Based on the above information it appears as if something involved with the materialization of the Timestamp value from the database may have a failure condition in the 0 milliseconds scenario.
This application is significantly multi-threaded with database work happening on multiple concurrent threads. Hardware is significantly multiprocessor (16-way on the development box). The core software environment is:
Java 1.4.2_03 Solaris Oracle 9i using OCI driver OJB 1.0rc4 JBoss 3.0.7
I experimented with OJB 1.0rc6 & JBoss 3.2.3 several weeks ago and appeared to have the same problem. I have not tried this combination with p6spy yet.
I have created a simple standalone multi-threaded test application outside of the application server, but I have not been able to reproduce the problem.
Does anyone have any suggestions on how to track down where the Timestamp value is being materialized incorrectly? My p6spy configuration skills are not particularly good, so I was not able to log the resultset which was being returned from the database driver.
Hope the message is not too incoherent, it is getting a bit late here...
Thanks in advance for any debugging suggestions.
Mike
--------------------------------------------------------------------- To unsubscribe, e-mail: [EMAIL PROTECTED] For additional commands, e-mail: [EMAIL PROTECTED]
