Derby
  1. Derby
  2. DERBY-2861

Thread safety issue in TableDescriptor

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 10.5.1.1
    • Component/s: SQL
    • Labels:
      None
    • Environment:
      Tested on a dual-core 3GHz Pentium machine running Windows Vista Business, using JDK 1.4.2_13 and Derby trunk revision 548822.

      Description

      A NullPointerException occurs in org.apache.derby.iapi.sql.dictionary.TableDescriptor.getObjectName when accessing the same object on many threads (each with its own connection). The attached test program starts N threads each creating and then dropping a separate view against the same source view, repeated M times. I can reproduce the problem with N=100 and M=100 on my machine, but not every run.

      An instance member named referencedColumnMap is checked for null at the top of the getObjectName method, but later when it is dereferenced it is null, because it was set to null by another thread. I am not sure what getObjectName is used for other than error reporting. I have considered a fix of just saving the non-null reference as a method variable, to avoid the later NullPointerException. But I don't know what unintended consequences this may have.

      When the test program does show the exception, the stack trace looks like this:

      java.lang.NullPointerException
      at org.apache.derby.iapi.sql.dictionary.TableDescriptor.getObjectName(TableDescriptor.java:758)
      at org.apache.derby.impl.sql.depend.BasicDependencyManager.getPersistentProviderInfos(BasicDependencyManager.java:677)
      at org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:287)
      at org.apache.derby.impl.sql.compile.CreateViewNode.bind(CreateViewNode.java:183)
      at org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:345)
      at org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:119)
      at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:745)
      at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:568)
      at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:517)
      at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:109)
      at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:10)
      at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:173)
      at java.lang.Thread.run(Thread.java:534)

      1. derby-2861-2.diff
        3 kB
        Dag H. Wanvik
      2. derby-2861-1.diff
        3 kB
        Dag H. Wanvik
      3. experiment.diff
        6 kB
        Dag H. Wanvik
      4. TestEmbeddedMultiThreading.java
        9 kB
        Jeff Clary

        Issue Links

          Activity

          Hide
          Jeff Clary added a comment -

          Command line arguments are NUMBER_OF_THREADS NUMBER_OF_ITERATIONS. I have seen the error occur with 100 threads after a few iterations.

          Show
          Jeff Clary added a comment - Command line arguments are NUMBER_OF_THREADS NUMBER_OF_ITERATIONS. I have seen the error occur with 100 threads after a few iterations.
          Hide
          Kathey Marsden added a comment -

          I can't seem to reproduce this on trunk or latest on 10.3. I get only lock timeouts. e.g.
          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.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:2082)
          at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:81)
          at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1325)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:625)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555)
          at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124)
          at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25)
          at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:189)
          at java.lang.Thread.run(Thread.java:803)
          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.RowLocking2.lockRecordForRead(RowLocking2.java:165)
          at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScan(B2IRowLocking3.java:127)
          at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockScan(B2IRowLocking3.java:739)
          at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(B2IRowLocking3.java:662)
          at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(B2IRowLockingRR.java:112)
          at org.apache.derby.impl.store.access.btree.BTreeScan.positionAtStartForForwardScan(BTreeScan.java:436)
          at org.apache.derby.impl.store.access.btree.BTreeForwardScan.positionAtStartPosition(BTreeForwardScan.java:71)
          at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:123)
          at org.apache.derby.impl.store.access.btree.BTreeScan.next(BTreeScan.java:1756)
          at org.apache.derby.impl.sql.execute.IndexChanger.doDelete(IndexChanger.java:335)
          at org.apache.derby.impl.sql.execute.IndexChanger.delete(IndexChanger.java:544)
          at org.apache.derby.impl.sql.execute.IndexSetChanger.delete(IndexSetChanger.java:250)
          at org.apache.derby.impl.sql.execute.RowChangerImpl.deleteRow(RowChangerImpl.java:476)
          at org.apache.derby.impl.sql.catalog.TabInfoImpl.deleteRows(TabInfoImpl.java:750)
          at org.apache.derby.impl.sql.catalog.TabInfoImpl.deleteRow(TabInfoImpl.java:581)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.dropColumnDescriptorCore(DataDictionaryImpl.java:2950)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.dropAllColumnDescriptors(DataDictionaryImpl.java:2452)
          at org.apache.derby.iapi.sql.dictionary.ViewDescriptor.drop(ViewDescriptor.java:411)
          at org.apache.derby.impl.sql.execute.DropViewConstantAction.executeConstantAction(DropViewConstantAction.java:13
          4)
          at org.apache.derby.impl.sql.execute.MiscResultSet.open(MiscResultSet.java:64)
          at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:372)
          at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235)
          ... 6 more

          Are the lock timeouts expected? Can anyone still reproduce this?

          Show
          Kathey Marsden added a comment - I can't seem to reproduce this on trunk or latest on 10.3. I get only lock timeouts. e.g. 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.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:2082) at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:81) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1325) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:625) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555) at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124) at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25) at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:189) at java.lang.Thread.run(Thread.java:803) 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.RowLocking2.lockRecordForRead(RowLocking2.java:165) at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScan(B2IRowLocking3.java:127) at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockScan(B2IRowLocking3.java:739) at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(B2IRowLocking3.java:662) at org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(B2IRowLockingRR.java:112) at org.apache.derby.impl.store.access.btree.BTreeScan.positionAtStartForForwardScan(BTreeScan.java:436) at org.apache.derby.impl.store.access.btree.BTreeForwardScan.positionAtStartPosition(BTreeForwardScan.java:71) at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:123) at org.apache.derby.impl.store.access.btree.BTreeScan.next(BTreeScan.java:1756) at org.apache.derby.impl.sql.execute.IndexChanger.doDelete(IndexChanger.java:335) at org.apache.derby.impl.sql.execute.IndexChanger.delete(IndexChanger.java:544) at org.apache.derby.impl.sql.execute.IndexSetChanger.delete(IndexSetChanger.java:250) at org.apache.derby.impl.sql.execute.RowChangerImpl.deleteRow(RowChangerImpl.java:476) at org.apache.derby.impl.sql.catalog.TabInfoImpl.deleteRows(TabInfoImpl.java:750) at org.apache.derby.impl.sql.catalog.TabInfoImpl.deleteRow(TabInfoImpl.java:581) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.dropColumnDescriptorCore(DataDictionaryImpl.java:2950) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.dropAllColumnDescriptors(DataDictionaryImpl.java:2452) at org.apache.derby.iapi.sql.dictionary.ViewDescriptor.drop(ViewDescriptor.java:411) at org.apache.derby.impl.sql.execute.DropViewConstantAction.executeConstantAction(DropViewConstantAction.java:13 4) at org.apache.derby.impl.sql.execute.MiscResultSet.open(MiscResultSet.java:64) at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:372) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235) ... 6 more Are the lock timeouts expected? Can anyone still reproduce this?
          Hide
          Bryan Pendleton added a comment -

          I ran the test program a number of times with the current trunk.

          Sometimes the program ran successfully, sometimes I got
          lock timeout errors, sometimes I got "table/view already exists" errors.

          I never saw the NPE observed by the original poster.

          This was on Ubuntu 8 with Sun JDK 1.5 on a fairly slow old machine.

          Show
          Bryan Pendleton added a comment - I ran the test program a number of times with the current trunk. Sometimes the program ran successfully, sometimes I got lock timeout errors, sometimes I got "table/view already exists" errors. I never saw the NPE observed by the original poster. This was on Ubuntu 8 with Sun JDK 1.5 on a fairly slow old machine.
          Hide
          Dag H. Wanvik added a comment -

          I was able to reproduce this error on trunk on a dual-cpu x86 box running Solaris 10 using
          10 threads and 100 iterations on the first attempt. Next 10 attempts worked well..

          In all cases I got the error:
          Table/View 'SOURCETABLE' already exists in Schema 'SCHEMAMAIN'

          My stack trace is similar:

          java.sql.SQLException: Java exception: ': java.lang.NullPointerException'.
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95)
          at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:87)
          at org.apache.derby.impl.jdbc.Util.javaException(Util.java:244)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:403)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:346)
          at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2183)
          at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:81)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:614)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555)
          at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124)
          at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25)
          at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188)
          at java.lang.Thread.run(Thread.java:619)
          Caused by: java.sql.SQLException: Java exception: ': java.lang.NullPointerException'.
          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)
          ... 12 more
          Caused by: java.lang.NullPointerException
          at org.apache.derby.iapi.sql.dictionary.TableDescriptor.getObjectName(TableDescriptor.java:775)
          at org.apache.derby.impl.sql.depend.BasicDependencyManager.getPersistentProviderInfos(BasicDependencyManager.java:681)
          at org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:287)
          at org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181)
          at org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314)
          at org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606)
          ... 5 more

          Show
          Dag H. Wanvik added a comment - I was able to reproduce this error on trunk on a dual-cpu x86 box running Solaris 10 using 10 threads and 100 iterations on the first attempt. Next 10 attempts worked well.. In all cases I got the error: Table/View 'SOURCETABLE' already exists in Schema 'SCHEMAMAIN' My stack trace is similar: java.sql.SQLException: Java exception: ': java.lang.NullPointerException'. at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95) at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:87) at org.apache.derby.impl.jdbc.Util.javaException(Util.java:244) at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:403) at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:346) at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2183) at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:81) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:614) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555) at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124) at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25) at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188) at java.lang.Thread.run(Thread.java:619) Caused by: java.sql.SQLException: Java exception: ': java.lang.NullPointerException'. 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) ... 12 more Caused by: java.lang.NullPointerException at org.apache.derby.iapi.sql.dictionary.TableDescriptor.getObjectName(TableDescriptor.java:775) at org.apache.derby.impl.sql.depend.BasicDependencyManager.getPersistentProviderInfos(BasicDependencyManager.java:681) at org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:287) at org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181) at org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314) at org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606) ... 5 more
          Hide
          Dag H. Wanvik added a comment -

          It seems there is a race condition here in that referencedColumnMap
          is being set to null after the test at the start of getObjectName but before
          the usage.

          By inserting a Thread.sleep(1000) at a line just before the access

          > if (referencedColumnMap.isSet(cd.getPosition())

          I can reliably reproduce the error. I will try to find out what usage/access sets
          referencedColumnMap to null now

          Show
          Dag H. Wanvik added a comment - It seems there is a race condition here in that referencedColumnMap is being set to null after the test at the start of getObjectName but before the usage. By inserting a Thread.sleep(1000) at a line just before the access > if (referencedColumnMap.isSet(cd.getPosition()) I can reliably reproduce the error. I will try to find out what usage/access sets referencedColumnMap to null now
          Hide
          Dag H. Wanvik added a comment -

          I instrumented the code that sets referencedColumnMap to collect the thread and the thread's
          stacktrace when it sets it to null, and printed that as well as the current thread and the stacktrace
          when the error occurs:

          I got these two stack traces that show how two threads get in each others way here.

          --->thread 1: Thread[Thread-10,5,main]

            • org.apache.derby.iapi.sql.dictionary.TableDescriptor.setReferencedColumnMap(TableDescriptor.java:381)
            • org.apache.derby.impl.sql.depend.BasicDependencyManager.clearColumnInfoInProviders(BasicDependencyManager.java:707)
            • org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:290)
            • org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181)
            • org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314)
            • org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88)
            • org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794)
            • org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606)
            • org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555)
            • TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124)
            • TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25)
            • TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188)
            • java.lang.Thread.run(Thread.java:619)

          --->thread 2: Thread[Thread-5,5,main]
          java.lang.Exception: Stack trace
          at java.lang.Thread.dumpStack(Thread.java:1206)
          at org.apache.derby.iapi.sql.dictionary.TableDescriptor.getObjectName(TableDescriptor.java:796)
          at org.apache.derby.impl.sql.depend.BasicDependencyManager.getPersistentProviderInfos(BasicDependencyManager.java:681)
          at org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:287)
          at org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181)
          at org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314)
          at org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555)
          at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124)
          at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25)
          at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188)
          at java.lang.Thread.run(Thread.java:619)

          These lines in CreatViewNode#bindViewDefinition account for both thread stacks:

          (2) ProviderInfo[] providerInfos = dm.getPersistentProviderInfos(apl);
          // need to clear the column info in case the same table descriptor
          // is reused, eg., in multiple target only view definition
          (1) dm.clearColumnInfoInProviders(apl);

          Thread 1 is excuting line marked (1), thread 2 is executing line marked (2).

          Show
          Dag H. Wanvik added a comment - I instrumented the code that sets referencedColumnMap to collect the thread and the thread's stacktrace when it sets it to null, and printed that as well as the current thread and the stacktrace when the error occurs: I got these two stack traces that show how two threads get in each others way here. --->thread 1: Thread [Thread-10,5,main] org.apache.derby.iapi.sql.dictionary.TableDescriptor.setReferencedColumnMap(TableDescriptor.java:381) org.apache.derby.impl.sql.depend.BasicDependencyManager.clearColumnInfoInProviders(BasicDependencyManager.java:707) org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:290) org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181) org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314) org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88) org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794) org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606) org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555) TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124) TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25) TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188) java.lang.Thread.run(Thread.java:619) --->thread 2: Thread [Thread-5,5,main] java.lang.Exception: Stack trace at java.lang.Thread.dumpStack(Thread.java:1206) at org.apache.derby.iapi.sql.dictionary.TableDescriptor.getObjectName(TableDescriptor.java:796) at org.apache.derby.impl.sql.depend.BasicDependencyManager.getPersistentProviderInfos(BasicDependencyManager.java:681) at org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:287) at org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181) at org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314) at org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555) at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124) at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25) at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188) at java.lang.Thread.run(Thread.java:619) These lines in CreatViewNode#bindViewDefinition account for both thread stacks: (2) ProviderInfo[] providerInfos = dm.getPersistentProviderInfos(apl); // need to clear the column info in case the same table descriptor // is reused, eg., in multiple target only view definition (1) dm.clearColumnInfoInProviders(apl); Thread 1 is excuting line marked (1), thread 2 is executing line marked (2).
          Hide
          Dag H. Wanvik added a comment -

          When I added synchronized(this) for both dm.getPersistentProviderInfos and dm.clearColumnInfoInProviders
          I observed another race:

          Table: SCHEMAMAIN.SOURCETABLE
          --->thread 1: Thread[Thread-11,5,main]

            • org.apache.derby.iapi.sql.dictionary.TableDescriptor.setReferencedColumnMap(TableDescriptor.java:381)
            • org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getTableDescriptor(DataDictionaryImpl.java:1997)
            • org.apache.derby.impl.sql.compile.QueryTreeNode.getTableDescriptor(QueryTreeNode.java:1228)
            • org.apache.derby.impl.sql.compile.FromBaseTable.bindTableDescriptor(FromBaseTable.java:2445)
            • org.apache.derby.impl.sql.compile.FromBaseTable.bindNonVTITables(FromBaseTable.java:2175)
            • org.apache.derby.impl.sql.compile.FromList.bindTables(FromList.java:310)
            • org.apache.derby.impl.sql.compile.SelectNode.bindNonVTITables(SelectNode.java:390)
            • org.apache.derby.impl.sql.compile.FromSubquery.bindNonVTITables(FromSubquery.java:154)
            • org.apache.derby.impl.sql.compile.FromBaseTable.bindNonVTITables(FromBaseTable.java:2290)
            • org.apache.derby.impl.sql.compile.FromList.bindTables(FromList.java:310)
            • org.apache.derby.impl.sql.compile.SelectNode.bindNonVTITables(SelectNode.java:390)
            • org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:259)
            • org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181)
            • org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314)
            • org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88)
            • org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794)
            • org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606)
            • org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555)
            • TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124)
            • TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25)
            • TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188)
            • java.lang.Thread.run(Thread.java:619)

          --->thread 2: Thread[Thread-8,5,main]
          java.lang.Exception: Stack trace
          at java.lang.Thread.dumpStack(Thread.java:1206)
          at org.apache.derby.iapi.sql.dictionary.TableDescriptor.getObjectName(TableDescriptor.java:796)
          at org.apache.derby.impl.sql.depend.BasicDependencyManager.getPersistentProviderInfos(BasicDependencyManager.java:683)
          at org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:287)
          at org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181)
          at org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314)
          at org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606)
          at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555)
          at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124)
          at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25)
          at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188)
          at java.lang.Thread.run(Thread.java:619)

          Show
          Dag H. Wanvik added a comment - When I added synchronized(this) for both dm.getPersistentProviderInfos and dm.clearColumnInfoInProviders I observed another race: Table: SCHEMAMAIN.SOURCETABLE --->thread 1: Thread [Thread-11,5,main] org.apache.derby.iapi.sql.dictionary.TableDescriptor.setReferencedColumnMap(TableDescriptor.java:381) org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getTableDescriptor(DataDictionaryImpl.java:1997) org.apache.derby.impl.sql.compile.QueryTreeNode.getTableDescriptor(QueryTreeNode.java:1228) org.apache.derby.impl.sql.compile.FromBaseTable.bindTableDescriptor(FromBaseTable.java:2445) org.apache.derby.impl.sql.compile.FromBaseTable.bindNonVTITables(FromBaseTable.java:2175) org.apache.derby.impl.sql.compile.FromList.bindTables(FromList.java:310) org.apache.derby.impl.sql.compile.SelectNode.bindNonVTITables(SelectNode.java:390) org.apache.derby.impl.sql.compile.FromSubquery.bindNonVTITables(FromSubquery.java:154) org.apache.derby.impl.sql.compile.FromBaseTable.bindNonVTITables(FromBaseTable.java:2290) org.apache.derby.impl.sql.compile.FromList.bindTables(FromList.java:310) org.apache.derby.impl.sql.compile.SelectNode.bindNonVTITables(SelectNode.java:390) org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:259) org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181) org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314) org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88) org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794) org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606) org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555) TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124) TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25) TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188) java.lang.Thread.run(Thread.java:619) --->thread 2: Thread [Thread-8,5,main] java.lang.Exception: Stack trace at java.lang.Thread.dumpStack(Thread.java:1206) at org.apache.derby.iapi.sql.dictionary.TableDescriptor.getObjectName(TableDescriptor.java:796) at org.apache.derby.impl.sql.depend.BasicDependencyManager.getPersistentProviderInfos(BasicDependencyManager.java:683) at org.apache.derby.impl.sql.compile.CreateViewNode.bindViewDefinition(CreateViewNode.java:287) at org.apache.derby.impl.sql.compile.CreateViewNode.bindStatement(CreateViewNode.java:181) at org.apache.derby.impl.sql.GenericStatement.prepMinion(GenericStatement.java:314) at org.apache.derby.impl.sql.GenericStatement.prepare(GenericStatement.java:88) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(GenericLanguageConnectionContext.java:794) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:606) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:555) at TestEmbeddedMultiThreading.executeStatement(TestEmbeddedMultiThreading.java:124) at TestEmbeddedMultiThreading.access$100(TestEmbeddedMultiThreading.java:25) at TestEmbeddedMultiThreading$ViewCreatorDropper.run(TestEmbeddedMultiThreading.java:188) at java.lang.Thread.run(Thread.java:619)
          Hide
          Dag H. Wanvik added a comment - - edited

          I got rid of that one by adding:

          synchronized(getDataDictionary().getDependencyManager()) {
          :

          to setReferencedColumnMap. But this all seems problematic,
          since the referenceColumnMap is used unsynchronized also from:

          FromBaseTable#getMatchingColumn

          It seems the mechanism of this shared state (refrencedColumnMap) in the TableDescriptor which is being manipulated by several threads is not sound and needs some rethinking.

          Uploading the patch I used to get this far, experiment.diff.

          Show
          Dag H. Wanvik added a comment - - edited I got rid of that one by adding: synchronized(getDataDictionary().getDependencyManager()) { : to setReferencedColumnMap. But this all seems problematic, since the referenceColumnMap is used unsynchronized also from: FromBaseTable#getMatchingColumn It seems the mechanism of this shared state (refrencedColumnMap) in the TableDescriptor which is being manipulated by several threads is not sound and needs some rethinking. Uploading the patch I used to get this far, experiment.diff.
          Hide
          Dag H. Wanvik added a comment -

          Note, the patch contains the instrumentation as well.
          By removing the synchronizations I added you should be able to see the
          bug in the repro.

          Show
          Dag H. Wanvik added a comment - Note, the patch contains the instrumentation as well. By removing the synchronizations I added you should be able to see the bug in the repro.
          Hide
          Dag H. Wanvik added a comment -

          It seems the TableDescriptors are only ever taken from the cache
          (i.e. not read from SYSTABLES) during compile time. The problem seen
          in the repro happens at compile time when threads access the same
          TableDescriptor instance and use save state in referencedColumnMap.

          Attaching a patch which makes the "sleep modified" repro work. It
          makes the field referencedColumnMap thread local. This should be OK
          since the field is not present in SYSTABLES, so it must be transitory.
          So with this patch, each new thread will experience that the field is
          null when the thread first accesses it.

          Quoting the comment from TableDescriptor.java:

          • It contains a weak hash map keyed by the the TableDescriptor
          • and the value is the actual referencedColumnMap bitmap. So,
          • each thread has a weak hash map it uses to find the appropriate
          • referencedColumnMap for 'this' TableDescriptor.
            *
          • Since the hash map is weak, when the TableDescriptor is no
          • longer referenced the hash entry can be garbage collected (it
          • is the key of a weak hash map that is weak, not the value).

          I did not add any test since I don't know how to reliably make one.
          Running regressions now.

          Show
          Dag H. Wanvik added a comment - It seems the TableDescriptors are only ever taken from the cache (i.e. not read from SYSTABLES) during compile time. The problem seen in the repro happens at compile time when threads access the same TableDescriptor instance and use save state in referencedColumnMap. Attaching a patch which makes the "sleep modified" repro work. It makes the field referencedColumnMap thread local. This should be OK since the field is not present in SYSTABLES, so it must be transitory. So with this patch, each new thread will experience that the field is null when the thread first accesses it. Quoting the comment from TableDescriptor.java: It contains a weak hash map keyed by the the TableDescriptor and the value is the actual referencedColumnMap bitmap. So, each thread has a weak hash map it uses to find the appropriate referencedColumnMap for 'this' TableDescriptor. * Since the hash map is weak, when the TableDescriptor is no longer referenced the hash entry can be garbage collected (it is the key of a weak hash map that is weak, not the value). I did not add any test since I don't know how to reliably make one. Running regressions now.
          Hide
          Kristian Waagan added a comment -

          Two comments on the patch 'derby-2861-1.diff':
          a) What is the purpose of 'synchronized' keyword in the signature of ThreadLocal.initialValue?
          b) Can the import of ThreadLocal be removed? (it is commented out)

          Show
          Kristian Waagan added a comment - Two comments on the patch 'derby-2861-1.diff': a) What is the purpose of 'synchronized' keyword in the signature of ThreadLocal.initialValue? b) Can the import of ThreadLocal be removed? (it is commented out)
          Hide
          Dag H. Wanvik added a comment -

          Thanks for looking at this, Kristian!

          Uploading a new version, #2. Btw, regression tests passed for #1.
          As for your comments:

          a) Yes, bad cut and paste job from the javadoc sample code Fixed.
          b) Yes, I forgot, thank. Fixed.

          Show
          Dag H. Wanvik added a comment - Thanks for looking at this, Kristian! Uploading a new version, #2. Btw, regression tests passed for #1. As for your comments: a) Yes, bad cut and paste job from the javadoc sample code Fixed. b) Yes, I forgot, thank. Fixed.
          Hide
          Dag H. Wanvik added a comment -

          Committed derby-2861-2 as svn 670286.

          Resolving.

          Show
          Dag H. Wanvik added a comment - Committed derby-2861-2 as svn 670286. Resolving.

            People

            • Assignee:
              Dag H. Wanvik
              Reporter:
              Jeff Clary
            • Votes:
              1 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development