| [CDO] ConnectionKeepAliveTask and database transactions [message #1692843] |
Mon, 20 April 2015 08:04  |
 András Péteri
Messages: 22
Registered: January 2010 |
Junior Member |
|
|
Hello,
I am trying to track down an intermittent problem in a CDO-based application (using MySQL as the store) where some of the list items can not be read from the MAIN branch. Typical stack traces include:
java.lang.IllegalArgumentException: Base of main branch is null
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.createBaseChunkReader(BranchingListTableMappingWithRanges.java:1388)
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.readChunks(BranchingListTableMappingWithRanges.java:543)
at org.eclipse.emf.cdo.server.internal.db.DBStoreChunkReader.executeRead(DBStoreChunkReader.java:98)
at org.eclipse.emf.cdo.internal.server.Repository.ensureChunk(Repository.java:676)
at org.eclipse.emf.cdo.internal.server.Repository.ensureChunk(Repository.java:599)
at org.eclipse.emf.cdo.internal.server.Repository.ensureChunks(Repository.java:584)
at org.eclipse.emf.cdo.internal.server.DelegatingRepository.ensureChunks(DelegatingRepository.java:471)
at org.eclipse.emf.cdo.internal.server.TransactionCommitContext.computeDirtyObject(TransactionCommitContext.java:1078)
at org.eclipse.emf.cdo.internal.server.TransactionCommitContext.computeDirtyObjects(TransactionCommitContext.java:1017)
at org.eclipse.emf.cdo.internal.server.TransactionCommitContext.write(TransactionCommitContext.java:488)
[...]
java.lang.IllegalArgumentException: Base of main branch is null
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.createBaseChunkReader(BranchingListTableMappingWithRanges.java:1388)
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.getValueFromBase(BranchingListTableMappingWithRanges.java:1372)
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.clearList(BranchingListTableMappingWithRanges.java:659)
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges$ListDeltaVisitor.visit(BranchingListTableMappingWithRanges.java:863)
at org.eclipse.emf.cdo.internal.common.revision.delta.CDOClearFeatureDeltaImpl.accept(CDOClearFeatureDeltaImpl.java:58)
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.processDelta(BranchingListTableMappingWithRanges.java:747)
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.HorizontalBranchingClassMapping$FeatureDeltaWriter.visit(HorizontalBranchingClassMapping.java:161)
at org.eclipse.emf.cdo.internal.common.revision.delta.CDOListFeatureDeltaImpl.accept(CDOListFeatureDeltaImpl.java:420)
at org.eclipse.emf.cdo.internal.common.revision.delta.CDORevisionDeltaImpl.accept(CDORevisionDeltaImpl.java:302)
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.HorizontalBranchingClassMapping$FeatureDeltaWriter.process(HorizontalBranchingClassMapping.java:122)
at org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.HorizontalBranchingClassMapping.writeRevisionDelta(HorizontalBranchingClassMapping.java:1113)
at org.eclipse.emf.cdo.server.internal.db.DBStoreAccessor.writeRevisionDelta(DBStoreAccessor.java:553)
at org.eclipse.emf.cdo.server.internal.db.DBStoreAccessor.writeRevisionDeltas(DBStoreAccessor.java:538)
at org.eclipse.emf.cdo.spi.server.StoreAccessor.doWrite(StoreAccessor.java:101)
at org.eclipse.emf.cdo.spi.server.StoreAccessorBase.write(StoreAccessorBase.java:149)
at org.eclipse.emf.cdo.internal.server.TransactionCommitContext.write(TransactionCommitContext.java:496)
[...]
When I shut down the server and check the list mappings using SQL, they look continuous (for a particular list source version, the only list index which does not have a successor is the index of the last item in the list).
One thing that I have noticed is related to ConnectionKeepAliveTask's "SELECT 1 FROM cdo_properties" ping query, which is executed on DBStoreAccessor connections in 4 hour intervals by default; if I enter this query into a MySQL console with autocommit disabled, I get the following from the InnoDB engine status output:
---TRANSACTION 567555, ACTIVE 2 sec
MySQL thread id 1, OS thread handle 0x143c, query id 16 localhost ::1 root init
show engine innodb status
Trx read view will not see trx with id >= 567556, sees < 567556
...which means that the SELECT kicks off a database transaction, and all further reads will only see rows that were written in this transaction, or have happened before the first read was issued, according to [1]. This may mean that an ensureChunks or clearList call is reading database state which is up to 4 hours behind. A more recent list source revision may state that it has more list items than what can be read from the table.
What's making this even harder to catch is that if reads succeed and do not cause any problems, the DB transaction is rolled back in DBStoreAccessor#doPassivate, and the connection will see the latest database state, until the keepalive query is run again. If there are not recently used accessors accumulated in the pool, and some transactions try to use them and fail, they will be "rejuvenated" by the rollback, and after some failed attempts, things may start to work again.
Is this a theory worth pursuing? Did someone else have similar problems?
[1] https://dev.mysql.com/doc/refman/5.6/en/innodb-consistent-read.html
|
|
|
| Re: [CDO] ConnectionKeepAliveTask and database transactions [message #1692986 is a reply to message #1692843] |
Tue, 21 April 2015 05:59  |
|
Hi Andras,
The problem (or a similar one?) has been reported some time ago:
416376: [DB] H2-branching-ranges: Base branch is null
https://bugs.eclipse.org/bugs/show_bug.cgi?id=416376
It is possible that it has been solved in the latest master branch sources. Have you tried it with newest sources or builds?
The ConnectionKeepAliveTask theory is a little hard to believe. Wouldn't that mean that
a) Problems would only occur at least 4 hours after repo start?
b) A lot more fundamental and different problems would occur?
Cheers
/Eike
----
http://www.esc-net.de
http://thegordian.blogspot.com
http://twitter.com/eikestepper
Am 20.04.2015 um 10:04 schrieb Andras Peteri:
> Hello,
>
> I am trying to track down an intermittent problem in a CDO-based application (using MySQL as the store) where some of
> the list items can not be read from the MAIN branch. Typical stack traces include:
>
>
> java.lang.IllegalArgumentException: Base of main branch is null
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.createBaseChunkReader(BranchingListTableMappingWithRanges.java:1388)
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.readChunks(BranchingListTableMappingWithRanges.java:543)
> at org.eclipse.emf.cdo.server.internal.db.DBStoreChunkReader.executeRead(DBStoreChunkReader.java:98)
> at org.eclipse.emf.cdo.internal.server.Repository.ensureChunk(Repository.java:676)
> at org.eclipse.emf.cdo.internal.server.Repository.ensureChunk(Repository.java:599)
> at org.eclipse.emf.cdo.internal.server.Repository.ensureChunks(Repository.java:584)
> at org.eclipse.emf.cdo.internal.server.DelegatingRepository.ensureChunks(DelegatingRepository.java:471)
> at org.eclipse.emf.cdo.internal.server.TransactionCommitContext.computeDirtyObject(TransactionCommitContext.java:1078)
> at
> org.eclipse.emf.cdo.internal.server.TransactionCommitContext.computeDirtyObjects(TransactionCommitContext.java:1017)
> at org.eclipse.emf.cdo.internal.server.TransactionCommitContext.write(TransactionCommitContext.java:488)
> [...]
>
>
>
> java.lang.IllegalArgumentException: Base of main branch is null
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.createBaseChunkReader(BranchingListTableMappingWithRanges.java:1388)
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.getValueFromBase(BranchingListTableMappingWithRanges.java:1372)
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.clearList(BranchingListTableMappingWithRanges.java:659)
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges$ListDeltaVisitor.visit(BranchingListTableMappingWithRanges.java:863)
> at
> org.eclipse.emf.cdo.internal.common.revision.delta.CDOClearFeatureDeltaImpl.accept(CDOClearFeatureDeltaImpl.java:58)
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.BranchingListTableMappingWithRanges.processDelta(BranchingListTableMappingWithRanges.java:747)
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.HorizontalBranchingClassMapping$FeatureDeltaWriter.visit(HorizontalBranchingClassMapping.java:161)
> at org.eclipse.emf.cdo.internal.common.revision.delta.CDOListFeatureDeltaImpl.accept(CDOListFeatureDeltaImpl.java:420)
> at org.eclipse.emf.cdo.internal.common.revision.delta.CDORevisionDeltaImpl.accept(CDORevisionDeltaImpl.java:302)
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.HorizontalBranchingClassMapping$FeatureDeltaWriter.process(HorizontalBranchingClassMapping.java:122)
> at
> org.eclipse.emf.cdo.server.internal.db.mapping.horizontal.HorizontalBranchingClassMapping.writeRevisionDelta(HorizontalBranchingClassMapping.java:1113)
> at org.eclipse.emf.cdo.server.internal.db.DBStoreAccessor.writeRevisionDelta(DBStoreAccessor.java:553)
> at org.eclipse.emf.cdo.server.internal.db.DBStoreAccessor.writeRevisionDeltas(DBStoreAccessor.java:538)
> at org.eclipse.emf.cdo.spi.server.StoreAccessor.doWrite(StoreAccessor.java:101)
> at org.eclipse.emf.cdo.spi.server.StoreAccessorBase.write(StoreAccessorBase.java:149)
> at org.eclipse.emf.cdo.internal.server.TransactionCommitContext.write(TransactionCommitContext.java:496)
> [...]
>
>
> When I shut down the server and check the list mappings using SQL, they look continuous (for a particular list source
> version, the only list index which does not have a successor is the index of the last item in the list).
>
> One thing that I have noticed is related to ConnectionKeepAliveTask's "SELECT 1 FROM cdo_properties" ping query, which
> is executed on DBStoreAccessor connections in 4 hour intervals by default; if I enter this query into a MySQL console
> with autocommit disabled, I get the following from the InnoDB engine status output:
>
>
> ---TRANSACTION 567555, ACTIVE 2 sec
> MySQL thread id 1, OS thread handle 0x143c, query id 16 localhost ::1 root init
> show engine innodb status
> Trx read view will not see trx with id >= 567556, sees < 567556
>
>
> ..which means that the SELECT kicks off a database transaction, and all further reads will only see rows that were
> written in this transaction, or have happened before the first read was issued, according to [1]. This may mean that
> an ensureChunks or clearList call is reading database state which is up to 4 hours behind. A more recent list source
> revision may state that it has more list items than what can be read from the table.
>
> What's making this even harder to catch is that if reads succeed and do not cause any problems, the DB transaction is
> rolled back in DBStoreAccessor#doPassivate, and the connection will see the latest database state, until the keepalive
> query is run again. If there are not recently used accessors accumulated in the pool, and some transactions try to use
> them and fail, they will be "rejuvenated" by the rollback, and after some failed attempts, things may start to work
> again.
>
> Is this a theory worth pursuing? Did someone else have similar problems?
>
> [1] https://dev.mysql.com/doc/refman/5.6/en/innodb-consistent-read.html
Cheers
/Eike
----
http://www.esc-net.de
http://thegordian.blogspot.com
http://twitter.com/eikestepper
|
|
|
Powered by
FUDForum. Page generated in 0.03295 seconds
] 
Search
Help
Register
Login
Home
