Derby
  1. Derby
  2. DERBY-3678

StackOverflowException in deadlock trace

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.3.2.1
    • Fix Version/s: 10.5.1.1
    • Component/s: SQL
    • Labels:
      None
    • Environment:
      (this is actually in version 10.3.2.2)
      MacOS 10, JDK 1.6

      Description

      I am getting a deadlock in SYSTABLE. When I turn on Dderby.locks.deadlockTrace=true, I get a StackOverflowException

      Derby version The Apache Software Foundation - Apache Derby - 10.3.2.2

      • (618335): instance 80220011-0119-f93f-b912-00000000bced
        on database directory /db/domains/geoff

      Database Class Loader started - derby.database.classpath=''
      2008-05-17 23:44:36.380
      GMT Thread[btpool0-2,5,main] (XID = 7556), (SESSIONID = 4), (DATABASE =
      domains/geoff), (DRDAID = null), Cleanup action starting
      java.lang.StackOverflowError
      at org.apache.derby.impl.sql.execute.GenericExecutionFactory.getValueRow(Unknown Source)
      at org.apache.derby.impl.sql.catalog.SYSCONGLOMERATESRowFactory.makeRow(Unknown Source)
      at org.apache.derby.impl.sql.catalog.SYSCONGLOMERATESRowFactory.makeEmptyRow(Unknown
      Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.hashAllConglomerateDescriptorsByNumber(Unknown
      Source)
      at org.apache.derby.impl.services.locks.TableNameInfo.<init>(Unknown Source)
      at org.apache.derby.impl.services.locks.Timeout.buildLockTableString(Unknown Source)
      at org.apache.derby.impl.services.locks.Timeout.createException(Unknown Source)
      at org.apache.derby.impl.services.locks.Timeout.buildException(Unknown Source)
      at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source)
      at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
      at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)
      at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForRead(Unknown Source)
      at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)
      at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)
      at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(Unknown
      Source)
      at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(Unknown
      Source)
      at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(Unknown
      Source)
      at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(Unknown Source)
      at org.apache.derby.impl.store.access.btree.BTreeScan.next(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getDescriptorViaIndex(Unknown
      Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.locateSchemaRow(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getSchemaDescriptor(Unknown
      Source)
      at org.apache.derby.impl.sql.catalog.SYSTABLESRowFactory.buildDescriptor(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.hashAllTableDescriptorsByTableId(Unknown
      Source)
      at org.apache.derby.impl.services.locks.TableNameInfo.<init>(Unknown Source)
      at org.apache.derby.impl.services.locks.Timeout.buildLockTableString(Unknown Source)
      at org.apache.derby.impl.services.locks.Timeout.createException(Unknown Source)
      at org.apache.derby.impl.services.locks.Timeout.buildException(Unknown Source)
      at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source)
      at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
      at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)
      at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForRead(Unknown Source)
      at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)
      at org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown Source)
      at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(Unknown
      Source)
      at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(Unknown
      Source)
      at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(Unknown
      Source)
      at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(Unknown Source)
      at org.apache.derby.impl.store.access.btree.BTreeScan.next(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getDescriptorViaIndex(Unknown
      Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.locateSchemaRow(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getSchemaDescriptor(Unknown
      Source)
      at org.apache.derby.impl.sql.catalog.SYSTABLESRowFactory.buildDescriptor(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.hashAllTableDescriptorsByTableId(Unknown
      Source)

      1. derby-3678-1.diff
        13 kB
        Dag H. Wanvik
      2. derby-3678-1.stat
        0.4 kB
        Dag H. Wanvik
      3. derby-3678-2.diff
        18 kB
        Dag H. Wanvik
      4. derby-3678-2.stat
        0.4 kB
        Dag H. Wanvik
      5. derby-3678-3.diff
        18 kB
        Dag H. Wanvik
      6. derby-3678-3.stat
        0.4 kB
        Dag H. Wanvik

        Issue Links

          Activity

          Hide
          Knut Anders Hatlen added a comment -

          Bryan Pendleton said this about the problem on derby-user (http://mail-archives.apache.org/mod_mbox/db-derby-user/200805.mbox/%3c48304502.8050602@amberpoint.com%3e):

          > 2) When the deadlock happens, the lock table tracing logic that is run
          > by derby.locks.deadlockTrace is itself encountering the same lock
          > problem, only that code has a bug and as you say you get stuck in an
          > infinite recursion:
          > - got a deadlock, which causes
          > - deadlockTrace code to run, which
          > - get a deadlock, which causes
          > - deadlockTrace code to run, which
          > - get a deadlock, which causes ...
          > and so forth.

          I think that's a correct observation (except it's not clear to me if it's a lock timeout or a deadlock). From the stack trace, it seems like we fail to get the scan protection lock on an index page for the SYS.SYSSCHEMAS table. That probably means that one thread is holding an exclusive lock on the scan protection row. Not sure how that could happen. Could be an index split deadlock (DERBY-2991), but that doesn't sound very likely since this is the SYSSCHEMAS table. Or do you have multiple threads creating lots of schemas?

          Show
          Knut Anders Hatlen added a comment - Bryan Pendleton said this about the problem on derby-user ( http://mail-archives.apache.org/mod_mbox/db-derby-user/200805.mbox/%3c48304502.8050602@amberpoint.com%3e): > 2) When the deadlock happens, the lock table tracing logic that is run > by derby.locks.deadlockTrace is itself encountering the same lock > problem, only that code has a bug and as you say you get stuck in an > infinite recursion: > - got a deadlock, which causes > - deadlockTrace code to run, which > - get a deadlock, which causes > - deadlockTrace code to run, which > - get a deadlock, which causes ... > and so forth. I think that's a correct observation (except it's not clear to me if it's a lock timeout or a deadlock). From the stack trace, it seems like we fail to get the scan protection lock on an index page for the SYS.SYSSCHEMAS table. That probably means that one thread is holding an exclusive lock on the scan protection row. Not sure how that could happen. Could be an index split deadlock ( DERBY-2991 ), but that doesn't sound very likely since this is the SYSSCHEMAS table. Or do you have multiple threads creating lots of schemas?
          Hide
          geoff hendrey added a comment -

          "Or do you have multiple threads creating lots of schemas?"
          I'm not creating any schemas at the time this problem happens.

          I will try to describe what I am doing, as background. There are two databases, naturally each has a different connection URL. Let's call them Database A and Database B. I read in a configuration file that describes a set of tables in Database A, and then I create those tables, and store some information about them in Database B.

          1) define tables in Database A
          2) store some information about tables in Database A in a table in Database B
          3) alter tables in Database A to add a named foreign key constraint to some of the tabes
          4) store some more information about tables in A into a table in Database B

          The problem only occurs on step 4, and it only occurs when there are 9 insertions into Database B as part of step (4). If I remove a single item from my configuration file, so that step (4) only processes 8 items, there is no problem.

          Here is the trace from derby.language.logQueryPlan. I excerpted only the portions related to "SYS....". There are two groups of relevant trace, and I separated them with "=================" in the cut-and-paste that follows. The lock timeout (or StackOverflowException if I turn on derby.locks.deadlockTrace) occurs after the second set of information in the logQueryPlan.

          2008-05-18 19:24:52.764 GMT Thread[btpool0-4,5,main] (XID = 8142), (SESSIONID = 2), EXECUTE STATEMENT SYS."getTables" ******* Sort ResultSet:
          Number of opens = 1
          Rows input = 13
          Rows returned = 13
          Eliminate duplicates = false
          In sorted order = false
          Sort information:
          Number of rows input=13
          Number of rows output=13
          Sort type=internal
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 5.71

          Source result set:
          Project-Restrict ResultSet (20):
          Number of opens = 1
          Rows seen = 13
          Rows filtered = 0
          restriction = false
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 5.71

          Source result set:
          Nested Loop Join ResultSet:
          Number of opens = 1
          Rows seen from the left = 13
          Rows seen from the right = 13
          Rows filtered = 0
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 5.71

          Left result set:
          Nested Loop Exists Join ResultSet:
          Number of opens = 1
          Rows seen from the left = 13
          Rows seen from the right = 13
          Rows filtered = 0
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 5.71

          Left result set:
          Project-Restrict ResultSet (5):
          Number of opens = 1
          Rows seen = 32
          Rows filtered = 19
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 5.43

          Source result set:
          Index Row to Base Row ResultSet for SYSTABLES:
          Number of opens = 1
          Rows seen = 32
          Columns accessed from heap =

          {1, 2, 3}
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 5.43

          Index Scan ResultSet for SYSTABLES using index SYSTABLES_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 32
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched={0, 2}
          Number of columns fetched=2
          Number of deleted rows visited=8
          Number of pages visited=1
          Number of rows qualified=32
          Number of rows visited=40
          Scan type=btree
          Tree height=1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          stop position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          qualifiers:
          None
          optimizer estimated row count: 0.06
          optimizer estimated cost: 5.43


          Right result set:
          Project-Restrict ResultSet (8):
          Number of opens = 13
          Rows seen = 13
          Rows filtered = 0
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.27

          Source result set:
          Index Row to Base Row ResultSet for SYSSCHEMAS:
          Number of opens = 13
          Rows seen = 13
          Columns accessed from heap = {1}
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.27

          Index Scan ResultSet for SYSSCHEMAS using index SYSSCHEMAS_INDEX2 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 13
          Rows seen = 13
          Rows filtered = 0
          Fetch Size = 1
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=2
          Number of deleted rows visited=0
          Number of pages visited=13
          Number of rows qualified=13
          Number of rows visited=13
          Scan type=btree
          Tree height=1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:
          0
          stop position:
          > on first 1 column(s).
          Ordered null semantics on the following columns:
          0
          qualifiers:
          None
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.27



          Right result set:
          Project-Restrict ResultSet (19):
          Number of opens = 13
          Rows seen = 52
          Rows filtered = 39
          restriction = true
          projection = false
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 0.00

          Source result set:
          Union ResultSet:
          Number of opens = 13
          Rows seen from the left = 39
          Rows seen from the right = 13
          Rows returned = 52
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 0.00

          Left result set:
          Union ResultSet:
          Number of opens = 13
          Rows seen from the left = 26
          Rows seen from the right = 13
          Rows returned = 39
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 0.00

          Left result set:
          Union ResultSet:
          Number of opens = 13
          Rows seen from the left = 13
          Rows seen from the right = 13
          Rows returned = 26
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.12
          optimizer estimated cost: 0.00

          Left result set:
          Normalize ResultSet:
          Number of opens = 13
          Rows seen = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.12
          optimizer estimated cost: 0.00

          Source result set:
          Row ResultSet:
          Number of opens = 13
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.00



          Right result set:
          Row ResultSet:
          Number of opens = 13
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.00



          Right result set:
          Normalize ResultSet:
          Number of opens = 13
          Rows seen = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 0.00

          Source result set:
          Row ResultSet:
          Number of opens = 13
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.00




          Right result set:
          Normalize ResultSet:
          Number of opens = 13
          Rows seen = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 0.00

          Source result set:
          Row ResultSet:
          Number of opens = 13
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.00






          2008-05-18 19:24:52.848 GMT Thread[btpool0-4,5,main] (XID = 8145), (SESSIONID = 2), EXECUTE STATEMENT SYS."getColumns" ******* Sort ResultSet:
          Number of opens = 1
          Rows input = 6
          Rows returned = 6
          Eliminate duplicates = false
          In sorted order = false
          Sort information:
          Number of rows input=6
          Number of rows output=6
          Sort type=internal
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 7.30

          Source result set:
          Project-Restrict ResultSet (12):
          Number of opens = 1
          Rows seen = 6
          Rows filtered = 0
          restriction = false
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 7.30

          Source result set:
          Nested Loop Join ResultSet:
          Number of opens = 1
          Rows seen from the left = 1
          Rows seen from the right = 6
          Rows filtered = 0
          Rows returned = 6
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 7.30

          Left result set:
          Nested Loop Join ResultSet:
          Number of opens = 1
          Rows seen from the left = 15
          Rows seen from the right = 1
          Rows filtered = 0
          Rows returned = 1
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.05
          optimizer estimated cost: 6.22

          Left result set:
          Project-Restrict ResultSet (5):
          Number of opens = 1
          Rows seen = 15
          Rows filtered = 0
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.43
          optimizer estimated cost: 4.99

          Source result set:
          Index Row to Base Row ResultSet for SYSSCHEMAS:
          Number of opens = 1
          Rows seen = 15
          Columns accessed from heap = {0, 1}
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.43
          optimizer estimated cost: 4.99

          Index Scan ResultSet for SYSSCHEMAS using index SYSSCHEMAS_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 15
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=2
          Number of deleted rows visited=12
          Number of pages visited=1
          Number of rows qualified=15
          Number of rows visited=27
          Scan type=btree
          Tree height=1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          stop position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          qualifiers:
          None
          optimizer estimated row count: 0.43
          optimizer estimated cost: 4.99


          Right result set:
          Project-Restrict ResultSet (8):
          Number of opens = 15
          Rows seen = 13
          Rows filtered = 12
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.05
          optimizer estimated cost: 1.23

          Source result set:
          Index Row to Base Row ResultSet for SYSTABLES:
          Number of opens = 15
          Rows seen = 13
          Columns accessed from heap = {0, 1, 3}
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.05
          optimizer estimated cost: 1.23

          Index Scan ResultSet for SYSTABLES using index SYSTABLES_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 15
          Rows seen = 13
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=3
          Number of deleted rows visited=120
          Number of pages visited=15
          Number of rows qualified=13
          Number of rows visited=330
          Scan type=btree
          Tree height=1
          start position:
          >= on first 2 column(s).
          Ordered null semantics on the following columns:
          1
          stop position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          qualifiers:
          Column[0][0] Id: 1
          Operator: =
          Ordered nulls: false
          Unknown return value: false
          Negate comparison result: false

          optimizer estimated row count: 0.05
          optimizer estimated cost: 1.23



          Right result set:
          Project-Restrict ResultSet (11):
          Number of opens = 1
          Rows seen = 6
          Rows filtered = 0
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 1.08

          Source result set:
          Index Row to Base Row ResultSet for SYSCOLUMNS:
          Number of opens = 1
          Rows seen = 6
          Columns accessed from heap = {0, 1, 2, 3, 4, 7, 8}
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 1.08

          Index Scan ResultSet for SYSCOLUMNS using index SYSCOLUMNS_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 6
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=3
          Number of deleted rows visited=0
          Number of pages visited=2
          Number of rows qualified=6
          Number of rows visited=7
          Scan type=btree
          Tree height=2
          start position:
          >= on first 2 column(s).
          Ordered null semantics on the following columns:
          0
          stop position:
          >= on first 2 column(s).
          Ordered null semantics on the following columns:
          0
          qualifiers:
          None
          optimizer estimated row count: 0.18
          optimizer estimated cost: 1.08




          2008-05-18 19:24:52.891 GMT Thread[btpool0-4,5,main] (XID = 8148), (SESSIONID = 3), SELECT CONSTRAINTNAME FROM SYS.SYSCONSTRAINTS ******* Index Scan ResultSet for SYSCONSTRAINTS using index SYSCONSTRAINTS_INDEX2 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 24
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched={0}
          Number of columns fetched=1
          Number of deleted rows visited=20
          Number of pages visited=3
          Number of rows qualified=24
          Number of rows visited=44
          Scan type=btree
          Tree height=-1
          start position:
          None
          stop position:
          None
          qualifiers:
          None
          optimizer estimated row count: 43.00
          optimizer estimated cost: 61.46





          ==========================



          2008-05-18 19:40:06.154 GMT Thread[btpool0-4,5,main] (XID = 8189), (SESSIONID = 2), EXECUTE STATEMENT SYS."getTables" ******* Sort ResultSet:
          Number of opens = 1
          Rows input = 13
          Rows returned = 13
          Eliminate duplicates = false
          In sorted order = false
          Sort information:
          Number of rows input=13
          Number of rows output=13
          Sort type=internal
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 5.71

          Source result set:
          Project-Restrict ResultSet (20):
          Number of opens = 1
          Rows seen = 13
          Rows filtered = 0
          restriction = false
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 5.71

          Source result set:
          Nested Loop Join ResultSet:
          Number of opens = 1
          Rows seen from the left = 13
          Rows seen from the right = 13
          Rows filtered = 0
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 5.71

          Left result set:
          Nested Loop Exists Join ResultSet:
          Number of opens = 1
          Rows seen from the left = 13
          Rows seen from the right = 13
          Rows filtered = 0
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 5.71

          Left result set:
          Project-Restrict ResultSet (5):
          Number of opens = 1
          Rows seen = 32
          Rows filtered = 19
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 5.43

          Source result set:
          Index Row to Base Row ResultSet for SYSTABLES:
          Number of opens = 1
          Rows seen = 32
          Columns accessed from heap = {1, 2, 3}

          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 5.43

          Index Scan ResultSet for SYSTABLES using index SYSTABLES_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 32
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=

          {0, 2}

          Number of columns fetched=2
          Number of deleted rows visited=8
          Number of pages visited=1
          Number of rows qualified=32
          Number of rows visited=40
          Scan type=btree
          Tree height=1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          stop position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          qualifiers:
          None
          optimizer estimated row count: 0.06
          optimizer estimated cost: 5.43

          Right result set:
          Project-Restrict ResultSet (8):
          Number of opens = 13
          Rows seen = 13
          Rows filtered = 0
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.27

          Source result set:
          Index Row to Base Row ResultSet for SYSSCHEMAS:
          Number of opens = 13
          Rows seen = 13
          Columns accessed from heap =

          {1}

          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.27

          Index Scan ResultSet for SYSSCHEMAS using index SYSSCHEMAS_INDEX2 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 13
          Rows seen = 13
          Rows filtered = 0
          Fetch Size = 1
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=2
          Number of deleted rows visited=0
          Number of pages visited=13
          Number of rows qualified=13
          Number of rows visited=13
          Scan type=btree
          Tree height=1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:
          0
          stop position:
          > on first 1 column(s).
          Ordered null semantics on the following columns:
          0
          qualifiers:
          None
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.27

          Right result set:
          Project-Restrict ResultSet (19):
          Number of opens = 13
          Rows seen = 52
          Rows filtered = 39
          restriction = true
          projection = false
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 0.00

          Source result set:
          Union ResultSet:
          Number of opens = 13
          Rows seen from the left = 39
          Rows seen from the right = 13
          Rows returned = 52
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 0.00

          Left result set:
          Union ResultSet:
          Number of opens = 13
          Rows seen from the left = 26
          Rows seen from the right = 13
          Rows returned = 39
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 0.00

          Left result set:
          Union ResultSet:
          Number of opens = 13
          Rows seen from the left = 13
          Rows seen from the right = 13
          Rows returned = 26
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.12
          optimizer estimated cost: 0.00

          Left result set:
          Normalize ResultSet:
          Number of opens = 13
          Rows seen = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.12
          optimizer estimated cost: 0.00

          Source result set:
          Row ResultSet:
          Number of opens = 13
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.00

          Right result set:
          Row ResultSet:
          Number of opens = 13
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.00

          Right result set:
          Normalize ResultSet:
          Number of opens = 13
          Rows seen = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 0.00

          Source result set:
          Row ResultSet:
          Number of opens = 13
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.00

          Right result set:
          Normalize ResultSet:
          Number of opens = 13
          Rows seen = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.24
          optimizer estimated cost: 0.00

          Source result set:
          Row ResultSet:
          Number of opens = 13
          Rows returned = 13
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.06
          optimizer estimated cost: 0.00

          2008-05-18 19:40:06.201 GMT Thread[btpool0-4,5,main] (XID = 8191), (SESSIONID = 2), EXECUTE STATEMENT SYS."getColumns" ******* Sort ResultSet:
          Number of opens = 1
          Rows input = 6
          Rows returned = 6
          Eliminate duplicates = false
          In sorted order = false
          Sort information:
          Number of rows input=6
          Number of rows output=6
          Sort type=internal
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 7.30

          Source result set:
          Project-Restrict ResultSet (12):
          Number of opens = 1
          Rows seen = 6
          Rows filtered = 0
          restriction = false
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 7.30

          Source result set:
          Nested Loop Join ResultSet:
          Number of opens = 1
          Rows seen from the left = 1
          Rows seen from the right = 6
          Rows filtered = 0
          Rows returned = 6
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 7.30

          Left result set:
          Nested Loop Join ResultSet:
          Number of opens = 1
          Rows seen from the left = 15
          Rows seen from the right = 1
          Rows filtered = 0
          Rows returned = 1
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.05
          optimizer estimated cost: 6.22

          Left result set:
          Project-Restrict ResultSet (5):
          Number of opens = 1
          Rows seen = 15
          Rows filtered = 0
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.43
          optimizer estimated cost: 4.99

          Source result set:
          Index Row to Base Row ResultSet for SYSSCHEMAS:
          Number of opens = 1
          Rows seen = 15
          Columns accessed from heap =

          {0, 1}

          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.43
          optimizer estimated cost: 4.99

          Index Scan ResultSet for SYSSCHEMAS using index SYSSCHEMAS_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 15
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=2
          Number of deleted rows visited=12
          Number of pages visited=1
          Number of rows qualified=15
          Number of rows visited=27
          Scan type=btree
          Tree height=1
          start position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          stop position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          qualifiers:
          None
          optimizer estimated row count: 0.43
          optimizer estimated cost: 4.99

          Right result set:
          Project-Restrict ResultSet (8):
          Number of opens = 15
          Rows seen = 13
          Rows filtered = 12
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.05
          optimizer estimated cost: 1.23

          Source result set:
          Index Row to Base Row ResultSet for SYSTABLES:
          Number of opens = 15
          Rows seen = 13
          Columns accessed from heap =

          {0, 1, 3}

          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.05
          optimizer estimated cost: 1.23

          Index Scan ResultSet for SYSTABLES using index SYSTABLES_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 15
          Rows seen = 13
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=3
          Number of deleted rows visited=120
          Number of pages visited=15
          Number of rows qualified=13
          Number of rows visited=330
          Scan type=btree
          Tree height=1
          start position:
          >= on first 2 column(s).
          Ordered null semantics on the following columns:
          1
          stop position:
          >= on first 1 column(s).
          Ordered null semantics on the following columns:

          qualifiers:
          Column[0][0] Id: 1
          Operator: =
          Ordered nulls: false
          Unknown return value: false
          Negate comparison result: false

          optimizer estimated row count: 0.05
          optimizer estimated cost: 1.23

          Right result set:
          Project-Restrict ResultSet (11):
          Number of opens = 1
          Rows seen = 6
          Rows filtered = 0
          restriction = true
          projection = true
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          restriction time (milliseconds) = 0
          projection time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 1.08

          Source result set:
          Index Row to Base Row ResultSet for SYSCOLUMNS:
          Number of opens = 1
          Rows seen = 6
          Columns accessed from heap =

          {0, 1, 2, 3, 4, 7, 8}

          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          optimizer estimated row count: 0.18
          optimizer estimated cost: 1.08

          Index Scan ResultSet for SYSCOLUMNS using index SYSCOLUMNS_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 6
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=All
          Number of columns fetched=3
          Number of deleted rows visited=0
          Number of pages visited=3
          Number of rows qualified=6
          Number of rows visited=7
          Scan type=btree
          Tree height=2
          start position:
          >= on first 2 column(s).
          Ordered null semantics on the following columns:
          0
          stop position:
          >= on first 2 column(s).
          Ordered null semantics on the following columns:
          0
          qualifiers:
          None
          optimizer estimated row count: 0.18
          optimizer estimated cost: 1.08

          2008-05-18 19:40:06.219 GMT Thread[btpool0-4,5,main] (XID = 8193), (SESSIONID = 3), SELECT CONSTRAINTNAME FROM SYS.SYSCONSTRAINTS ******* Index Scan ResultSet for SYSCONSTRAINTS using index SYSCONSTRAINTS_INDEX2 at read uncommitted isolation level using share row locking chosen by the optimizer
          Number of opens = 1
          Rows seen = 24
          Rows filtered = 0
          Fetch Size = 16
          constructor time (milliseconds) = 0
          open time (milliseconds) = 0
          next time (milliseconds) = 0
          close time (milliseconds) = 0
          next time in milliseconds/row = 0

          scan information:
          Bit set of columns fetched=

          {0}

          Number of columns fetched=1
          Number of deleted rows visited=24
          Number of pages visited=3
          Number of rows qualified=24
          Number of rows visited=48
          Scan type=btree
          Tree height=-1
          start position:
          None
          stop position:
          None
          qualifiers:
          None
          optimizer estimated row count: 26.00
          optimizer estimated cost: 59.49

          Show
          geoff hendrey added a comment - "Or do you have multiple threads creating lots of schemas?" I'm not creating any schemas at the time this problem happens. I will try to describe what I am doing, as background. There are two databases, naturally each has a different connection URL. Let's call them Database A and Database B. I read in a configuration file that describes a set of tables in Database A, and then I create those tables, and store some information about them in Database B. 1) define tables in Database A 2) store some information about tables in Database A in a table in Database B 3) alter tables in Database A to add a named foreign key constraint to some of the tabes 4) store some more information about tables in A into a table in Database B The problem only occurs on step 4, and it only occurs when there are 9 insertions into Database B as part of step (4). If I remove a single item from my configuration file, so that step (4) only processes 8 items, there is no problem. Here is the trace from derby.language.logQueryPlan. I excerpted only the portions related to "SYS....". There are two groups of relevant trace, and I separated them with "=================" in the cut-and-paste that follows. The lock timeout (or StackOverflowException if I turn on derby.locks.deadlockTrace) occurs after the second set of information in the logQueryPlan. 2008-05-18 19:24:52.764 GMT Thread [btpool0-4,5,main] (XID = 8142), (SESSIONID = 2), EXECUTE STATEMENT SYS."getTables" ******* Sort ResultSet: Number of opens = 1 Rows input = 13 Rows returned = 13 Eliminate duplicates = false In sorted order = false Sort information: Number of rows input=13 Number of rows output=13 Sort type=internal constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 5.71 Source result set: Project-Restrict ResultSet (20): Number of opens = 1 Rows seen = 13 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 5.71 Source result set: Nested Loop Join ResultSet: Number of opens = 1 Rows seen from the left = 13 Rows seen from the right = 13 Rows filtered = 0 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 5.71 Left result set: Nested Loop Exists Join ResultSet: Number of opens = 1 Rows seen from the left = 13 Rows seen from the right = 13 Rows filtered = 0 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 5.71 Left result set: Project-Restrict ResultSet (5): Number of opens = 1 Rows seen = 32 Rows filtered = 19 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 5.43 Source result set: Index Row to Base Row ResultSet for SYSTABLES: Number of opens = 1 Rows seen = 32 Columns accessed from heap = {1, 2, 3} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 5.43 Index Scan ResultSet for SYSTABLES using index SYSTABLES_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 32 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched={0, 2} Number of columns fetched=2 Number of deleted rows visited=8 Number of pages visited=1 Number of rows qualified=32 Number of rows visited=40 Scan type=btree Tree height=1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: stop position: >= on first 1 column(s). Ordered null semantics on the following columns: qualifiers: None optimizer estimated row count: 0.06 optimizer estimated cost: 5.43 Right result set: Project-Restrict ResultSet (8): Number of opens = 13 Rows seen = 13 Rows filtered = 0 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.27 Source result set: Index Row to Base Row ResultSet for SYSSCHEMAS: Number of opens = 13 Rows seen = 13 Columns accessed from heap = {1} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.27 Index Scan ResultSet for SYSSCHEMAS using index SYSSCHEMAS_INDEX2 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 13 Rows seen = 13 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=2 Number of deleted rows visited=0 Number of pages visited=13 Number of rows qualified=13 Number of rows visited=13 Scan type=btree Tree height=1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: 0 stop position: > on first 1 column(s). Ordered null semantics on the following columns: 0 qualifiers: None optimizer estimated row count: 0.06 optimizer estimated cost: 0.27 Right result set: Project-Restrict ResultSet (19): Number of opens = 13 Rows seen = 52 Rows filtered = 39 restriction = true projection = false constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 0.00 Source result set: Union ResultSet: Number of opens = 13 Rows seen from the left = 39 Rows seen from the right = 13 Rows returned = 52 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 0.00 Left result set: Union ResultSet: Number of opens = 13 Rows seen from the left = 26 Rows seen from the right = 13 Rows returned = 39 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 0.00 Left result set: Union ResultSet: Number of opens = 13 Rows seen from the left = 13 Rows seen from the right = 13 Rows returned = 26 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.12 optimizer estimated cost: 0.00 Left result set: Normalize ResultSet: Number of opens = 13 Rows seen = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.12 optimizer estimated cost: 0.00 Source result set: Row ResultSet: Number of opens = 13 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.00 Right result set: Row ResultSet: Number of opens = 13 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.00 Right result set: Normalize ResultSet: Number of opens = 13 Rows seen = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 0.00 Source result set: Row ResultSet: Number of opens = 13 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.00 Right result set: Normalize ResultSet: Number of opens = 13 Rows seen = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 0.00 Source result set: Row ResultSet: Number of opens = 13 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.00 2008-05-18 19:24:52.848 GMT Thread [btpool0-4,5,main] (XID = 8145), (SESSIONID = 2), EXECUTE STATEMENT SYS."getColumns" ******* Sort ResultSet: Number of opens = 1 Rows input = 6 Rows returned = 6 Eliminate duplicates = false In sorted order = false Sort information: Number of rows input=6 Number of rows output=6 Sort type=internal constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 7.30 Source result set: Project-Restrict ResultSet (12): Number of opens = 1 Rows seen = 6 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 7.30 Source result set: Nested Loop Join ResultSet: Number of opens = 1 Rows seen from the left = 1 Rows seen from the right = 6 Rows filtered = 0 Rows returned = 6 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 7.30 Left result set: Nested Loop Join ResultSet: Number of opens = 1 Rows seen from the left = 15 Rows seen from the right = 1 Rows filtered = 0 Rows returned = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.05 optimizer estimated cost: 6.22 Left result set: Project-Restrict ResultSet (5): Number of opens = 1 Rows seen = 15 Rows filtered = 0 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.43 optimizer estimated cost: 4.99 Source result set: Index Row to Base Row ResultSet for SYSSCHEMAS: Number of opens = 1 Rows seen = 15 Columns accessed from heap = {0, 1} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.43 optimizer estimated cost: 4.99 Index Scan ResultSet for SYSSCHEMAS using index SYSSCHEMAS_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 15 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=2 Number of deleted rows visited=12 Number of pages visited=1 Number of rows qualified=15 Number of rows visited=27 Scan type=btree Tree height=1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: stop position: >= on first 1 column(s). Ordered null semantics on the following columns: qualifiers: None optimizer estimated row count: 0.43 optimizer estimated cost: 4.99 Right result set: Project-Restrict ResultSet (8): Number of opens = 15 Rows seen = 13 Rows filtered = 12 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.05 optimizer estimated cost: 1.23 Source result set: Index Row to Base Row ResultSet for SYSTABLES: Number of opens = 15 Rows seen = 13 Columns accessed from heap = {0, 1, 3} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.05 optimizer estimated cost: 1.23 Index Scan ResultSet for SYSTABLES using index SYSTABLES_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 15 Rows seen = 13 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=3 Number of deleted rows visited=120 Number of pages visited=15 Number of rows qualified=13 Number of rows visited=330 Scan type=btree Tree height=1 start position: >= on first 2 column(s). Ordered null semantics on the following columns: 1 stop position: >= on first 1 column(s). Ordered null semantics on the following columns: qualifiers: Column [0] [0] Id: 1 Operator: = Ordered nulls: false Unknown return value: false Negate comparison result: false optimizer estimated row count: 0.05 optimizer estimated cost: 1.23 Right result set: Project-Restrict ResultSet (11): Number of opens = 1 Rows seen = 6 Rows filtered = 0 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 1.08 Source result set: Index Row to Base Row ResultSet for SYSCOLUMNS: Number of opens = 1 Rows seen = 6 Columns accessed from heap = {0, 1, 2, 3, 4, 7, 8} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 1.08 Index Scan ResultSet for SYSCOLUMNS using index SYSCOLUMNS_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 6 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=3 Number of deleted rows visited=0 Number of pages visited=2 Number of rows qualified=6 Number of rows visited=7 Scan type=btree Tree height=2 start position: >= on first 2 column(s). Ordered null semantics on the following columns: 0 stop position: >= on first 2 column(s). Ordered null semantics on the following columns: 0 qualifiers: None optimizer estimated row count: 0.18 optimizer estimated cost: 1.08 2008-05-18 19:24:52.891 GMT Thread [btpool0-4,5,main] (XID = 8148), (SESSIONID = 3), SELECT CONSTRAINTNAME FROM SYS.SYSCONSTRAINTS ******* Index Scan ResultSet for SYSCONSTRAINTS using index SYSCONSTRAINTS_INDEX2 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 24 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched={0} Number of columns fetched=1 Number of deleted rows visited=20 Number of pages visited=3 Number of rows qualified=24 Number of rows visited=44 Scan type=btree Tree height=-1 start position: None stop position: None qualifiers: None optimizer estimated row count: 43.00 optimizer estimated cost: 61.46 ========================== 2008-05-18 19:40:06.154 GMT Thread [btpool0-4,5,main] (XID = 8189), (SESSIONID = 2), EXECUTE STATEMENT SYS."getTables" ******* Sort ResultSet: Number of opens = 1 Rows input = 13 Rows returned = 13 Eliminate duplicates = false In sorted order = false Sort information: Number of rows input=13 Number of rows output=13 Sort type=internal constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 5.71 Source result set: Project-Restrict ResultSet (20): Number of opens = 1 Rows seen = 13 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 5.71 Source result set: Nested Loop Join ResultSet: Number of opens = 1 Rows seen from the left = 13 Rows seen from the right = 13 Rows filtered = 0 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 5.71 Left result set: Nested Loop Exists Join ResultSet: Number of opens = 1 Rows seen from the left = 13 Rows seen from the right = 13 Rows filtered = 0 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 5.71 Left result set: Project-Restrict ResultSet (5): Number of opens = 1 Rows seen = 32 Rows filtered = 19 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 5.43 Source result set: Index Row to Base Row ResultSet for SYSTABLES: Number of opens = 1 Rows seen = 32 Columns accessed from heap = {1, 2, 3} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 5.43 Index Scan ResultSet for SYSTABLES using index SYSTABLES_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 32 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched= {0, 2} Number of columns fetched=2 Number of deleted rows visited=8 Number of pages visited=1 Number of rows qualified=32 Number of rows visited=40 Scan type=btree Tree height=1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: stop position: >= on first 1 column(s). Ordered null semantics on the following columns: qualifiers: None optimizer estimated row count: 0.06 optimizer estimated cost: 5.43 Right result set: Project-Restrict ResultSet (8): Number of opens = 13 Rows seen = 13 Rows filtered = 0 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.27 Source result set: Index Row to Base Row ResultSet for SYSSCHEMAS: Number of opens = 13 Rows seen = 13 Columns accessed from heap = {1} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.27 Index Scan ResultSet for SYSSCHEMAS using index SYSSCHEMAS_INDEX2 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 13 Rows seen = 13 Rows filtered = 0 Fetch Size = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=2 Number of deleted rows visited=0 Number of pages visited=13 Number of rows qualified=13 Number of rows visited=13 Scan type=btree Tree height=1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: 0 stop position: > on first 1 column(s). Ordered null semantics on the following columns: 0 qualifiers: None optimizer estimated row count: 0.06 optimizer estimated cost: 0.27 Right result set: Project-Restrict ResultSet (19): Number of opens = 13 Rows seen = 52 Rows filtered = 39 restriction = true projection = false constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 0.00 Source result set: Union ResultSet: Number of opens = 13 Rows seen from the left = 39 Rows seen from the right = 13 Rows returned = 52 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 0.00 Left result set: Union ResultSet: Number of opens = 13 Rows seen from the left = 26 Rows seen from the right = 13 Rows returned = 39 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 0.00 Left result set: Union ResultSet: Number of opens = 13 Rows seen from the left = 13 Rows seen from the right = 13 Rows returned = 26 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.12 optimizer estimated cost: 0.00 Left result set: Normalize ResultSet: Number of opens = 13 Rows seen = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.12 optimizer estimated cost: 0.00 Source result set: Row ResultSet: Number of opens = 13 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.00 Right result set: Row ResultSet: Number of opens = 13 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.00 Right result set: Normalize ResultSet: Number of opens = 13 Rows seen = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 0.00 Source result set: Row ResultSet: Number of opens = 13 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.00 Right result set: Normalize ResultSet: Number of opens = 13 Rows seen = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.24 optimizer estimated cost: 0.00 Source result set: Row ResultSet: Number of opens = 13 Rows returned = 13 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.06 optimizer estimated cost: 0.00 2008-05-18 19:40:06.201 GMT Thread [btpool0-4,5,main] (XID = 8191), (SESSIONID = 2), EXECUTE STATEMENT SYS."getColumns" ******* Sort ResultSet: Number of opens = 1 Rows input = 6 Rows returned = 6 Eliminate duplicates = false In sorted order = false Sort information: Number of rows input=6 Number of rows output=6 Sort type=internal constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 7.30 Source result set: Project-Restrict ResultSet (12): Number of opens = 1 Rows seen = 6 Rows filtered = 0 restriction = false projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 7.30 Source result set: Nested Loop Join ResultSet: Number of opens = 1 Rows seen from the left = 1 Rows seen from the right = 6 Rows filtered = 0 Rows returned = 6 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 7.30 Left result set: Nested Loop Join ResultSet: Number of opens = 1 Rows seen from the left = 15 Rows seen from the right = 1 Rows filtered = 0 Rows returned = 1 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.05 optimizer estimated cost: 6.22 Left result set: Project-Restrict ResultSet (5): Number of opens = 1 Rows seen = 15 Rows filtered = 0 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.43 optimizer estimated cost: 4.99 Source result set: Index Row to Base Row ResultSet for SYSSCHEMAS: Number of opens = 1 Rows seen = 15 Columns accessed from heap = {0, 1} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.43 optimizer estimated cost: 4.99 Index Scan ResultSet for SYSSCHEMAS using index SYSSCHEMAS_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 15 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=2 Number of deleted rows visited=12 Number of pages visited=1 Number of rows qualified=15 Number of rows visited=27 Scan type=btree Tree height=1 start position: >= on first 1 column(s). Ordered null semantics on the following columns: stop position: >= on first 1 column(s). Ordered null semantics on the following columns: qualifiers: None optimizer estimated row count: 0.43 optimizer estimated cost: 4.99 Right result set: Project-Restrict ResultSet (8): Number of opens = 15 Rows seen = 13 Rows filtered = 12 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.05 optimizer estimated cost: 1.23 Source result set: Index Row to Base Row ResultSet for SYSTABLES: Number of opens = 15 Rows seen = 13 Columns accessed from heap = {0, 1, 3} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.05 optimizer estimated cost: 1.23 Index Scan ResultSet for SYSTABLES using index SYSTABLES_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 15 Rows seen = 13 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=3 Number of deleted rows visited=120 Number of pages visited=15 Number of rows qualified=13 Number of rows visited=330 Scan type=btree Tree height=1 start position: >= on first 2 column(s). Ordered null semantics on the following columns: 1 stop position: >= on first 1 column(s). Ordered null semantics on the following columns: qualifiers: Column [0] [0] Id: 1 Operator: = Ordered nulls: false Unknown return value: false Negate comparison result: false optimizer estimated row count: 0.05 optimizer estimated cost: 1.23 Right result set: Project-Restrict ResultSet (11): Number of opens = 1 Rows seen = 6 Rows filtered = 0 restriction = true projection = true constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 restriction time (milliseconds) = 0 projection time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 1.08 Source result set: Index Row to Base Row ResultSet for SYSCOLUMNS: Number of opens = 1 Rows seen = 6 Columns accessed from heap = {0, 1, 2, 3, 4, 7, 8} constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 optimizer estimated row count: 0.18 optimizer estimated cost: 1.08 Index Scan ResultSet for SYSCOLUMNS using index SYSCOLUMNS_INDEX1 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 6 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched=All Number of columns fetched=3 Number of deleted rows visited=0 Number of pages visited=3 Number of rows qualified=6 Number of rows visited=7 Scan type=btree Tree height=2 start position: >= on first 2 column(s). Ordered null semantics on the following columns: 0 stop position: >= on first 2 column(s). Ordered null semantics on the following columns: 0 qualifiers: None optimizer estimated row count: 0.18 optimizer estimated cost: 1.08 2008-05-18 19:40:06.219 GMT Thread [btpool0-4,5,main] (XID = 8193), (SESSIONID = 3), SELECT CONSTRAINTNAME FROM SYS.SYSCONSTRAINTS ******* Index Scan ResultSet for SYSCONSTRAINTS using index SYSCONSTRAINTS_INDEX2 at read uncommitted isolation level using share row locking chosen by the optimizer Number of opens = 1 Rows seen = 24 Rows filtered = 0 Fetch Size = 16 constructor time (milliseconds) = 0 open time (milliseconds) = 0 next time (milliseconds) = 0 close time (milliseconds) = 0 next time in milliseconds/row = 0 scan information: Bit set of columns fetched= {0} Number of columns fetched=1 Number of deleted rows visited=24 Number of pages visited=3 Number of rows qualified=24 Number of rows visited=48 Scan type=btree Tree height=-1 start position: None stop position: None qualifiers: None optimizer estimated row count: 26.00 optimizer estimated cost: 59.49
          Hide
          geoff hendrey added a comment -

          Any plan to investigate? this is a major issue for us. Especially if you run derby embedded, this will freeze the webserver that shares the JVM with the database. I have to "kill -9" the process, it is frozen so badly. I can gather as much information as you need to help resolve this, just tell me what you need.

          Show
          geoff hendrey added a comment - Any plan to investigate? this is a major issue for us. Especially if you run derby embedded, this will freeze the webserver that shares the JVM with the database. I have to "kill -9" the process, it is frozen so badly. I can gather as much information as you need to help resolve this, just tell me what you need.
          Hide
          Knut Anders Hatlen added a comment -

          Dag H. Wanvik posted the following comment on derby-dev:

          The following scenario creates a hang when a 2nd connection is made
          for the user "newuser":

          > java -Dij.exceptionTrace=true org.apache.derby.tools.ij

          ij> connect 'jdbc:derby:wombat;user=newuser';
          – no schema is yet created for newuser.
          ij> autocommit off;
          ij> create table i (i int); – the schema is only created for 'newuser' at this point
          0 rows inserted/updated/deleted

          Notice that this session has not yet committed... now we make a new
          session with the same user:

          ij> connect 'jdbc:derby:wombat;user=newuser';
          ERROR 40XL1: A lock could not be obtained within the time requested

          Might this be what happens for you? The first time a new user
          connects and creates a database object, his schema will be
          created. But until that session commits, another session cannot login
          with the same user name, since the new entry in SYSSCHEMAS
          corresponding to the new user's schema has not been committed either
          (it has a write lock on it so it can't be read by the second session).

          Note, even if you don't use explicit users, there will still be be an
          implicit user, so the same thing applies.

          Dag

          ERROR 40XL1: A lock could not be obtained within the time requested
          (full stack trace I got):

          java.sql.SQLTransactionRollbackException: A lock could not be obtained within the time requested
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:88)
          at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:201)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:391)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:346)
          at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2179)
          at org.apache.derby.impl.jdbc.EmbedConnection.checkUserIsNotARole(EmbedConnection.java:1197)
          at org.apache.derby.impl.jdbc.EmbedConnection.checkUserCredentials(EmbedConnection.java:1130)
          at org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:398)
          at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73)
          at org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:54)
          at org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:68)
          at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:238)
          at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:119)
          at java.sql.DriverManager.getConnection(DriverManager.java:582)
          at java.sql.DriverManager.getConnection(DriverManager.java:154)
          at org.apache.derby.impl.tools.ij.ij.dynamicConnection(ij.java:1237)
          at org.apache.derby.impl.tools.ij.ij.ConnectStatement(ij.java:1087)
          at org.apache.derby.impl.tools.ij.ij.ijStatement(ij.java:915)
          at org.apache.derby.impl.tools.ij.utilMain.runScriptGuts(utilMain.java:328)
          at org.apache.derby.impl.tools.ij.utilMain.go(utilMain.java:248)
          at org.apache.derby.impl.tools.ij.Main.go(Main.java:215)
          at org.apache.derby.impl.tools.ij.Main.mainCore(Main.java:181)
          at org.apache.derby.impl.tools.ij.Main.main(Main.java:73)
          at org.apache.derby.tools.ij.main(ij.java:59)
          Caused by: java.sql.SQLException: A lock could not be obtained within the time requested
          at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45)
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:119)
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70)
          ... 23 more
          Caused by: ERROR 40XL1: A lock could not be obtained within the time requested
          at org.apache.derby.iapi.error.StandardException.newException(StandardException.java:276)
          at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:602)
          at org.apache.derby.impl.services.locks.AbstractPool.lockObject(AbstractPool.java:117)
          at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(ConcurrentPool.java:28)
          at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForRead(RowLocking3.java:187)
          at org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:520)
          at org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:638)
          at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(B2IRowLocking3.java:335)
          at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(B2IRowLocking3.java:628)
          at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(B2IRowLockingRR.java:112)
          at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:304)
          at org.apache.derby.impl.store.access.btree.BTreeScan.next(BTreeScan.java:1756)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getDescriptorViaIndex(DataDictionaryImpl.java:8243)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.locateSchemaRow(DataDictionaryImpl.java:1559)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getSchemaDescriptor(DataDictionaryImpl.java:1469)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.initDefaultSchemaDescriptor(GenericLanguageConnectionContext.java:370)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.initialize(GenericLanguageConnectionContext.java:347)
          at org.apache.derby.impl.db.BasicDatabase.setupConnection(BasicDatabase.java:309)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.startTransaction(TransactionResourceImpl.java:188)
          at org.apache.derby.impl.jdbc.EmbedConnection.checkUserIsNotARole(EmbedConnection.java:1166)
          ... 18 more
          ij>

          Show
          Knut Anders Hatlen added a comment - Dag H. Wanvik posted the following comment on derby-dev: The following scenario creates a hang when a 2nd connection is made for the user "newuser": > java -Dij.exceptionTrace=true org.apache.derby.tools.ij ij> connect 'jdbc:derby:wombat;user=newuser'; – no schema is yet created for newuser. ij> autocommit off; ij> create table i (i int); – the schema is only created for 'newuser' at this point 0 rows inserted/updated/deleted Notice that this session has not yet committed... now we make a new session with the same user: ij> connect 'jdbc:derby:wombat;user=newuser'; ERROR 40XL1: A lock could not be obtained within the time requested Might this be what happens for you? The first time a new user connects and creates a database object, his schema will be created. But until that session commits, another session cannot login with the same user name, since the new entry in SYSSCHEMAS corresponding to the new user's schema has not been committed either (it has a write lock on it so it can't be read by the second session). Note, even if you don't use explicit users, there will still be be an implicit user, so the same thing applies. Dag ERROR 40XL1: A lock could not be obtained within the time requested (full stack trace I got): java.sql.SQLTransactionRollbackException: A lock could not be obtained within the time requested at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:88) at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:201) at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:391) at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:346) at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2179) at org.apache.derby.impl.jdbc.EmbedConnection.checkUserIsNotARole(EmbedConnection.java:1197) at org.apache.derby.impl.jdbc.EmbedConnection.checkUserCredentials(EmbedConnection.java:1130) at org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:398) at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73) at org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:54) at org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:68) at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:238) at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:119) at java.sql.DriverManager.getConnection(DriverManager.java:582) at java.sql.DriverManager.getConnection(DriverManager.java:154) at org.apache.derby.impl.tools.ij.ij.dynamicConnection(ij.java:1237) at org.apache.derby.impl.tools.ij.ij.ConnectStatement(ij.java:1087) at org.apache.derby.impl.tools.ij.ij.ijStatement(ij.java:915) at org.apache.derby.impl.tools.ij.utilMain.runScriptGuts(utilMain.java:328) at org.apache.derby.impl.tools.ij.utilMain.go(utilMain.java:248) at org.apache.derby.impl.tools.ij.Main.go(Main.java:215) at org.apache.derby.impl.tools.ij.Main.mainCore(Main.java:181) at org.apache.derby.impl.tools.ij.Main.main(Main.java:73) at org.apache.derby.tools.ij.main(ij.java:59) Caused by: java.sql.SQLException: A lock could not be obtained within the time requested at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:119) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70) ... 23 more Caused by: ERROR 40XL1: A lock could not be obtained within the time requested at org.apache.derby.iapi.error.StandardException.newException(StandardException.java:276) at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:602) at org.apache.derby.impl.services.locks.AbstractPool.lockObject(AbstractPool.java:117) at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(ConcurrentPool.java:28) at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForRead(RowLocking3.java:187) at org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:520) at org.apache.derby.impl.store.access.heap.HeapController.lockRow(HeapController.java:638) at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(B2IRowLocking3.java:335) at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(B2IRowLocking3.java:628) at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(B2IRowLockingRR.java:112) at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:304) at org.apache.derby.impl.store.access.btree.BTreeScan.next(BTreeScan.java:1756) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getDescriptorViaIndex(DataDictionaryImpl.java:8243) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.locateSchemaRow(DataDictionaryImpl.java:1559) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getSchemaDescriptor(DataDictionaryImpl.java:1469) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.initDefaultSchemaDescriptor(GenericLanguageConnectionContext.java:370) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.initialize(GenericLanguageConnectionContext.java:347) at org.apache.derby.impl.db.BasicDatabase.setupConnection(BasicDatabase.java:309) at org.apache.derby.impl.jdbc.TransactionResourceImpl.startTransaction(TransactionResourceImpl.java:188) at org.apache.derby.impl.jdbc.EmbedConnection.checkUserIsNotARole(EmbedConnection.java:1166) ... 18 more ij>
          Hide
          Knut Anders Hatlen added a comment -

          Kathey Marsden posted a comment on derby-dev saying that the issue mentioned by Dag is filed as DERBY-48.

          Show
          Knut Anders Hatlen added a comment - Kathey Marsden posted a comment on derby-dev saying that the issue mentioned by Dag is filed as DERBY-48 .
          Hide
          Knut Anders Hatlen added a comment -

          When I try Dag's test case with derby.locks.deadlockTrace=true, I see the originally reported StackOverflowException:

          $ java -Dderby.locks.waitTimeout=1 -Dderby.locks.deadlockTrace=true -jar derbyrun.jar ij
          ij version 10.5
          ij> connect 'jdbc:derby:wombat;user=newuser;create=true';
          ij> autocommit off;
          ij> create table i (i int);
          0 rows inserted/updated/deleted
          ij> connect 'jdbc:derby:wombat;user=newuser';
          ERROR XJ001: Java exception: ': java.lang.StackOverflowError'.
          ij>

          Show
          Knut Anders Hatlen added a comment - When I try Dag's test case with derby.locks.deadlockTrace=true, I see the originally reported StackOverflowException: $ java -Dderby.locks.waitTimeout=1 -Dderby.locks.deadlockTrace=true -jar derbyrun.jar ij ij version 10.5 ij> connect 'jdbc:derby:wombat;user=newuser;create=true'; ij> autocommit off; ij> create table i (i int); 0 rows inserted/updated/deleted ij> connect 'jdbc:derby:wombat;user=newuser'; ERROR XJ001: Java exception: ': java.lang.StackOverflowError'. ij>
          Hide
          geoff hendrey added a comment -

          I only have one connection open to the given database. So it seems this problem will occur even with only one connection. However, I found that the problem can be made to go away, in my case, by more carefully closing my prepared statements immediately after I am done with them, instead of relying on Connection.close. So the problem seems, in my case, to be related to having 9 or more PreparedStatements open through a given connection.

          Show
          geoff hendrey added a comment - I only have one connection open to the given database. So it seems this problem will occur even with only one connection. However, I found that the problem can be made to go away, in my case, by more carefully closing my prepared statements immediately after I am done with them, instead of relying on Connection.close. So the problem seems, in my case, to be related to having 9 or more PreparedStatements open through a given connection.
          Hide
          Dag H. Wanvik added a comment -

          "geoff hendrey (JIRA)" <jira@apache.org> writes:

          > I only have one connection open to the given database. So it seems
          > this problem will occur even with only one connection. However, I
          > found that the problem can be made to go away, in my case, by more
          > carefully closing my prepared statements immediately after I am done
          > with them, instead of relying on Connection.close. So the problem
          > seems, in my case, to be related to having 9 or more
          > PreparedStatements open through a given connection.

          Would you be able to post a repro with and without the mod that made it work? It would help a lot in pin-pointing
          your problem...

          Show
          Dag H. Wanvik added a comment - "geoff hendrey (JIRA)" <jira@apache.org> writes: > I only have one connection open to the given database. So it seems > this problem will occur even with only one connection. However, I > found that the problem can be made to go away, in my case, by more > carefully closing my prepared statements immediately after I am done > with them, instead of relying on Connection.close. So the problem > seems, in my case, to be related to having 9 or more > PreparedStatements open through a given connection. Would you be able to post a repro with and without the mod that made it work? It would help a lot in pin-pointing your problem...
          Hide
          Dag H. Wanvik added a comment -

          The underlying issue that provoked the bug in the deadlock detection (DERBY-48) in this case,
          has been fixed on trunk.
          To reproduce the stack overflow now that DERBY-48 is fixed, one could roll back that fix or find some other
          way of provoking it.

          Show
          Dag H. Wanvik added a comment - The underlying issue that provoked the bug in the deadlock detection ( DERBY-48 ) in this case, has been fixed on trunk. To reproduce the stack overflow now that DERBY-48 is fixed, one could roll back that fix or find some other way of provoking it.
          Hide
          Dag H. Wanvik added a comment - - edited

          This patch, derby-3678-1, adds a testcase, testDerby3678, to
          LazyDefaultSchemaCreationTest. This reproduces the infinite recursion
          seen by this issue, if applied without the rest of the patch, which
          also contains a fix.

          Description of the problem:

          A time-out occurs when a second transaction tries to connect if
          another connection creates a schema and populates it with a table
          without committing. See also DERBY-48.

          In the repro test case, after the timeout occurs on the second
          connect, the code in Timeout.java tries to construct the diagnostic
          lock table when tracing is enabled
          (derby.locks.deadlockTrace=true). The first thing Timeout does when
          contructing an exception (inside buildLockTableString), is to create a
          new instance of TableNameInfo, which it uses to map conglomerate ids
          to names to make the print-out more user friendly.

          The constructor of TableNameInfo calls
          DataDictionary#hashAllTableDescriptorsByTableId, which scans
          SYS.SYSTABLES in read uncommitted mode. When an entry is found, a
          descriptor for that table is built
          (SYSTABLESRowFactory#buildDescriptor).

          As part of building the descriptor for the table, buildDescriptor
          tries to look up thats table's schema using the UUID of the schema
          (found in the row from SYSTABLES describing the table) using
          dd.getSchemaDescriptor. This method tries to read SYS.SYSSCHEMAS with
          repeatable read mode, which leads to the recursive lock and finally
          stack overflow for the thread.

          If the lookup of the table's schema is done with read uncommitted
          instead, the recursion will not happen. This seems permissible, since
          SYS.SYSTABLES is also read in read uncommitted mode from
          hashAllTableDescriptorsByTableId, which is only ever called from
          TableNameInfo, which, in turn, is only used for diagnostics, as far as
          I can tell.

          Patch description:

          • Adds a new testcase to LazyDefaultSchemaCreationTest
          • Makes hashAllTableDescriptorsByTableId use read uncommitted mode when
            accessing SYS.SYSSCHEMAS. Unfortunately I had to add many overloads
            to be able to propagate the isolation mode all the way down. Is
            there a better way?

          Running regressions now.

          Show
          Dag H. Wanvik added a comment - - edited This patch, derby-3678-1, adds a testcase, testDerby3678, to LazyDefaultSchemaCreationTest. This reproduces the infinite recursion seen by this issue, if applied without the rest of the patch, which also contains a fix. Description of the problem: A time-out occurs when a second transaction tries to connect if another connection creates a schema and populates it with a table without committing. See also DERBY-48 . In the repro test case, after the timeout occurs on the second connect, the code in Timeout.java tries to construct the diagnostic lock table when tracing is enabled (derby.locks.deadlockTrace=true). The first thing Timeout does when contructing an exception (inside buildLockTableString), is to create a new instance of TableNameInfo, which it uses to map conglomerate ids to names to make the print-out more user friendly. The constructor of TableNameInfo calls DataDictionary#hashAllTableDescriptorsByTableId, which scans SYS.SYSTABLES in read uncommitted mode. When an entry is found, a descriptor for that table is built (SYSTABLESRowFactory#buildDescriptor). As part of building the descriptor for the table, buildDescriptor tries to look up thats table's schema using the UUID of the schema (found in the row from SYSTABLES describing the table) using dd.getSchemaDescriptor. This method tries to read SYS.SYSSCHEMAS with repeatable read mode, which leads to the recursive lock and finally stack overflow for the thread. If the lookup of the table's schema is done with read uncommitted instead, the recursion will not happen. This seems permissible, since SYS.SYSTABLES is also read in read uncommitted mode from hashAllTableDescriptorsByTableId, which is only ever called from TableNameInfo, which, in turn, is only used for diagnostics, as far as I can tell. Patch description: Adds a new testcase to LazyDefaultSchemaCreationTest Makes hashAllTableDescriptorsByTableId use read uncommitted mode when accessing SYS.SYSSCHEMAS. Unfortunately I had to add many overloads to be able to propagate the isolation mode all the way down. Is there a better way? Running regressions now.
          Hide
          Dag H. Wanvik added a comment -

          Regressions passed.

          Show
          Dag H. Wanvik added a comment - Regressions passed.
          Hide
          Dag H. Wanvik added a comment -

          I will commit this patch soon if nobody has any objections. I'd still appreciate a review of this one, though.

          Show
          Dag H. Wanvik added a comment - I will commit this patch soon if nobody has any objections. I'd still appreciate a review of this one, though.
          Hide
          Knut Anders Hatlen added a comment -

          The approach looks fine to me. Two tiny nits:

          1. Javadoc for hashAllTableDescriptorsByTableId() should be updated:
          "This method will scan SYS.SYSTABLES at READ UNCOMMITTED." --> "This method will scan SYS.SYSTABLES and SYS.SYSSCHEMAS at READ UNCOMMITTED."

          2. The indentation seems to have been accidentally deleted for a line in DataDictionaryImpl:

          • /**
            +
            +/**
          • Get the target schema by searching for a matching row
          • in SYSSCHEMAS by schema name. Read only scan.
          Show
          Knut Anders Hatlen added a comment - The approach looks fine to me. Two tiny nits: 1. Javadoc for hashAllTableDescriptorsByTableId() should be updated: "This method will scan SYS.SYSTABLES at READ UNCOMMITTED." --> "This method will scan SYS.SYSTABLES and SYS.SYSSCHEMAS at READ UNCOMMITTED." 2. The indentation seems to have been accidentally deleted for a line in DataDictionaryImpl: /** + +/** Get the target schema by searching for a matching row in SYSSCHEMAS by schema name. Read only scan.
          Hide
          Knut Anders Hatlen added a comment -

          I also noticed that hashAllTableDescriptorsByTableId() says:

          // it is important for read uncommitted scans to use fetchNext() rather
          // than fetch, so that the fetch happens while latch is held, otherwise
          // the next() might position the scan on a row, but the subsequent
          // fetch() may find the row deleted or purged from the table.

          With the patch, getDescriptorViaIndexMinion() sometimes uses read uncommitted isolation level, but still it uses next() + fetch() instead of fetchNext(). Do you think this could cause any problems?

          Show
          Knut Anders Hatlen added a comment - I also noticed that hashAllTableDescriptorsByTableId() says: // it is important for read uncommitted scans to use fetchNext() rather // than fetch, so that the fetch happens while latch is held, otherwise // the next() might position the scan on a row, but the subsequent // fetch() may find the row deleted or purged from the table. With the patch, getDescriptorViaIndexMinion() sometimes uses read uncommitted isolation level, but still it uses next() + fetch() instead of fetchNext(). Do you think this could cause any problems?
          Hide
          Dag H. Wanvik added a comment -

          Thanks for looking at this, Knut Anders. Fixed the javadoc and the
          accidental whitespace thing. As for your second, comment, I agree it
          is probably better to use the idiom for reading the index row under
          read uncommitted mode, so I did that.

          Additionally, I modified the existing sanity code which asserts that
          the base row is always there to just run when repeatable read is used,
          and added an extra check for this case for read uncommitted mode in
          which case I just throw an error (RAWSTORE_RECORD_VANISHED). This
          should be very unlikely, but if it happens we have seen that TimeOut
          swallows exceptions when building TableNameInfo and prints the lock
          table even without table information, so I think it is ok. We could
          possibly catch this exception in hashAllTableDescriptorsByTableId and
          just skip that table (which has gone anyway since its schema has
          gone..., but I didn't.

          I also added javadoc to say that only repeatable read (normal case)
          and read uncommitted are supported (in the new signatures).

          Re-running tests.

          Show
          Dag H. Wanvik added a comment - Thanks for looking at this, Knut Anders. Fixed the javadoc and the accidental whitespace thing. As for your second, comment, I agree it is probably better to use the idiom for reading the index row under read uncommitted mode, so I did that. Additionally, I modified the existing sanity code which asserts that the base row is always there to just run when repeatable read is used, and added an extra check for this case for read uncommitted mode in which case I just throw an error (RAWSTORE_RECORD_VANISHED). This should be very unlikely, but if it happens we have seen that TimeOut swallows exceptions when building TableNameInfo and prints the lock table even without table information, so I think it is ok. We could possibly catch this exception in hashAllTableDescriptorsByTableId and just skip that table (which has gone anyway since its schema has gone... , but I didn't. I also added javadoc to say that only repeatable read (normal case) and read uncommitted are supported (in the new signatures). Re-running tests.
          Hide
          Knut Anders Hatlen added a comment -

          Thanks for the new patch, Dag. Some more comments:

          1) typo in javadoc: SYS:SYSSCHEMAS -> SYS.SYSSCHEMAS (colon -> comma)

          2) Message for SQLState.RAWSTORE_RECORD_VANISHED needs a parameter (recordName)

          3) In the code below, couldn't the nested if statements be combined into a single one? Then the debug code doesn't have to be reindented.
          + if (! base_row_exists) {
          + if (isolationLevel ==
          + TransactionController.ISOLATION_REPEATABLE_READ) {
          --> if (!base_row_exists && isolationLevel == ...)

          4) I don't know the store API well enough to say whether the code is correct or not, but isn't there a risk in getDescriptorViaIndexMinion() that heapCC.fetch() reads the wrong row, as the row isn't protected by a lock between retrieving the row location from the index and actually reading the value?

          5) If getDescriptorViaIndex() only supports repeatable read and read uncommitted, should it have an assert so that no one accidentally calls it with another isolation level?

          Show
          Knut Anders Hatlen added a comment - Thanks for the new patch, Dag. Some more comments: 1) typo in javadoc: SYS:SYSSCHEMAS -> SYS.SYSSCHEMAS (colon -> comma) 2) Message for SQLState.RAWSTORE_RECORD_VANISHED needs a parameter (recordName) 3) In the code below, couldn't the nested if statements be combined into a single one? Then the debug code doesn't have to be reindented. + if (! base_row_exists) { + if (isolationLevel == + TransactionController.ISOLATION_REPEATABLE_READ) { --> if (!base_row_exists && isolationLevel == ...) 4) I don't know the store API well enough to say whether the code is correct or not, but isn't there a risk in getDescriptorViaIndexMinion() that heapCC.fetch() reads the wrong row, as the row isn't protected by a lock between retrieving the row location from the index and actually reading the value? 5) If getDescriptorViaIndex() only supports repeatable read and read uncommitted, should it have an assert so that no one accidentally calls it with another isolation level?
          Hide
          Dag H. Wanvik added a comment -

          Thanks for your comment, Knut Anders.
          A new version of the patch, #3, addresses all your comments so:

          1) Typo fixed
          2) Moved away from throwing the vanished exception, I just return an empty descriptor.
          I tried this by simulating that the base row had gone and the diagnostics printed ok.
          Please see the new comment in the code.
          3) Done
          4) I think this can only happen is a compress managed to squeeze in between the
          reading of the index row adn the base row; as far as i remember the row location
          is not reused until a compress happens...
          5) Added sanity checks.

          Re-running regression tests

          Show
          Dag H. Wanvik added a comment - Thanks for your comment, Knut Anders. A new version of the patch, #3, addresses all your comments so: 1) Typo fixed 2) Moved away from throwing the vanished exception, I just return an empty descriptor. I tried this by simulating that the base row had gone and the diagnostics printed ok. Please see the new comment in the code. 3) Done 4) I think this can only happen is a compress managed to squeeze in between the reading of the index row adn the base row; as far as i remember the row location is not reused until a compress happens... 5) Added sanity checks. Re-running regression tests
          Hide
          Knut Anders Hatlen added a comment -

          Thanks again, Dag!

          I guess you're right that the problem is limited to concurrent compress of SYS.SYSSCHEMAS and is not very likely, nor very harmful given that this code is only used for diagnostics. Great that you added a comment about this in the code! I have no more comments to the latest patch.

          Show
          Knut Anders Hatlen added a comment - Thanks again, Dag! I guess you're right that the problem is limited to concurrent compress of SYS.SYSSCHEMAS and is not very likely, nor very harmful given that this code is only used for diagnostics. Great that you added a comment about this in the code! I have no more comments to the latest patch.
          Hide
          Dag H. Wanvik added a comment -

          Patch derby-3678-3 committed as svn 666901, resolving.

          Show
          Dag H. Wanvik added a comment - Patch derby-3678-3 committed as svn 666901, resolving.

            People

            • Assignee:
              Dag H. Wanvik
              Reporter:
              geoff hendrey
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development