[
https://issues.apache.org/jira/browse/DERBY-6533?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Rick Hillegas updated DERBY-6533:
---------------------------------
Attachment: derby-6533-02-aa-sequencesAndMoreStats.diff
Attaching derby-6533-02-aa-sequencesAndMoreStats.diff. This patch makes a
couple more improvements to NsTest:
1) Exercises sequence generators. This feature was not being tested. I have
added a sequence generator. I have added a column to the table, which INSERT
stuffs with the next value of the sequence generator. I have added a background
thread which inspects the current value of the sequence generator every minute.
I've added a line to the statistics printout at the end; this line reports the
last value which the background thread read from the sequence generator.
2) Added timestamps. The test now reports its start time, end time, and
duration (in minutes).
3) Another exception recorded. I found another spot in DbUtil where we needed
to record an exception.
With this patch, I ran the test for 2 hours using the following command...
{noformat}
java -Dderby.nstest.justCountErrors=true -Dderby.nstest.outputFile=nstest.out
org.apache.derbyTesting.system.nstest.NsTest Embedded
{noformat}
...and then hit control-c.
I have attached the full output as derby-6533-02-aa-sequencesAndMoreStats.out.
Here is the introductory statistics section:
{noformat}
STATISTICS OF OPERATIONS DONE
-----------------------------
Start time = 2014-04-01 08:40:39.896
End time = 2014-04-01 10:50:19.255
Duration = 129 minutes
SUCCESSFUL:
Number of INSERTS = 164717
Number of UPDATES = 81054
Number of DELETES = 81255
Number of SELECTS = 25372
FAILED:
Number of failed INSERTS = 108
Number of failed UPDATES = 78975
Number of failed DELETES = 79022
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 = 199029
Number of 40XL1 = 154
{noformat}
The remainder of derby-6533-02-aa-sequencesAndMoreStats.out is a list of twelve
different stack traces which gave rise to 40XL1 (A lock could not be obtained
within the time requested) errors. Each stack trace is marked with the number
of times it was seen. The bulk of them are timeouts while trying to allocate a
new identity value. The rest seem to be timeouts while trying to read the table
descriptor during the compilation of various statements.
Here's an example of one of these stack traces:
{noformat}
//////////////////////////////////////////////////////////////
//
// Count = 74, 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:148)
at
org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109)
at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:753)
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:8688)
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.acea26cfefx0145x1df3x13ddx000003e474c00.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
{noformat}
Touches the following files:
M java/testing/org/apache/derbyTesting/system/nstest/utils/DbUtil.java
A
java/testing/org/apache/derbyTesting/system/nstest/utils/SequenceReader.java
M java/testing/org/apache/derbyTesting/system/nstest/NsTest.java
M java/testing/org/apache/derbyTesting/system/nstest/init/DbSetup.java
M
java/testing/org/apache/derbyTesting/system/nstest/tester/TesterObject.java
> 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
>
>
> 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)
