Issue Details (XML | Word | Printable)

Key: NUCCORE-1080
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Minor Minor
Assignee: Unassigned
Reporter: pica
Votes: 1
Watchers: 2
Operations

If you were logged in you would be able to see more operations.
DataNucleus Core

multi-threaded initialization issues with @Order extension annotation

Created: 07/Nov/13 06:28 PM   Updated: 19/Nov/13 10:28 AM   Resolved: 11/Nov/13 09:10 AM
Component/s: Code Structure
Affects Version/s: 3.2.7
Fix Version/s: 3.2.9

File Attachments: 1. Zip Archive DN-initialization-test_100threads_10iterations_100runs.zip (70 kB)
2. Zip Archive DN-initialization-test_10threads_2iterations_100runs_nightly-SNAPSHOT.zip (63 kB)
3. Zip Archive DN-initialization-test_10threads_5iterations_100runs.zip (68 kB)
4. Zip Archive DN-initialization-test_10threads_5iterations_100runs_nightly-SNAPSHOT.zip (62 kB)
5. Text File FKListStore.java.patch (3 kB)
6. Text File FKListStore.NPE.log (0.6 kB)
7. Zip Archive NUCACCESS-122.zip (95 kB)


Datastore: Microsoft SQL Server, PostgreSQL
Severity: Test/Acceptance


 Description  « Hide
when multiple threads attempt to persist a class with an collection having an @Order annotation without previously having started DataNucleus a NullPointerException is thrown (stacktrace for datanucleus-core-3.2.8 & datanucleus-rdbms-3.2.7):

18:10:11,404 (main) INFO [DataNucleus.General] - >> Starting threads
18:10:11,640 (Thread-60) ERROR [DataNucleus.General] - Exception performing test
java.lang.NullPointerException
at org.datanucleus.store.rdbms.scostore.FKListStore.getSQLStatementForIterator(FKListStore.java:1204)
at org.datanucleus.store.rdbms.scostore.FKListStore.listIterator(FKListStore.java:958)
at org.datanucleus.store.rdbms.scostore.AbstractListStore.listIterator(AbstractListStore.java:92)
at org.datanucleus.store.rdbms.scostore.AbstractListStore.iterator(AbstractListStore.java:82)
at org.datanucleus.store.types.backed.List.loadFromStore(List.java:298)
at org.datanucleus.store.types.backed.List.initialise(List.java:247)
at org.datanucleus.store.types.SCOUtils.createSCOWrapper(SCOUtils.java:252)
at org.datanucleus.store.types.SCOUtils.newSCOInstance(SCOUtils.java:138)
at org.datanucleus.store.rdbms.mapping.java.AbstractContainerMapping.replaceFieldWithWrapper(AbstractContainerMapping.java:399)
at org.datanucleus.store.rdbms.mapping.java.CollectionMapping.postInsert(CollectionMapping.java:80)
at org.datanucleus.store.rdbms.request.InsertRequest.execute(InsertRequest.java:519)
at org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertTable(RDBMSPersistenceHandler.java:167)
at org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertObject(RDBMSPersistenceHandler.java:143)
at org.datanucleus.state.JDOStateManager.internalMakePersistent(JDOStateManager.java:3776)
at org.datanucleus.state.JDOStateManager.makePersistent(JDOStateManager.java:3752)
at org.datanucleus.ExecutionContextImpl.persistObjectInternal(ExecutionContextImpl.java:2199)
at org.datanucleus.ExecutionContextImpl.persistObjectWork(ExecutionContextImpl.java:2045)
at org.datanucleus.ExecutionContextImpl.persistObject(ExecutionContextImpl.java:1893)
at org.datanucleus.api.jdo.JDOPersistenceManager.jdoMakePersistent(JDOPersistenceManager.java:727)
at org.datanucleus.api.jdo.JDOPersistenceManager.makePersistent(JDOPersistenceManager.java:752)
at org.datanucleus.test.MultithreadTest.performTest(MultithreadTest.java:96)
at org.datanucleus.test.MultithreadTest$1.run(MultithreadTest.java:35)
at java.lang.Thread.run(Thread.java:722)
18:10:16,764 (main) INFO [DataNucleus.General] - >> Completed thread

test case at https://github.com/pktxu/test-jdo

