Issue #1137: ArrayIndexOutOfBoundException

Hello,

we got this exception when using ObjectDB:

[2013-05-27 06:01:43 #38 *]
java.lang.ArrayIndexOutOfBoundsException: -102141
                at com.objectdb.o.PGC.w(PGC.java:212)
                at com.objectdb.o.SNP.F(SNP.java:421)
                at com.objectdb.o.MST.aT(MST.java:475)
                at com.objectdb.o.MST.aS(MST.java:434)
                at com.objectdb.o.MST.U3(MST.java:407)
                at com.objectdb.o.WRA.U3(WRA.java:249)
                at com.objectdb.o.LDR.F(LDR.java:532)
                at com.objectdb.o.LDR.E(LDR.java:466)
                at com.objectdb.o.LDR.z(LDR.java:268)
                at com.objectdb.o.OBC.aO(OBC.java:1081)
                at com.objectdb.o.OBC.aM(OBC.java:999)
                at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
                at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
                at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
                at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
                at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
                at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
                at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
                at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2123)
                at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1431)
                at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
                at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-05-27 16:27:57 #39 store]
Database 'C:\SafeQORS\server\cache\MainORSCache.odb' is closed by 6912@QA12-S017

Thanks for support.

Marta

The stack trace indicates an unexpected exception due to an attempt to locate  a page with a negative ID in the cache, where page IDs are never expected to be negative.

Please provide the following information:

• Can you reproduce this specific exception?
• Please check the database with the ObjectDB Doctor. Are there any errors?
• What is the size of the database?
• What is the size of the page cache, as specified in the configuration.
• Can you identify specific circumstances in which this happens?

• We are not able to reproduce the problem.
• Result from ObjectDB Doctor check is attached.
• The size of the database is cca 42 MB
• Configuration is default:

<processing cache="64mb" max-threads="10" />
<query-cache results="32mb" programs="500" />

• The problem occurs once after several hours of running.

The Database Doctor output indicates that the database is healthy, except references from CacheableJobStat instances to deleted CacheableJobLog instances. This requires fixing the application (making sure that references to deleted objects are removed to avoid broken references), but it doesn't seem to be related to the reported exception.

We are currently checking this problem, and apparently it looks related to the other issues that you reported today (issue #1142 andissue #1143). Unfortunately without the ability to see the problem in action, it wouldn't be easy to find and fix it. If you can share your test so we will be able to get the exceptions in our development environment it could be very helpful.

Since these exceptions may be related to the cache, please check if changing the cache size affects.

If it is related to the "processing cache", increasing it to 256mb may result in getting these exception less often, and on the other hand, decreasing it to 8mb may result in getting these exception more often. The cache cannot be disabled completely.

You may also try running ObjectDB with the following configuration:

    <processing cache="64mb" max-threads="10" synchronized="true" />

When synchronized is enabled, all operations against the database engine are synchronized and executed one after the other. Whether or not this solves the problem, could provide some clue in understanding the problem.

But as noted above, if you can share your test so we will be able to get the exceptions in our development environment, it could be the fastest route to solution.

Any new information regarding this issue?

Hello,

we are not successfull to simulate the problem in test till now, it occurs during our stress systems tests, where many threads are running concurently and usually after some hours of running.

We would like to avoid using synchronized="true" due to performance reason.

I am going to run the stress tests with recommended settings to see if it affects the problem and let you know.

Is there any other way how can we help to solve the issue (debug...)?

Thanks

Marta

Assuming all the exceptions are in invocations of EntityManager's find method (as seen in your reports), you may try wrapping it with your own method that will retry find several times if it fails. If necessary, add a delay between successive find attempts.

This may serve as a temporary workaround if it works.

It may also indicate that the problem is related to concurrent use of the cache.

To help solving the problem, would you be able to provide us your tests (binary only, no need for source code) and instructions how to run them? If we can see the exception in our debugging environment, we may be able to understand and fix the issue.

Hello,

we have another fresh portions of exceptions from our stress test, unfortunately the problem occurs random and we have not get the exact scenario to simulate.

There is log from ObjectDB:

java.lang.ArrayIndexOutOfBoundsException: 49
at com.objectdb.o.UTY.aI(UTY.java:1390)
at com.objectdb.o.UTY.readStrictly(UTY.java:1369)
at com.objectdb.o.TYR.aE(TYR.java:608)
at com.objectdb.o.TYR.completeRead(TYR.java:318)
at com.objectdb.o.TYR.readElement(TYR.java:294)
at com.objectdb.o.UTY.readAndAdjust(UTY.java:1403)
at com.objectdb.o.UMR.readAndAdjust(UMR.java:653)
at eu.ysoft.safeq.core.cache.entity.CacheableJobLog.__odbReadContent(CacheableJobLog.java:1)
at com.objectdb.o.MMM.ag(MMM.java:1064)
at com.objectdb.o.UTY.aH(UTY.java:1301)
at com.objectdb.o.UTY.aG(UTY.java:1273)
at com.objectdb.o.ENH.b(ENH.java:102)
at com.objectdb.o.LDR.J(LDR.java:796)
at com.objectdb.o.LDR.UW(LDR.java:1023)
at com.objectdb.o.MST.aU(MST.java:508)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)


