Exception on creation when running multithreaded

#1

Hi,

I'm trying to test the creation of an object from my datamodel(Organisation) and the creation process includes the creation of an acl for the newly created organisation all in the same transaction.

The process is as followed:

1. The organisation gets created

2. The acl is being searched to check if it already exists

3. if it exists it will be updated, otherwise it will be created

 

Everything works fine when running with one thread, however, when adding a second thread some the of the creations fail with the following exception:

 

[ObjectDB 2.2.8_07] javax.persistence.PersistenceException
Failed to read from file 'C:\Dev\contextspace\cs_services\trunk\objectdb\db\contextspace.odb' (error 117)
at com.objectdb.jpa.JpaQuery.getResultList(JpaQuery.java:633)
at com.contextspace.acl.JpaBasicLookupStrategy.lookupObjectIdentities(JpaBasicLookupStrategy.java:166)
at com.contextspace.acl.JpaBasicLookupStrategy.readAclsById(JpaBasicLookupStrategy.java:110)
at com.contextspace.acl.JpaAclService.readAclsById(JpaAclService.java:109)
at com.contextspace.acl.JpaAclService.readAclById(JpaAclService.java:88)
at com.contextspace.acl.JpaAclService.readAclById(JpaAclService.java:79)
at com.contextspace.acl.JpaMutableAclService.createAcl(JpaMutableAclService.java:115)
at com.contextspace.services.impl.SecurityHelper.addPermission(SecurityHelper.java:149)
at com.contextspace.services.impl.SecurityHelper.addPermission(SecurityHelper.java:120)
at com.contextspace.services.impl.OrganisationService.add(OrganisationService.java:71)
at com.contextspace.services.impl.OrganisationService.add(OrganisationService.java:1)
at sun.reflect.GeneratedMethodAccessor42.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:309)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:110)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.security.access.intercept.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:67)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
at $Proxy27.add(Unknown Source)
at com.contextspace.services.OrganisationMultiThreadedPerfTest$BasicThread.run(OrganisationMultiThreadedPerfTest.java:103)
Caused by: com.objectdb.o.UserException: Failed to read from file 'C:\Dev\contextspace\cs_services\trunk\objectdb\db\contextspace.odb'
at com.objectdb.o.MSG.d(MSG.java:74)
at com.objectdb.o.LFL.T(LFL.java:1059)
at com.objectdb.o.PAG.al(PAG.java:806)
at com.objectdb.o.PGC.w(PGC.java:235)
at com.objectdb.o.SNP.B(SNP.java:342)
at com.objectdb.o.OBI.v(OBI.java:430)
at com.objectdb.o.OBI.s(OBI.java:339)
at com.objectdb.o.OBI.r(OBI.java:266)
at com.objectdb.o.OBI.U6(OBI.java:232)
at com.objectdb.o.BQI.Vf(BQI.java:140)
at com.objectdb.o.PRG.ad(PRG.java:698)
at com.objectdb.o.PRG.ab(PRG.java:627)
at com.objectdb.o.QRM.US(QRM.java:259)
at com.objectdb.o.MST.US(MST.java:884)
at com.objectdb.o.WRA.US(WRA.java:286)
at com.objectdb.o.WSM.US(WSM.java:113)
at com.objectdb.o.QRR.g(QRR.java:225)
at com.objectdb.o.QRR.b(QRR.java:144)
at com.objectdb.jpa.JpaQuery.getResultList(JpaQuery.java:627)
... 23 more
Caused by: java.io.EOFException
at java.io.RandomAccessFile.readFully(RandomAccessFile.java:383)
at com.objectdb.o.LFL.T(LFL.java:1056)
... 40 more

 

The exception is being thrown during step 2.

 

Any ideas regarding what may be the cause for this exception? I could understand a concurrency issue when persisting but during a lookup doesn't make a lot of sense.

 

Thanks,

Eitan

#2

If your queries are executed on flushed changes that have not been committed yet - this may indicate an ObjectDB bug in transaction isolation or cache management.

Anyway, a test case that reproduces the problem would be very helpful.

ObjectDB Support
#3

Yes, the query was executed on flushed changes and I also had:

typedQuery.setFlushMode(FlushModeType.AUTO);

for the specific query.

 

If I change the logic and don't query before creation everything is happpy.

I'll try to create a test project with the specific bits.

The Acls part is an Objectdb(JPA) implementation for the spring security domain acls and we intend to release it as opensource at some stage.

 

Cheers,

Eitan

#4

Well, I tried to create a test project to reproduce the error but couldn't.

 

In the meantime, I've continued on by removing the code that queries for the newly created object and now I've encountered an even more random behavior.

 

The test is as follows:

 

I'm creating my objects using a multithreaded unit test whith 8 threads each creating 100 objects. The objects that gets created are of type CDI and in addition, as a setup for the test I'm creating another 3 objects of type PDI.

 

both PDI and CDI extends the same superclass and are very similar with some minor differences. Now after the CDIs creation I'm running a count query and it returns 800 as expected, then I run the following query "select $1 from CDI $1" and I get back 803 objects including the 3 PDI objects. This behavior only seems to happened when I use 8+ threads and 100+ objects created per thread.

 

Now to make it a bit more interesting, I also have an class called Organisation which is also extending the same class as CDI and PDI with some minor additions. In the same test that fail I then create 800 organisations using the 8*100 again and then running "select $1 from Organisation $1" actually returns 800 as expected. 

