Return-Path: X-Original-To: apmail-db-derby-dev-archive@www.apache.org Delivered-To: apmail-db-derby-dev-archive@www.apache.org Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by minotaur.apache.org (Postfix) with SMTP id 47CDB10DED for ; Fri, 18 Apr 2014 13:03:21 +0000 (UTC) Received: (qmail 61371 invoked by uid 500); 18 Apr 2014 13:03:21 -0000 Delivered-To: apmail-db-derby-dev-archive@db.apache.org Received: (qmail 61179 invoked by uid 500); 18 Apr 2014 13:03:20 -0000 Mailing-List: contact derby-dev-help@db.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: Delivered-To: mailing list derby-dev@db.apache.org Received: (qmail 60621 invoked by uid 99); 18 Apr 2014 13:03:17 -0000 Received: from arcas.apache.org (HELO arcas.apache.org) (140.211.11.28) by apache.org (qpsmtpd/0.29) with ESMTP; Fri, 18 Apr 2014 13:03:17 +0000 Date: Fri, 18 Apr 2014 13:03:17 +0000 (UTC) From: "Rick Hillegas (JIRA)" To: derby-dev@db.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (DERBY-6533) Add a quiet mode to NsTest MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ 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.(EmbedPreparedStatement.java:152) at org.apache.derby.impl.jdbc.EmbedPreparedStatement42.(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.(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.(EmbedPreparedStatement.java:152) at org.apache.derby.impl.jdbc.EmbedPreparedStatement42.(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.(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)