Issue #1860: ODB IndexActivation NullPointerException

Hi,

We have created indexes on an existing database, which has 4.3 million objects. As soon we create first query, NullPointerException is thrown:

Exception in thread "ODB IndexActivation" java.lang.NullPointerException
at com.objectdb.o.IIX.g(IIX.java:69)
at com.objectdb.o.IIX.f(IIX.java:58)
at com.objectdb.o.IXS.i(IXS.java:96)
at com.objectdb.o.IIS.p(IIS.java:55)
at com.objectdb.o.IXM.Vc(IXM.java:438)
at com.objectdb.o.PBI.C(PBI.java:146)
at com.objectdb.o.PBI.q(PBI.java:115)
at com.objectdb.o.MBI.VC(MBI.java:83)
at com.objectdb.o.MST.Vn(MST.java:783)
at com.objectdb.o.IXM.D(IXM.java:363)
at com.objectdb.o.IXM.run(IXM.java:338)
at java.lang.Thread.run(Thread.java:745)
* Batch ended at 88

I've read that:
"Indexing large amount of data may take considerable processing time."

Do we have to wait until index activation is finished before we can start using the database or something else is causing the problem?

A new index is not being used until its building is completed it but meanwhile you should be able to use the database normally. The stack trace indicates an exception in the new index building rather than in executing a query, so apparently it is not related to the query that you ran but to the background index building, which is a new ObjectDB feature.

Build 2.6.7_07 includes an attempt to fix this exception. Please try it.

Since we switch from ObjectDB 2.6.8_08 to 2.6.9_07, we get sporadic problems if we connected to an existing Database and create an EntityManager.

1) sometimes the following System out:

* Batch ended at '2LG'
* Batch ended at '2LG'
* Batch ended at '2LG'
* Batch ended at '2LG'
* Batch ended at '2oq'
* Batch ended at '2LG'
* Batch ended at '2LG'
* Batch ended at '2oq'
* Batch ended at '2LG'

And the Application stopped working.

2)

* Batch ended at '2LG'
* Batch ended at '2oq'
* Batch ended at MAX
* Batch ended at '2LG'
* Batch ended at '2oq'
* Batch ended at '2LG'
* Batch ended at '2LG'
* Batch ended at '2oq'
* Batch ended at MAX

If MAX is the last, then it looks like that every thing is ok.

3) An Exception

Exception in thread "ODB IndexActivation" java.lang.NullPointerException
at com.objectdb.o.IXM.run(IXM.java:322)
at java.lang.Thread.run(Thread.java:745)
* Batch ended at '2LG'
* Batch ended at '2LG'

I used always the same existing Database and got sporadic one of the three problems.

The messages are related to rebuilding an index, e.g. when a new index is defined for an existing database. Indexes are built in the background starting version 2.6.6, and apparently the last related code change was in build 2.6.7_07.

It is unclear why the application stops working and how a NullPointerException is thrown.

If you use embedded mode please check if the connection time to the database affects. If the database is closed before building the index is completed then the work is discarded and another attempt is done next time. So maybe opening and closing the database for very short periods (in which index rebuilding cannot be completed) may be related.

To the unexpected messages: The writing to System.out is therefore expected.  -> OK

But we still need help to find a solution!

> If you use embedded mode

Yes, we use the database in embeddedMode.

> opening and closing the database for very short periods

Do you mean with opening and closing the creation of EntityManagerFactory or of EntityManager?

Is it possible to ask if the ODB IndexActivation are finished?

And you have no idea why we get a NullPointerException at com.objectdb.o.IXM.run(IXM.java:322)

Maybe we have a not correct handled schema change or any other hint?

Small update:

We think a workarround (but not usefull) is to create a entityManager - close it - and wait a few seconds, that the IndexActiovation thread can finish. Then it should work.

Our normal open database scenario:

1) Create EntityManager in thread A. This thread update the Metamodel, and then close the entityManager.

