[
https://issues.apache.org/jira/browse/DERBY-6533?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13974035#comment-13974035
]
Rick Hillegas commented on DERBY-6533:
--------------------------------------
Here is yesterday's 4 hour NsTest run on the 8-core machine.
Summary: 51 lock timeouts, of which 5 were attempts to allocate an identity
value and the rest were in the compiler.
{noformat}
STATISTICS OF OPERATIONS DONE
-----------------------------
Start time = 2014-04-17 17:47:58.0
End time = 2014-04-17 21:47:58.013
Duration = 240 minutes
SUCCESSFUL:
Number of INSERTS = 996700
Number of UPDATES = 489758
Number of DELETES = 490942
Number of SELECTS = 52873
FAILED:
Number of failed INSERTS = 51
Number of failed UPDATES = 476148
Number of failed DELETES = 476470
Number of failed SELECTS = 0
Note that this may not be the same as the server side connections made
to the database especially if connection pooling is employed
NOTE: Failing operations could be because of locking issue that are
directly related to the application logic. They are not necessarily bugs.
Max sequence counter peeked at = 1031313
Last total memory = 6268387328, last free memory = 4673013080 as measured at
Thu Apr 17 21:44:41 CEST 2014
Number of 40XL1 = 51
//////////////////////////////////////////////////////////////
//
// Count = 5, SQLState = 40XL1, Message = A lock could not be obtained
within the time requested
//
//////////////////////////////////////////////////////////////
java.sql.SQLTransactionRollbackException: A lock could not be obtained within
the time requested
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:92)
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:233)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:424)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:353)
at
org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2396)
at
org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:82)
at
org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1430)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1709)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeLargeUpdate(EmbedPreparedStatement.java:320)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate(EmbedPreparedStatement.java:309)
at
org.apache.derbyTesting.system.nstest.utils.DbUtil.add_one_row(DbUtil.java:196)
at
org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:163)
at
org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:114)
at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:790)
Caused by: ERROR 40XL1: A lock could not be obtained within the time requested
at
org.apache.derby.iapi.error.StandardException.newException(StandardException.java:290)
at
org.apache.derby.iapi.error.StandardException.newException(StandardException.java:285)
at
org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:619)
at
org.apache.derby.impl.services.locks.AbstractPool.lockObject(AbstractPool.java:120)
at
org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(ConcurrentPool.java:28)
at
org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(RowLocking3.java:248)
at
org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(OpenConglomerate.java:588)
at
org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(GenericConglomerateController.java:382)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getSetAutoincrementValue(DataDictionaryImpl.java:8717)
at
org.apache.derby.impl.sql.execute.InsertResultSet.getSetAutoincrementValue(InsertResultSet.java:825)
at
org.apache.derby.impl.sql.execute.BaseActivation.getSetAutoincrementValue(BaseActivation.java:742)
at
org.apache.derby.exe.ac8f6a536bx0145x705fx8170x000017ae3f889e.e0(Unknown Source)
at
org.apache.derby.impl.services.reflect.DirectCall.invoke(ReflectGeneratedClass.java:101)
at
org.apache.derby.impl.sql.execute.RowResultSet.getNextRowCore(RowResultSet.java:150)
at
org.apache.derby.impl.sql.execute.NormalizeResultSet.getNextRowCore(NormalizeResultSet.java:188)
at
org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore(DMLWriteResultSet.java:143)
at
org.apache.derby.impl.sql.execute.InsertResultSet.getNextRowCore(InsertResultSet.java:1249)
at
org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:496)
at
org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:470)
at
org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:349)
at
org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1338)
... 7 more
//////////////////////////////////////////////////////////////
//
// Count = 24, SQLState = 40XL1, Message = A lock could not be obtained
within the time requested
//
//////////////////////////////////////////////////////////////
java.sql.SQLTransactionRollbackException: A lock could not be obtained within
the time requested
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:92)
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:233)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:424)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:353)
at
org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2396)
at
org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:82)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(EmbedPreparedStatement.java:152)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement42.<init>(EmbedPreparedStatement42.java:41)
at
org.apache.derby.jdbc.Driver42.newEmbedPreparedStatement(Driver42.java:59)
at
org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(EmbedConnection.java:1734)
at
org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(EmbedConnection.java:1562)
at
org.apache.derbyTesting.system.nstest.utils.DbUtil.add_one_row(DbUtil.java:95)
at
org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:163)
at
org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:114)
at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:790)
Caused by: ERROR 40XL1: A lock could not be obtained within the time requested
at
org.apache.derby.iapi.error.StandardException.newException(StandardException.java:290)
at
org.apache.derby.iapi.error.StandardException.newException(StandardException.java:285)
at
org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:619)
at
org.apache.derby.impl.services.locks.AbstractPool.lockObject(AbstractPool.java:120)
at
org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(ConcurrentPool.java:28)
at
org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForRead(RowLocking3.java:188)
at
org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:531)
at
org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:648)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(B2IRowLocking3.java:306)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(B2IRowLocking3.java:590)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(B2IRowLockingRR.java:104)
at
org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:313)
at
org.apache.derby.impl.store.access.btree.BTreeScan.fetchNext(BTreeScan.java:1600)
at
org.apache.derby.impl.sql.catalog.TabInfoImpl.getRowInternal(TabInfoImpl.java:877)
at
org.apache.derby.impl.sql.catalog.TabInfoImpl.getRowLocation(TabInfoImpl.java:810)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.computeRowLocation(DataDictionaryImpl.java:10143)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.computeAutoincRowLocations(DataDictionaryImpl.java:8669)
at
org.apache.derby.impl.sql.compile.InsertNode.bindStatement(InsertNode.java:544)
at
org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:401)
at
org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:99)
at
org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:1116)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(EmbedPreparedStatement.java:134)
... 8 more
//////////////////////////////////////////////////////////////
//
// Count = 22, SQLState = 40XL1, Message = A lock could not be obtained
within the time requested
//
//////////////////////////////////////////////////////////////
java.sql.SQLTransactionRollbackException: A lock could not be obtained within
the time requested
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:92)
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:233)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:424)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:353)
at
org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2396)
at
org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:82)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(EmbedPreparedStatement.java:152)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement42.<init>(EmbedPreparedStatement42.java:41)
at
org.apache.derby.jdbc.Driver42.newEmbedPreparedStatement(Driver42.java:59)
at
org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(EmbedConnection.java:1734)
at
org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(EmbedConnection.java:1562)
at
org.apache.derbyTesting.system.nstest.utils.DbUtil.add_one_row(DbUtil.java:95)
at
org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:163)
at
org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109)
at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:794)
Caused by: ERROR 40XL1: A lock could not be obtained within the time requested
at
org.apache.derby.iapi.error.StandardException.newException(StandardException.java:290)
at
org.apache.derby.iapi.error.StandardException.newException(StandardException.java:285)
at
org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:619)
at
org.apache.derby.impl.services.locks.AbstractPool.lockObject(AbstractPool.java:120)
at
org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(ConcurrentPool.java:28)
at
org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForRead(RowLocking3.java:188)
at
org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:531)
at
org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:648)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(B2IRowLocking3.java:306)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(B2IRowLocking3.java:590)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(B2IRowLockingRR.java:104)
at
org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:313)
at
org.apache.derby.impl.store.access.btree.BTreeScan.fetchNext(BTreeScan.java:1600)
at
org.apache.derby.impl.sql.catalog.TabInfoImpl.getRowInternal(TabInfoImpl.java:877)
at
org.apache.derby.impl.sql.catalog.TabInfoImpl.getRowLocation(TabInfoImpl.java:810)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.computeRowLocation(DataDictionaryImpl.java:10143)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.computeAutoincRowLocations(DataDictionaryImpl.java:8669)
at
org.apache.derby.impl.sql.compile.InsertNode.bindStatement(InsertNode.java:544)
at
org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:401)
at
org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:99)
at
org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:1116)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(EmbedPreparedStatement.java:134)
... 8 more
{noformat}
> Add a quiet mode to NsTest
> --------------------------
>
> Key: DERBY-6533
> URL: https://issues.apache.org/jira/browse/DERBY-6533
> Project: Derby
> Issue Type: Improvement
> Components: Test
> Affects Versions: 10.11.0.0
> Reporter: Rick Hillegas
> Assignee: Rick Hillegas
> Attachments: derby-6533-01-aa-quietMode.diff,
> derby-6533-02-aa-sequencesAndMoreStats.diff,
> derby-6533-02-aa-sequencesAndMoreStats.out, derby-6533-03-timerThread.diff,
> derby-6533-04-outOfMemory.diff, derby-6533-05-aa-dieQuickly.diff,
> derby-6533-aa-anotherNPE.diff, nstest.out, nstest.out, nstest.out, nstest.out
>
>
> Right now NsTest produces an enormous log file. This may be useful for
> tracking down some errors. However, this can also make it hard to find the
> signal in the noise. It would be good to turn off the chatty diagnostics
> which report the result of every insert, update, delete, and select. A
> summary at the end may be good enough, including a summary of the number of
> times each kind of error (SQLState) was seen. While I'm in there, I plan to
> make other smallish changes.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
