[
https://issues.apache.org/jira/browse/DERBY-6533?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14010130#comment-14010130
]
Rick Hillegas commented on DERBY-6533:
--------------------------------------
Here is the log from today's 6 hour run of NsTest on the 8 core machine.
Summary:
o 3 TooMuchContention errors on the user-declared sequence generator, 1 1/2
hours into the test
o 1 LockTimeout on the internal sequence generator which backs the identity
column, 3 1/2 hours into the test
o 1 TooMuchContention error on the user-declared sequence generator, 6 3/4
hours into the test
{noformat}
STATISTICS OF OPERATIONS DONE
-----------------------------
Start time = 2014-05-27 14:29:11.444
End time = 2014-05-27 20:29:11.452
Duration = 360 minutes
SUCCESSFUL:
Number of INSERTS = 2490533
Number of UPDATES = 1227762
Number of DELETES = 1226891
Number of SELECTS = 100888
FAILED:
Number of failed INSERTS = 5
Number of failed UPDATES = 1190373
Number of failed DELETES = 1189685
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 = 2521325
Last total memory = 6337593344, last free memory = 4663293072 as measured at
Tue May 27 20:25:55 CEST 2014
Number of X0Y84 = 4
Number of 40XL1 = 1
//////////////////////////////////////////////////////////////
//
// Count = 1, SQLState = X0Y84, Message = Too much contention on sequence
NSTESTTAB_SEQ. This is probably caused by an uncommitted scan of the
SYS.SYSSEQUENCES catalog. Do not query this catalog directly. Instead, use the
SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE function to view the current value of a
sequence generator.
//
// First occurrence at 2014-05-27 16:01:04.741, last occurrence at
2014-05-27 16:01:04.741
//
//////////////////////////////////////////////////////////////
java.sql.SQLException: Too much contention on sequence NSTESTTAB_SEQ. This is
probably caused by an uncommitted scan of the SYS.SYSSEQUENCES catalog. Do not
query this catalog directly. Instead, use the SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE
function to view the current value of a sequence generator.
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:107)
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:164)
at
org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:121)
at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:805)
Caused by: ERROR X0Y84: Too much contention on sequence NSTESTTAB_SEQ. This is
probably caused by an uncommitted scan of the SYS.SYSSEQUENCES catalog. Do not
query this catalog directly. Instead, use the SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE
function to view the current value of a sequence generator.
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.sql.catalog.SequenceUpdater.tooMuchContentionException(SequenceUpdater.java:190)
at
org.apache.derby.impl.sql.catalog.SequenceUpdater.getCurrentValueAndAdvance(SequenceUpdater.java:427)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getCurrentValueAndAdvance(DataDictionaryImpl.java:10306)
at
org.apache.derby.impl.sql.execute.BaseActivation.getCurrentValueAndAdvance(BaseActivation.java:763)
at
org.apache.derby.exe.ac79d58706x0146x3da7xe5f6x000017b298301.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:1311)
at
org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:503)
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 = 2, SQLState = X0Y84, Message = Too much contention on sequence
NSTESTTAB_SEQ. This is probably caused by an uncommitted scan of the
SYS.SYSSEQUENCES catalog. Do not query this catalog directly. Instead, use the
SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE function to view the current value of a
sequence generator.
//
// First occurrence at 2014-05-27 16:01:04.742, last occurrence at
2014-05-27 16:01:04.743
//
//////////////////////////////////////////////////////////////
java.sql.SQLException: Too much contention on sequence NSTESTTAB_SEQ. This is
probably caused by an uncommitted scan of the SYS.SYSSEQUENCES catalog. Do not
query this catalog directly. Instead, use the SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE
function to view the current value of a sequence generator.
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:107)
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:164)
at
org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:113)
at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:809)
Caused by: ERROR X0Y84: Too much contention on sequence NSTESTTAB_SEQ. This is
probably caused by an uncommitted scan of the SYS.SYSSEQUENCES catalog. Do not
query this catalog directly. Instead, use the SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE
function to view the current value of a sequence generator.
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.sql.catalog.SequenceUpdater.tooMuchContentionException(SequenceUpdater.java:190)
at
org.apache.derby.impl.sql.catalog.SequenceUpdater.getCurrentValueAndAdvance(SequenceUpdater.java:427)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getCurrentValueAndAdvance(DataDictionaryImpl.java:10306)
at
org.apache.derby.impl.sql.execute.BaseActivation.getCurrentValueAndAdvance(BaseActivation.java:763)
at
org.apache.derby.exe.ac79d58706x0146x3da7xe5f6x000017b298301.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:1311)
at
org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:503)
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 = 1, SQLState = 40XL1, Message = A lock could not be obtained
within the time requested
//
// First occurrence at 2014-05-27 18:06:10.547, last occurrence at
2014-05-27 18:06:10.547
//
//////////////////////////////////////////////////////////////
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:164)
at
org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:113)
at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:809)
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.sql.catalog.SequenceUpdater.tooMuchContentionException(SequenceUpdater.java:185)
at
org.apache.derby.impl.sql.catalog.SequenceUpdater.getCurrentValueAndAdvance(SequenceUpdater.java:427)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getCurrentValueAndAdvance(DataDictionaryImpl.java:10306)
at
org.apache.derby.impl.sql.execute.BaseActivation.getCurrentValueAndAdvance(BaseActivation.java:763)
at
org.apache.derby.impl.sql.execute.InsertResultSet.getSetAutoincrementValue(InsertResultSet.java:777)
at
org.apache.derby.impl.sql.execute.BaseActivation.getSetAutoincrementValue(BaseActivation.java:742)
at
org.apache.derby.exe.ac15941700x0146x3da7xe5f6x000017b2983082.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:1311)
at
org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:503)
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 = 1, SQLState = X0Y84, Message = Too much contention on sequence
NSTESTTAB_SEQ. This is probably caused by an uncommitted scan of the
SYS.SYSSEQUENCES catalog. Do not query this catalog directly. Instead, use the
SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE function to view the current value of a
sequence generator.
//
// First occurrence at 2014-05-27 20:16:51.381, last occurrence at
2014-05-27 20:16:51.381
//
//////////////////////////////////////////////////////////////
java.sql.SQLException: Too much contention on sequence NSTESTTAB_SEQ. This is
probably caused by an uncommitted scan of the SYS.SYSSEQUENCES catalog. Do not
query this catalog directly. Instead, use the SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE
function to view the current value of a sequence generator.
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:107)
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:164)
at
org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:113)
at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:809)
Caused by: ERROR X0Y84: Too much contention on sequence NSTESTTAB_SEQ. This is
probably caused by an uncommitted scan of the SYS.SYSSEQUENCES catalog. Do not
query this catalog directly. Instead, use the SYSCS_UTIL.SYSCS_PEEK_AT_SEQUENCE
function to view the current value of a sequence generator.
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.sql.catalog.SequenceUpdater.tooMuchContentionException(SequenceUpdater.java:190)
at
org.apache.derby.impl.sql.catalog.SequenceUpdater.getCurrentValueAndAdvance(SequenceUpdater.java:427)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getCurrentValueAndAdvance(DataDictionaryImpl.java:10306)
at
org.apache.derby.impl.sql.execute.BaseActivation.getCurrentValueAndAdvance(BaseActivation.java:763)
at
org.apache.derby.exe.ac0bbcd7f9x0146x3da7xe5f6x000017b298308f.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:1311)
at
org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:503)
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
{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-07-aa-moreDefensiveCode.diff, derby-6533-08-aa-sortErrors.diff,
> derby-6533-aa-anotherNPE.diff, nstest.out, nstest.out, nstest.out,
> nstest.out, nstest.out, nstest.out, nstest.out, nstest.out, nstest.out,
> 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)