and later after new start:


[2013-06-06 21:01:40 #71 *]
java.lang.ArrayIndexOutOfBoundsException: -102141
at com.objectdb.o.PGC.w(PGC.java:211)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.MST.aU(MST.java:475)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-06 21:01:40 #72 *]
java.lang.ArrayIndexOutOfBoundsException: -102141
at com.objectdb.o.PGC.w(PGC.java:211)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.MST.aU(MST.java:475)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-06 21:02:12 #73 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:24:17 #74 load]
[ObjectDB 2.5.0_06] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) Server VM 1.6.0_30 (on Windows Server 2008 R2 6.1).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: Unexpected request java.lang.Object:10000000000871755
com.objectdb.o.InternalException: Unexpected request java.lang.Object:10000000000871755
at com.objectdb.o.LDR.UW(LDR.java:991)
at com.objectdb.o.MST.aU(MST.java:508)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-06 21:24:17 #75 load]
Request set: {eu.ysoft.safeq.core.cache.entity.CacheableJobLog#10000000000871755(including subtypes), lockMode=-1}

[2013-06-06 21:26:46 #76 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #77 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #78 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #79 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #80 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #81 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #82 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #83 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #84 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #85 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #86 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #87 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #88 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #89 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #90 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #91 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #92 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #93 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-06 21:27:25 #94 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-07 02:38:22 #95 *]
java.lang.ArrayIndexOutOfBoundsException: 63
at com.objectdb.o.UTY.aG(UTY.java:1275)
at com.objectdb.o.ENH.b(ENH.java:102)
at com.objectdb.o.LDR.J(LDR.java:796)
at com.objectdb.o.LDR.UW(LDR.java:1023)
at com.objectdb.o.MST.aU(MST.java:508)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-07 03:05:40 #96 load]
[ObjectDB 2.5.0_06] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) Server VM 1.6.0_30 (on Windows Server 2008 R2 6.1).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: Unexpected request java.lang.Object:10000000001280296
com.objectdb.o.InternalException: Unexpected request java.lang.Object:10000000001280296
at com.objectdb.o.LDR.UW(LDR.java:991)
at com.objectdb.o.MST.aU(MST.java:508)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-07 03:05:40 #97 load]
Request set: {eu.ysoft.safeq.core.cache.entity.CacheableJobLog#10000000001280296(including subtypes), lockMode=-1}

[2013-06-07 03:18:52 #98 *]
java.lang.ArrayIndexOutOfBoundsException: 10
at com.objectdb.o.PAG.ar(PAG.java:957)
at com.objectdb.o.PAG.aq(PAG.java:928)
at com.objectdb.o.MST.aU(MST.java:469)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-07 04:58:36 #99 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-07 05:37:47 #100 load]
[ObjectDB 2.5.0_06] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) Server VM 1.6.0_30 (on Windows Server 2008 R2 6.1).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: Unexpected request eu.ysoft.safeq.core.cache.entity.CacheableJobLog:10000000000135233
com.objectdb.o.InternalException: Unexpected request eu.ysoft.safeq.core.cache.entity.CacheableJobLog:10000000000135233
at com.objectdb.o.LDR.UW(LDR.java:991)
at com.objectdb.o.MST.aU(MST.java:508)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:518)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-07 05:37:47 #101 load]
Request set: {eu.ysoft.safeq.core.cache.entity.CacheableJobStat#10000000000135233(including subtypes), lockMode=-1}

[2013-06-07 05:42:31 #102 *]
[ObjectDB 2.5.0_06] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) Server VM 1.6.0_30 (on Windows Server 2008 R2 6.1).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: null
com.objectdb.o.InternalException
at com.objectdb.o.InternalException.f(InternalException.java:236)
at com.objectdb.o.TYR.completeRead(TYR.java:584)
at com.objectdb.o.TYR.readElement(TYR.java:294)
at com.objectdb.o.UTY.readAndAdjust(UTY.java:1403)
at com.objectdb.o.UMR.readAndAdjust(UMR.java:653)
at eu.ysoft.safeq.core.cache.entity.CacheableJobStat.__odbReadContent(CacheableJobStat.java:1)
at com.objectdb.o.MMM.ag(MMM.java:1064)
at com.objectdb.o.UTY.aH(UTY.java:1301)
at com.objectdb.o.UTY.aG(UTY.java:1273)
at com.objectdb.o.ENH.b(ENH.java:102)
at com.objectdb.o.LDR.J(LDR.java:796)
at com.objectdb.o.LDR.UW(LDR.java:1023)
at com.objectdb.o.MST.aU(MST.java:508)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:518)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-07 08:34:38 #103 *]
java.lang.ArrayIndexOutOfBoundsException


We found similar problems in more logs:


java.lang.ArrayIndexOutOfBoundsException: -102141
at com.objectdb.o.PGC.w(PGC.java:211)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.MST.aU(MST.java:475)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-05 17:53:46 #6 *]
java.lang.ArrayIndexOutOfBoundsException: -102141
at com.objectdb.o.PGC.w(PGC.java:211)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.MST.aU(MST.java:475)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-05 17:53:46 #7 *]
java.lang.ArrayIndexOutOfBoundsException: -102141
at com.objectdb.o.PGC.w(PGC.java:211)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.MST.aU(MST.java:475)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-05 17:53:46 #8 *]
java.lang.ArrayIndexOutOfBoundsException: -102141
at com.objectdb.o.PGC.w(PGC.java:211)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.MST.aU(MST.java:475)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-05 17:53:46 #9 *]
java.lang.ArrayIndexOutOfBoundsException: -102141
at com.objectdb.o.PGC.w(PGC.java:211)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.MST.aU(MST.java:475)
at com.objectdb.o.MST.aT(MST.java:434)
at com.objectdb.o.MST.U3(MST.java:407)
at com.objectdb.o.WRA.U3(WRA.java:251)
at com.objectdb.o.LDR.F(LDR.java:532)
at com.objectdb.o.LDR.E(LDR.java:466)
at com.objectdb.o.LDR.z(LDR.java:268)
at com.objectdb.o.OBC.aO(OBC.java:1052)
at com.objectdb.o.OBC.aM(OBC.java:970)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:361)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:356)
at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:347)
at eu.ysoft.safeq.ors.CacheDBWrapper.delete(CacheDBWrapper.java:73)
at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:512)
at ysoft.sqpro.queue.PrintQueue.deleteJobOnSafe(PrintQueue.java:2124)
at ysoft.sqpro.queue.PrintQueue.processJob(PrintQueue.java:1432)
at ysoft.sqpro.queue.SecuredPrintQue.singleDeviceQue(SecuredPrintQue.java:499)
at ysoft.sqpro.queue.SecuredPrintQue.run(SecuredPrintQue.java:350)

