Return-Path: Delivered-To: apmail-db-derby-user-archive@www.apache.org Received: (qmail 89084 invoked from network); 27 Jan 2009 22:20:49 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.2) by minotaur.apache.org with SMTP; 27 Jan 2009 22:20:49 -0000 Received: (qmail 90743 invoked by uid 500); 26 Jan 2009 23:37:32 -0000 Delivered-To: apmail-db-derby-user-archive@db.apache.org Received: (qmail 90724 invoked by uid 500); 26 Jan 2009 23:37:32 -0000 Mailing-List: contact derby-user-help@db.apache.org; run by ezmlm Precedence: bulk list-help: list-unsubscribe: List-Post: List-Id: Reply-To: "Derby Discussion" Delivered-To: mailing list derby-user@db.apache.org Received: (qmail 90715 invoked by uid 99); 26 Jan 2009 23:37:32 -0000 Received: from nike.apache.org (HELO nike.apache.org) (192.87.106.230) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 26 Jan 2009 15:37:32 -0800 X-ASF-Spam-Status: No, hits=-0.0 required=10.0 tests=SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (nike.apache.org: domain of blair@orcaware.com designates 12.11.234.124 as permitted sender) Received: from [12.11.234.124] (HELO orca3.orcaware.com) (12.11.234.124) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 26 Jan 2009 23:37:24 +0000 Received: from [127.0.0.1] (localhost [127.0.0.1]) by orca3.orcaware.com (8.13.5.20060308/8.13.5/Debian-3ubuntu1.1) with ESMTP id n0QNaw1N022746; Mon, 26 Jan 2009 15:36:58 -0800 Message-ID: <497E4919.7090908@orcaware.com> Date: Mon, 26 Jan 2009 15:36:57 -0800 From: Blair Zajac User-Agent: Thunderbird 2.0.0.19 (Macintosh/20081209) MIME-Version: 1.0 To: Derby Discussion Subject: Re: 50 transactions timing out with no CPU usage and no deadlocks References: <497D1184.8020301@orcaware.com> <497D7586.90002@Sun.COM> In-Reply-To: <497D7586.90002@Sun.COM> Content-Type: multipart/mixed; boundary="------------010609050304090401000009" X-Virus-Checked: Checked by ClamAV on apache.org This is a multi-part message in MIME format. --------------010609050304090401000009 Content-Type: text/plain; charset=ISO-8859-1; format=flowed Content-Transfer-Encoding: 7bit Kristian Waagan wrote: > Blair Zajac wrote: >> > Hello Blair, > > My only *guess* is that there might be a restructuring of a BTree going > on, which is not correctly reported - and you might be experiencing a > deadlock. To stop guessing and actually start understanding what's going > on, it would be great if you could provide a standalone repro. > Such a repro is best handled by creating a bug report in Jira: > https://issues.apache.org/jira/browse/DERBY Hello Kristian, Thanks for the quick reply. I do have a reproduction standalone Java file that runs the tests. I've attached it to the note. Should I still open a ticket if the DERBY-2991 patch works? More information below. > Other things to try: > o Post the stack trace from the hang, preferably from a Derby debug > build to get line numbers. Here they are Compiling 10.4.2.0 from the svn tag and using that: org.apache.derby.iapi.error.StandardException.newException(StandardException.java:286) org.apache.derby.impl.services.locks.Timeout.createException(Timeout.java:150) org.apache.derby.impl.services.locks.Timeout.buildException(Timeout.java:249) org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:597) org.apache.derby.impl.services.locks.AbstractPool.lockObject(AbstractPool.java:119) org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(RowLocking3.java:248) org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:504) org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:638) org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(B2IRowLocking3.java:335) org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockNonScanRowOnPage(B2IRowLocking3.java:1091) org.apache.derby.impl.store.access.btree.BTreeController.doIns(BTreeController.java:706) org.apache.derby.impl.store.access.btree.BTreeController.insert(BTreeController.java:1264) org.apache.derby.impl.store.access.btree.index.B2IController.insert(B2IController.java:210) org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(IndexChanger.java:439) org.apache.derby.impl.sql.execute.IndexChanger.doInsert(IndexChanger.java:383) org.apache.derby.impl.sql.execute.IndexChanger.insert(IndexChanger.java:589) org.apache.derby.impl.sql.execute.IndexSetChanger.insert(IndexSetChanger.java:268) org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(RowChangerImpl.java:453) org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:1011) org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:487) org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:372) org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235) org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:625) org.apache.derby.impl.jdbc.EmbedStatement.executeUpdate(EmbedStatement.java:175) NoProgressTest.executeUpdate(NoProgressTest.java:38) NoProgressTest.access$100(NoProgressTest.java:10) NoProgressTest$InsertRunnable.run(NoProgressTest.java:213) Using the 10.4 branch at r737828. org.apache.derby.impl.services.locks.Timeout.createException(Timeout.java:150) org.apache.derby.impl.services.locks.Timeout.buildException(Timeout.java:249) org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:597) org.apache.derby.impl.services.locks.AbstractPool.lockObject(AbstractPool.java:119) org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(RowLocking3.java:248) org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:504) org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:638) org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(B2IRowLocking3.java:335) org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockNonScanRowOnPage(B2IRowLocking3.java:1091) org.apache.derby.impl.store.access.btree.BTreeController.doIns(BTreeController.java:706) org.apache.derby.impl.store.access.btree.BTreeController.insert(BTreeController.java:1264) org.apache.derby.impl.store.access.btree.index.B2IController.insert(B2IController.java:210) org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(IndexChanger.java:439) org.apache.derby.impl.sql.execute.IndexChanger.doInsert(IndexChanger.java:383) org.apache.derby.impl.sql.execute.IndexChanger.insert(IndexChanger.java:589) org.apache.derby.impl.sql.execute.IndexSetChanger.insert(IndexSetChanger.java:268) org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(RowChangerImpl.java:453) org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:1011) org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:487) org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:372) org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235) org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:625) org.apache.derby.impl.jdbc.EmbedStatement.executeUpdate(EmbedStatement.java:175) NoProgressTest.executeUpdate(NoProgressTest.java:38) NoProgressTest.access$100(NoProgressTest.java:10) NoProgressTest$InsertRunnable.run(NoProgressTest.java:213) With an unpatched trunk at r737572 org.apache.derby.iapi.error.StandardException.newException(StandardException.java:286) org.apache.derby.impl.services.locks.Timeout.createException(Timeout.java:150) org.apache.derby.impl.services.locks.Timeout.buildException(Timeout.java:249) org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:597) org.apache.derby.impl.services.locks.AbstractPool.lockObject(AbstractPool.java:119) org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(RowLocking3.java:248) org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:504) org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:638) org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(B2IRowLocking3.java:335) org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockNonScanRowOnPage(B2IRowLocking3.java:1091) org.apache.derby.impl.store.access.btree.BTreeController.doIns(BTreeController.java:707) org.apache.derby.impl.store.access.btree.BTreeController.insert(BTreeController.java:1261) org.apache.derby.impl.store.access.btree.index.B2IController.insert(B2IController.java:210) org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(IndexChanger.java:439) org.apache.derby.impl.sql.execute.IndexChanger.doInsert(IndexChanger.java:383) org.apache.derby.impl.sql.execute.IndexChanger.insert(IndexChanger.java:589) org.apache.derby.impl.sql.execute.IndexSetChanger.insert(IndexSetChanger.java:268) org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(RowChangerImpl.java:453) org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:1022) org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:495) org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:416) org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:297) org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235) org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:625) org.apache.derby.impl.jdbc.EmbedStatement.executeUpdate(EmbedStatement.java:175) NoProgressTest.executeUpdate(NoProgressTest.java:38) NoProgressTest.access$100(NoProgressTest.java:10) > o You don't say if you enabled "extended tracing". If not, see > http://wiki.apache.org/db-derby/LockDebugging I've done this. > o Download the patch for DERBY-2991, build Derby and see if it solves > your problem. I downloaded d2991-preview-1e.diff and applied it to r737572 of trunk. I don't see the original problem now. Even going to 500 threads and setting derby.locks.waitTimeout to -1 works. Will or when will a patch for d2991 be applied to trunk? Regards, Blair --------------010609050304090401000009 Content-Type: text/plain; name="NoProgressTest.java" Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="NoProgressTest.java" import java.sql.Connection; import java.sql.ResultSet; import java.sql.Statement; import java.util.ArrayList; import java.util.List; import java.util.TreeSet; import java.util.concurrent.atomic.AtomicInteger; import java.util.concurrent.CountDownLatch; public class NoProgressTest { private static Connection getConnection(String suffix) throws java.sql.SQLException { // String url = "jdbc:derby://localhost/no-progress" + suffix; String url = "jdbc:derby:no-progress" + suffix; return java.sql.DriverManager.getConnection(url); } private static void execute(Connection c, String sql) throws java.sql.SQLException { Statement s = c.createStatement(); try { s.execute(sql); } finally { s.close(); } } private static void executeUpdate(Connection c, String sql) throws java.sql.SQLException { Statement s = c.createStatement(); try { int count = s.executeUpdate(sql); if (count != 1) { throw new java.lang.RuntimeException(sql + " updated " + count + " rows."); } } finally { s.close(); } } private static void createSchema() throws java.sql.SQLException { Connection c = getConnection(";create=true"); try { execute(c, "CREATE TABLE facility " + "(pk_facility INT PRIMARY KEY, " + " code CHAR(3) UNIQUE)"); execute(c, "CREATE TABLE facility_set " + "(pk_facility_set INT PRIMARY KEY)"); execute(c, "CREATE TABLE facility_set_membership " + "(pk_facility INT, " + "pk_facility_set INT)"); execute(c, "CREATE UNIQUE INDEX fsm_idx ON " + "facility_set_membership (pk_facility, pk_facility_set)"); execute(c, "ALTER TABLE facility_set_membership " + "ADD CONSTRAINT fk_fsm_f " + "FOREIGN KEY (pk_facility) " + "REFERENCES facility(pk_facility)"); execute(c, "ALTER TABLE facility_set_membership " + "ADD CONSTRAINT fk_fsm_fs " + "FOREIGN KEY (pk_facility_set) " + "REFERENCES facility_set(pk_facility_set)"); execute(c, "CREATE TABLE location " + "(pk_location INT PRIMARY KEY, " + "pk_facility_set INT, " + "path VARCHAR(1024) UNIQUE NOT NULL)"); execute(c, "ALTER TABLE location " + "ADD CONSTRAINT fk_loc_fs " + "FOREIGN KEY (pk_facility_set) " + "REFERENCES facility_set(pk_facility_set)"); } finally { c.close(); } } private static void populateFacilityTable(List facilityCodes) throws java.sql.SQLException { Connection c = getConnection(""); try { for (String code : facilityCodes) { executeUpdate(c, "INSERT INTO facility (pk_facility, code) " + "VALUES (" + code.hashCode() + ", '" + code + "')"); } } finally { c.close(); } } private static void insertFacilitySet(Connection c, TreeSet facilitySet) throws java.sql.SQLException { executeUpdate(c, "INSERT INTO facility_set (pk_facility_set) VALUES " + "(" + facilitySet.hashCode() + ")"); for (String code : facilitySet) { executeUpdate(c, "INSERT INTO facility_set_membership " + "(pk_facility, pk_facility_set) VALUES " + "(" + code.hashCode() + ", " + facilitySet.hashCode() + ")"); } } private static void populateFacilitySetTable(List> facilitySets) throws java.sql.SQLException { Connection c = getConnection(""); try { for (TreeSet facilitySet : facilitySets) { insertFacilitySet(c, facilitySet); } } finally { c.close(); } } private static TreeSet getLocationFacilitySet(Connection c, String location) throws java.sql.SQLException { Statement s = c.createStatement(); try { // First get the location's facility_set foriegn key. String sql1 = "SELECT pk_facility_set FROM location WHERE " + "pk_location = " + location.hashCode() + " FOR UPDATE"; ResultSet rs1 = s.executeQuery(sql1); rs1.next(); int pk_facility_set = rs1.getInt(1); rs1.close(); String sql2 = "SELECT facility.code " + "FROM facility, facility_set_membership, " + "facility_set " + "WHERE facility.pk_facility = facility_set_membership.pk_facility AND " + "facility_set_membership.pk_facility_set = facility_set.pk_facility_set ANd " + "facility_set.pk_facility_set = " + pk_facility_set; ResultSet rs2 = s.executeQuery(sql2); TreeSet facilitySet = new TreeSet(); while (rs2.next()) { facilitySet.add(rs2.getString(1)); } rs2.close(); return facilitySet; } finally { s.close(); } } private static class InsertRunnable implements Runnable { private final String location; private final ArrayList> facilitySets; private final AtomicInteger ai; private final CountDownLatch allThreadsReadyLatch; private final CountDownLatch startInsertLatch; public InsertRunnable(String location, ArrayList> facilitySets, CountDownLatch allThreadsReadyLatch, CountDownLatch startInsertLatch, AtomicInteger ai) { this.location = location; this.facilitySets = facilitySets; this.allThreadsReadyLatch = allThreadsReadyLatch; this.startInsertLatch = startInsertLatch; this.ai = ai; } public void run() { try { int i = ai.getAndIncrement(); TreeSet facilitySet = facilitySets.get(i); Connection c = getConnection(""); c.setAutoCommit(false); allThreadsReadyLatch.countDown(); startInsertLatch.await(); // Try to INSERT the location. try { executeUpdate(c, "INSERT INTO location (pk_location, " + "pk_facility_set, path) " + "VALUES (" + location.hashCode() + ", " + facilitySet.hashCode() + ", '" + location + "')"); } catch (java.lang.Throwable e) { // Get the location's current facility set. TreeSet currentFacilitySet = getLocationFacilitySet(c, location); // Get the union of the current and the input // facility set. TreeSet unionFacilitySet = new TreeSet(); unionFacilitySet.addAll(facilitySet); unionFacilitySet.addAll(currentFacilitySet); // If the two sets are different, then add the // union facility set to the database and upate // the foreign key for the location. if (unionFacilitySet != currentFacilitySet) { insertFacilitySet(c, unionFacilitySet); executeUpdate(c, "UPDATE location " + "SET pk_facility_set = " + unionFacilitySet.hashCode() + " WHERE pk_location = " + location.hashCode() + " AND pk_facility_set = " + currentFacilitySet.hashCode()); } } c.commit(); System.out.println(Thread.currentThread().toString() + " OK"); } catch (java.lang.InterruptedException e) { } catch (java.sql.SQLException e) { } } }; public static void main(String[] args) throws java.lang.ClassNotFoundException, java.lang.InterruptedException, java.sql.SQLException { System.setProperty("derby.locks.deadlockTrace", "true"); System.setProperty("derby.locks.monitor", "true"); System.setProperty("derby.locks.waitTimeout", "-1"); Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); // Class.forName("org.apache.derby.jdbc.ClientDriver"); System.out.println("Creating schema."); createSchema(); String location = "/path/to/foobar"; final int numberThreads = 500; // Create a list of facilities. ArrayList facilityCodes = new ArrayList(); for (int i = 0; i < numberThreads; ++i) { String code = String.format("%03d", i); facilityCodes.add(code); }; // Create a list of facility sets. ArrayList> facilitySets = new ArrayList>(); for (String code : facilityCodes) { TreeSet fs = new TreeSet(); fs.add(code); facilitySets.add(fs); } // Populate the facility table. populateFacilityTable(facilityCodes); // Populate the facility set table. populateFacilitySetTable(facilitySets); CountDownLatch allThreadsReadyLatch = new CountDownLatch(numberThreads); CountDownLatch startInsertLatch = new CountDownLatch(1); AtomicInteger ai = new AtomicInteger(0); // Start all the threads. System.out.println("Starting " + numberThreads + " threads."); ArrayList threadList = new ArrayList(numberThreads); for (int i = 0; i < numberThreads; ++i) { Thread t = new Thread(new InsertRunnable(location, facilitySets, allThreadsReadyLatch, startInsertLatch, ai)); t.start(); threadList.add(t); } // Wait for all the threads to be ready to start. System.out.println("Waiting for " + numberThreads + " threads to be ready"); allThreadsReadyLatch.await(); // Signal all the threads to start the test. System.out.println("Signaling " + numberThreads + " threads to start INSERTing"); startInsertLatch.countDown(); // Join on all the threads. System.out.println("Joining on " + numberThreads + " threads"); for (Thread t : threadList) { t.join(); System.out.println("Joined on " + t); } System.out.println("Joins complete"); { Connection c = getConnection(""); TreeSet facilitySet = getLocationFacilitySet(c, location); if (facilitySet.size() == numberThreads) { System.out.println("Final location has the expected " + "facility set with " + facilitySet.size() + " members."); } else { throw new java.lang.RuntimeException("Final location does " + "have the expected " + "facility set with " + facilitySet.size() + " members."); } } try { java.sql.DriverManager.getConnection("jdbc:derby:;shutdown=true"); } catch (java.sql.SQLException e) { } } } --------------010609050304090401000009--