db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Rick Hillegas (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (DERBY-6533) Add a quiet mode to NsTest
Date Fri, 18 Apr 2014 13:03:17 GMT

    [ 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)

Mime
View raw message