(UpdateMetamodel: call for each EntityClass:  entityManager.getMetamodel().entity(entityClass);  [http://www.objectdb.com/database/forum/597] )

2) Create anoter EntityManager in thread B. (ThreadA not finished)
 

AdditionalTests:

Also if we block thread B until thread A finished we get the problems.

So it seems to be a link between the Metamodel and the IndexActivation.

Thank you for the update. We will follow your scenario description and try to reproduce the problem and find a solution.

Additional Update:  Sometimes we get still the Nullpointer (IXM.java:322) and then it happens again that we run into a dead lock

Maybe the additional picures of the thread states can help:

Please try build 2.6.9_08 that should

• fix the NullPointerException.
• remove the printing to the standard output.

The index building is done in a separate thread that starts when the database is opened and runs until completion. The name of the thread in build 2.6.9_08 is "ODB-IndexActivation" (it was "ODB IndexActivation" until version 2.6.9_07). You may be able to locate the thread in embedded mode and delay closing the database until its completion (e.g. by using join).

We run still into a dead lock.
I adding a few screenshots and I hope it help you to find/solve the isse.

ODB-IndexActivation thread (id:427) -> waiting for MST   (owend by Thread: [pool-5-thread-3] )

ODB FileWriter -> waiting for MST   (owend by Thread: [pool-5-thread-3] )

Thread_checkFeatures -> waiting for MST  (owend by Thread: [pool-5-thread-3] )

[pool-5-thread-3]  ->  waiting for  Thread id:427  (ODB-IndexActivation)   the Thread.join() was called by ObjectDB.

The [pool-5-thread-3] is our thread to update the metamodel. -> (We call for each EntityClass: entityManager.getMetamodel().entity(entityClass);  [http://www.objectdb.com/database/forum/597] )

We can add the following code block after creating the EntityManagerFactory.

this.entityManagerFactory = createEntityManagerFactory(....);

//trigger the ODB IndexActivation. It failed if it run together with the metamodelUpdate
// (http://www.objectdb.com/database/forum/1060)
EntityManager em = this.entityManagerFactory.createEntityManager();

final String indexActivationThreadName = "ODB-IndexActivation";
Thread indexActivationThread = null;

Set<Thread> threadSet = Thread.getAllStackTraces().keySet();
Thread[] threadArray = threadSet.toArray(new Thread[threadSet.size()]);

for (int i = 0; i < threadArray.length; i++) {
    if (threadArray[i].getName().equals(indexActivationThreadName)) {
        indexActivationThread = threadArray[i];
        break;
    }
}

if (indexActivationThread != null) {
    try {
        indexActivationThread.join();
    } catch (InterruptedException e) {
        log.debug("Thread interruped during join the 'ODB-IndexActivation' thread");
    }
}

em.close();

Is this correct?

Is it guaranteed that we get the thread 'ODB-IndexActivation' or do we need a fallback?

if (indexActivationThread != null) {
    try {
        indexActivationThread.join();
    } catch (InterruptedException e) {
        log.debug("Thread interruped during join the 'ODB-IndexActivation' thread");
    }
} else {
    log.debug("Thread ODB IndexActivation not running. Fallback wait 4 seconds");
    try {
        //wait 4 seconds
        Thread.sleep(100);
    } catch (InterruptedException e) {
        log.debug("SLEEP for ODB IndexActivation failed");
    }
}

If we open a database without any Metamodel changes we don't get the tread. I think that in this case the IndexActivation are finished. (But it must not happen that we do not wait.)

The problem is indeed a deadlock collision between metamodel access and automatic index activation.

Your workaround seems good. Does it work?

For the scenario we know, the workaround works.

So you may use this workaround until we solve the issue, which may take some time.

Hi 

We had the same issue using the version 2.6.1 and waited for a new version to fix. Unfortunatly the new version 2.7-1_01 does not fix that problem as it should do, according to the release notes. We could repeatable cause this error, when opening an old database (created from version 2.6.1) with the new library, do some short thing and close it again. 

Using the workaround from user 'btc_es' avoids the exception. After the workaround has taken place, we could run the testcase (on the newly indexed database) several times without the workaround and without any exceptions. 

Now I'm a little bit unshure, if we should rely on this workaround and wether we need it every time after opening the database or only once a time after changing the indexes. 

In our scenario (exspecially update) it may happen that the database ist opened only for a short time. What if the indexer will start his work in this moment. 

edit1: I Just recognized, that the behavior of 2.7.1_01 is not completly the same as in 2.6.7, escpecially it's not a null pointer exception. Instead it seems, that closing the database causes the ODB-IndexActivation Thread to complain about the now unreadable database. 

12.07.2017 16:43:30 | copy dbfile
12.07.2017 16:43:33 | Datenbank gefunden und angemeldet (U:\Arne_Temp\TestDB_Arne_objectd_jar\dbtest\AdvoluxData)
12.07.2017 16:43:33 | changed: Peter Gegner, Anschrift: Gegnerweg 1, 10119 Berlin
pos = 3987456
length = 2048
12.07.2017 16:43:34 | Datenbank abgemeldet
Exception in thread "ODB-IndexActivation" com.objectdb.o.UserException: Failed to read from file 'U:\Arne_Temp\TestDB_Arne_objectd_jar\dbtest\AdvoluxData\db\anwalt.objectdb'
at com.objectdb.o.MSG.d(MSG.java:75)
at com.objectdb.o.LFL.UA(LFL.java:1107)
at com.objectdb.o.PAG.au(PAG.java:928)
at com.objectdb.o.PGC.C(PGC.java:283)
at com.objectdb.o.SNP.G(SNP.java:436)
at com.objectdb.o.OBI.v(OBI.java:448)
at com.objectdb.o.OBI.s(OBI.java:357)
at com.objectdb.o.OBI.r(OBI.java:274)
at com.objectdb.o.MBI.c(MBI.java:51)
at com.objectdb.o.MBI.VC(MBI.java:71)
at com.objectdb.o.MST.U8(MST.java:783)
at com.objectdb.o.IXM.D(IXM.java:366)
at com.objectdb.o.IXM.run(IXM.java:341)
at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.seek0(Native Method)
at java.io.RandomAccessFile.seek(Unknown Source)
at com.objectdb.o.LFL.L(LFL.java:1184)
at com.objectdb.o.LFL.UA(LFL.java:1101)

edit2: I played around a little bit with our  testcase and repeated the task several times before calling the workaround. It seems that once the workaround was called, every thing went fine and there was no damage at the database. The old library (I think it was 2.6.7) has sometimes damaged the whole database, so we did not dare to deliver it to our customers. 

Apparently the line numbers in this stack trace do not match build 2.7.1_01 completely.

Please check the stack trace in the log file as it should contain also the actual build number.

If you use client-server mode use the new version on both sides.

I have to appologize. You're quite right. I included the 2.7.1_01 in the classpath Testproject and forgot, that the 2.6.x was already included by a required project of the build path. 

I will continue testing. 

best regards 

Arne

the stacktrace now (with version 2.7.1_01) is now13.07.2017 11:19:13 | copy dbfile

13.07.2017 11:19:13 1 copyFile: U:\Arne_Temp\TestDB_Arne_objectd_jar\dbtest\AdvoluxData\db\xanwalt.objectdb zu U:\Arne_Temp\TestDB_Arne_objectd_jar\dbtest\AdvoluxData\db\anwalt.objectdb
13.07.2017 11:19:13 1 dblib version: 2.7.1_01
13.07.2017 11:19:15 | Datenbank gefunden und angemeldet (U:\Arne_Temp\TestDB_Arne_objectd_jar\dbtest\AdvoluxData)
13.07.2017 11:19:16 | changed: Peter Gegner, Anschrift: Gegnerweg 1, 10119 Berlin
13.07.2017 11:19:16 1 Close Anwalt Server
13.07.2017 11:19:16 | Datenbank abgemeldet

Exception in thread "ODB-IndexActivation" com.objectdb.o.UserException: Failed to read from file 'U:\Arne_Temp\TestDB_Arne_objectd_jar\dbtest\AdvoluxData\db\anwalt.objectdb'
at com.objectdb.o.MSG.d(MSG.java:75)
at com.objectdb.o.LFL.UA(LFL.java:1157)
at com.objectdb.o.LFL.UA(LFL.java:1126)
at com.objectdb.o.PAG.au(PAG.java:927)
at com.objectdb.o.PGC.C(PGC.java:283)
at com.objectdb.o.SNP.G(SNP.java:436)
at com.objectdb.o.OBI.v(OBI.java:448)
at com.objectdb.o.OBI.s(OBI.java:357)
at com.objectdb.o.OBI.r(OBI.java:274)
at com.objectdb.o.MBI.c(MBI.java:51)
at com.objectdb.o.MBI.VC(MBI.java:71)
at com.objectdb.o.MST.U8(MST.java:783)
at com.objectdb.o.IXM.E(IXM.java:379)
at com.objectdb.o.IXM.run(IXM.java:351)
at java.lang.Thread.run(Unknown Source)
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.seek0(Native Method)
at java.io.RandomAccessFile.seek(Unknown Source)
at com.objectdb.o.LFL.UA(LFL.java:1153)
... 13 more

Of course this may happen, if we close the database, while the indexer is working. Is there any legal way to detect, wether objectdb is really finished with all activities that may be proceed and should not be stopped before closing the database. 

The only background activity is currently the index rebuilding.

You may be able to wait for it to finish following #9 above.