[2013-06-05 18:00:29 #10 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:06:51 #11 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:06:51 #12 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:06:52 #13 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:06:52 #14 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:06:52 #15 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:06:53 #16 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:07:12 #17 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:08:02 #18 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:08:28 #19 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:09:58 #20 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:10:59 #21 *]
java.lang.ArrayIndexOutOfBoundsException

[2013-06-05 18:10:59 #22 *]
java.lang.ArrayIndexOutOfBoundsException

As you can see the problem occurs very randomly as the stress tests test one user scenario again and again in many threads parallel.

We will further testing the same scenario with configuration you recommend us.

Regards

Marta

During the weekend we ran intensive tests of concurrent persist/find/remove/update operations, but unfortunately we couldn't reproduce these exceptions.

Probably there is something in your tests that is different and causes the exception. Maybe if you provide more information about the test and the relevant entity classes, it could help.

The exceptions are thrown during find. Which entity classes are involved? CacheableJobStat? CacheableJobLog? Could you describe their schema, and particularly the primary key in use?

The relevant activity in your test is deleteInOpenTransaction. Could you describe what it does? What is the state of the database and the transaction when find is invoked, do you have an open transaction? Are there flushed but non committed changes to the database?

Any further details that you can share may help.

Hello,

I finally found the cause of these exception. We have following entity:

@Entity
public final class CacheableJobStat {   

@OneToOne(fetch = FetchType.EAGER)
private CacheableJobInfo ji;  

@OneToOne(fetch = FetchType.EAGER)
private CacheableJobLog jl;

}

Where CacheableJobInfo and CacheableJoLog are also entities without no reference to another entity. These entities are not persist in cascade, but explicitly by calling persist.

The problem dissapeared when removing the @OneToOne(fetch = FetchType.EAGER) annotation.

I am not sure wheather this annotation is allowed when not cascade persist is used?

The exception occurs when trying to delete:

beginTransaction();

find and delete CacheableJobInfo;

find and delete CacheableJobLog; << find causes exception under load

find and delete CacheableJobStat; << find causes exception under load

commitTransaction();

I have already done some test when changing the processing cache size, but the exceptions seems occuring at the same rate.

We have removed the annotation and the exceptions seems not occuring anymore.

Marta

Thank you for the update and good to hear that you found a workaround.

These annotations are allowed and exceptions should not be thrown, so we will try to use this new information to reproduce the exceptions with our tests.

Hello,

we are again facing the issue with EOF exception:

Failed to read from file 'C:\SafeQORS\server\cache\MainORSCache.odb' (error 117)
                at com.objectdb.jpa.EMImpl.find(EMImpl.java:596)
                at com.objectdb.jpa.EMImpl.find(EMImpl.java:514)
                at com.ysoft.cache.objectdb.ObjectCacheDB.deleteInOpenTransaction(ObjectCacheDB.java:396)
                at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:391)
                at com.ysoft.cache.objectdb.ObjectCacheDB.delete(ObjectCacheDB.java:379)
                at ysoft.sqcore.job.CacheJobManager.jobExtinction(CacheJobManager.java:520)
                at ysoft.sqpro.spooler.AbstractSpoolCleanerManager.doDeleteJobs(AbstractSpoolCleanerManager.java:64)
                at ysoft.sqpro.spooler.CacheSpoolCleanerManager.prepareFilesToDelete(CacheSpoolCleanerManager.java:162)
                at ysoft.sqpro.spooler.SpoolCleaner.checkJobs(SpoolCleaner.java:226)
                at ysoft.sqpro.spooler.SpoolCleaner.run(SpoolCleaner.java:81)
Caused by: com.objectdb.o.UserException: Failed to read from file 'C:\SafeQORS\server\cache\MainORSCache.odb'
                at com.objectdb.o.MSG.d(MSG.java:74)
                at com.objectdb.o.LFL.U(LFL.java:1077)
                at com.objectdb.o.PAG.an(PAG.java:841)
                at com.objectdb.o.PGC.w(PGC.java:238)
                at com.objectdb.o.SNP.F(SNP.java:421)
                at com.objectdb.o.MST.aU(MST.java:475)
                at com.objectdb.o.MST.aT(MST.java:434)
                at com.objectdb.o.MST.U3(MST.java:407)
                at com.objectdb.o.WRA.U3(WRA.java:251)
                at com.objectdb.o.LDR.F(LDR.java:532)
                at com.objectdb.o.LDR.E(LDR.java:466)
                at com.objectdb.o.LDR.z(LDR.java:268)
                at com.objectdb.o.OBC.aO(OBC.java:1052)
                at com.objectdb.o.OBC.aM(OBC.java:970)
                at com.objectdb.jpa.EMImpl.find(EMImpl.java:591)
                ... 9 more
Caused by: java.io.EOFException
                at java.io.RandomAccessFile.readFully(Unknown Source)
                at com.objectdb.o.LFL.U(LFL.java:1072)
                ... 22 more

The deleteInOpenTransaction deletes several entities in batch.

Is this again some concurrency issue?

I was inspecting the code and meanwhile one thread was deleting several entities of this type (in batch), second thread persists new entity of this type.

Thanks

We couldn't reproduce this problem yet, and haven't got similar reports from other users, so this is still an unclear open issue. Possibly your workaround at #12 reduced the concurrency load, but the problem was still there.

Please verify again that the database is healthy by running the Doctor.

If you can isolate these operations into a self standing test that reproduces the issue, or even provide a close test case, i.e. an application that we can run (possibly large, and with no source code), I hope we will be able to solve it.

Alternatively we may try to understand better when this happens, and at least suggest a working workaround. Please provide more information about the two involved threads (the deleted and the finder). Are they use the same EntityManagerFactory? the same EntityManager? Any other relevant details?