Notes:

1. there are several failure modes, the stacktrace posted is the most common
2. since it is a concurrency issue, several test runs might be needed before manifesting


Sort Order: Ascending order - Click to sort in descending order
pica added a comment - 07/Nov/13 06:31 PM

pica added a comment - 08/Nov/13 09:01 AM
A related NullPointerException (but different, since this one we get when reading, not writing) we are seeing is this:

java.lang.NullPointerException
at org.datanucleus.store.rdbms.scostore.FKListStore.getSQLStatementForIterator(FKListStore.java:1204)
at org.datanucleus.store.rdbms.scostore.FKListStore.listIterator(FKListStore.java:958)
at org.datanucleus.store.rdbms.scostore.AbstractListStore.listIterator(AbstractListStore.java:92)
at org.datanucleus.store.rdbms.scostore.AbstractListStore.iterator(AbstractListStore.java:82)
at org.datanucleus.store.types.backed.List.loadFromStore(List.java:298)
at org.datanucleus.store.types.backed.List.initialise(List.java:247)
at org.datanucleus.store.types.SCOUtils.createSCOWrapper(SCOUtils.java:252)
at org.datanucleus.store.types.SCOUtils.newSCOInstance(SCOUtils.java:138)
at org.datanucleus.store.rdbms.mapping.java.AbstractContainerMapping.replaceFieldWithWrapper(AbstractContainerMapping.java:399)
at org.datanucleus.store.rdbms.mapping.java.AbstractContainerMapping.postFetch(AbstractContainerMapping.java:417)
at org.datanucleus.store.rdbms.request.FetchRequest.execute(FetchRequest.java:420)
at org.datanucleus.store.rdbms.RDBMSPersistenceHandler.fetchObject(RDBMSPersistenceHandler.java:324)
at org.datanucleus.state.AbstractStateManager.loadFieldsFromDatastore(AbstractStateManager.java:1120)
at org.datanucleus.state.JDOStateManager.loadUnloadedFieldsInFetchPlan(JDOStateManager.java:2992)
at org.datanucleus.state.JDOStateManager.isLoaded(JDOStateManager.java:3206)

Andy Jefferson added a comment - 08/Nov/13 05:49 PM
Not reproduceable. Ran that test 10 times, none failed. I'm using SVN trunk of course, but nothing else is different.

pica added a comment - 09/Nov/13 08:06 PM
It is indeed hard to reproduce in such a simple test. For reference, on an i7-3667U CPU (dual core @ 2GHz), I get anything between 8 to 17 failures every 100 runs with THREAD_SIZE reduced to 100 or 10 (way lower than the 500 in the test as-is).

I'm attaching the output of four sets of tests, each of which launched with:

    for i in `seq 100`; do mvn test; touch $i.exit_code.$?; mv datanucleus.log datanucleus.log.$i; done

Two of them are against the release versions, two of them against the nightly snapshots. Note that the number of iterations in performTest() can be reduced for faster testing.

I'm also attaching a patch (against rdbms-3.2.8) adding logging to FKListStore. It hasn't proved useful enough to determine the root cause of the issue so far, but might provide clues to someone knowledgeable.

I hope you can reproduce the issue at least some time with these hints.

pica added a comment - 09/Nov/13 08:08 PM
resuts of a 100 test run against released version

pica added a comment - 09/Nov/13 08:09 PM
resuts of a 100 test run against nightly snapshots

pica added a comment - 09/Nov/13 08:09 PM
detailed logging of an NPE in FKListStore

Andy Jefferson added a comment - 10/Nov/13 09:18 AM - edited
Finally saw an exception by changing to MySQL and running 20 times. OrderMetaData has a change in nightly builds to only assign the fieldOrders field when fully populated; try that and see if it changes things and report back.

Note that one exception in your log was relating to XXXMapping; any errors of that form are possibly due to you not initialising the table structure before starting persistence; which is what datanucleus.PersistenceUnitLoadClasses=true is for (or an auto-start mechanism). I couldn't get this exception so no way of knowing more, either way that is not what this JIRA issue is about so if that is reproducible in some way *once you've added that persistence property* then raise a separate issue

pica added a comment - 10/Nov/13 10:25 PM
The issue can not be reproduced in the latest nightly, thanks for your time.