Now if I remove the initial test of the CDIs, meaning after the 3 PDIs I create the 800 Organisations I do a count on Organisations and get 800 and then I do "select $1 from Organisation $1" and get the 803.

 

That's very strange behavior and I'm assuming it has something to do with something being cached or not cleaned up after the creation.

 

I can't reproduce it on my test project yet which is a lot less complex than the one I'm testing on but in the meanwhile, here is the output for both the CDI and Organisation queries from objectdb trace:

 

for the CDI I can see 3 queries:

[2011-08-09 01:51:47 #37 query.compiler]
<finalPlans>
    <fatchPlan plan="fetch(index(-101[all]))" eval="5.1439" var="1" prm="0" reg="0">
        <btreePlan plan="index(-101[all])" eval="3.8429" var="1" prm="0" reg="0" variable="$1" />
    </fatchPlan>
    <btreePlan plan="type(CDI[all])" eval="5.2275" var="1" prm="1" reg="0" variable="$1" />
</finalPlans>

[2011-08-09 01:51:47 #38 query.compiler]
<finalPlans>
    <filterPlan plan="filter(extract($$owner,type(Relationship[all])),($$owner.party=:1))" eval="3.4426" var="1" prm="1" reg="1" filter="($$owner.party=:1)">
        <extractPlan plan="extract($$owner,type(Relationship[all]))" eval="3.4214" var="1" prm="1" reg="1" variable="$$owner">
            <btreePlan plan="type(Relationship[all])" eval="3.4214" var="1" prm="1" reg="0" variable="$$owner" />
        </extractPlan>
    </filterPlan>
    <fatchPlan plan="fetch(index(-107[pos<1>:1->:1:notNull]))" eval="4.3054" var="1" prm="0" reg="1">
        <btreePlan plan="index(-107[pos<1>:1->:1:notNull])" eval="3.0043" var="1" prm="0" reg="1" variable="$$owner" />
    </fatchPlan>
</finalPlans>

[2011-08-09 01:51:47 #39 query.compiler]
<finalPlans>
    <filterPlan plan="filter(extract($$owner,type(Relationship[all])),($$owner.otherParty=:1))" eval="3.4426" var="1" prm="1" reg="1" filter="($$owner.otherParty=:1)">
        <extractPlan plan="extract($$owner,type(Relationship[all]))" eval="3.4214" var="1" prm="1" reg="1" variable="$$owner">
            <btreePlan plan="type(Relationship[all])" eval="3.4214" var="1" prm="1" reg="0" variable="$$owner" />
        </extractPlan>
    </filterPlan>
    <fatchPlan plan="fetch(index(-106[pos<1>:1->:1:notNull]))" eval="4.3054" var="1" prm="0" reg="1">
        <btreePlan plan="index(-106[pos<1>:1->:1:notNull])" eval="3.0043" var="1" prm="0" reg="1" variable="$$owner" />
    </fatchPlan>
</finalPlans>

 

which returns 803 objects, then for the Organisations I can see only one query:

[2011-08-09 01:51:49 #69 query.compiler]
<finalPlans>
    <btreePlan plan="type(Organisation[all])" eval="5.1259" var="1" prm="1" reg="0" variable="$1" />
    <fatchPlan plan="fetch(index(-101[all]))" eval="5.5654" var="1" prm="0" reg="0">
        <btreePlan plan="index(-101[all])" eval="4.2643" var="1" prm="0" reg="0" variable="$1" />
    </fatchPlan>
</finalPlans>

I hope this can help isolate the problem.

 

Thanks,

Eitan

#5

Your report in #4 exposed a bug in query execution on a subclass when index of a super class is used by the query program. Version 2.2.9 fixes this bug. Thank you for this report.

ObjectDB Support
#6

Well, I'm getting a different behavior now but it is not working yet.

 

Now on the first query I'm getting back 0 objects, even though the count before it shows there are 800 objects and then the second query for the organisations returns 800 objects as expected.

 

#7

If you don't get 803 objects anymore it is a progress.

Can you post a test case that demonstrates the 0 count problem?

ObjectDB Support
#8

I can't post a test case but here are the plans that are used for both queries:

Persistence Class is of type com.contextspace.datamodel.party.CDI
[2011-08-12 02:51:23 #32 query.compiler]
<finalPlans>
    <fatchPlan plan="fetch(index(-101[all]))" eval="5.1439" var="1" prm="0" reg="0">
        <btreePlan plan="index(-101[all])" eval="3.8429" var="1" prm="0" reg="0" variable="t" />
    </fatchPlan>
    <btreePlan plan="type(CDI[all])" eval="5.1617" var="1" prm="1" reg="0" variable="t" />
</finalPlans>

Number Of objects for com.contextspace.datamodel.party.CDI is 0

 

Persistence Class is of type com.contextspace.datamodel.party.Organisation
[2011-08-12 02:51:24 #38 query.compiler]
<finalPlans>
    <btreePlan plan="type(Organisation[all])" eval="5.1955" var="1" prm="1" reg="0" variable="t" />
    <fatchPlan plan="fetch(index(-101[all]))" eval="5.5654" var="1" prm="0" reg="0">
        <btreePlan plan="index(-101[all])" eval="4.2643" var="1" prm="0" reg="0" variable="t" />
    </fatchPlan>
</finalPlans>

Number Of objects for com.contextspace.datamodel.party.Organisation is 800

 

I hope this helps.

Eitan

#9

Please try build 2.2.9_02 that includes an improved fix.

ObjectDB Support
#10

Looks like this version works.

Thanks,

Eitan

Reply