Derby
  1. Derby
  2. DERBY-5037

Assertion failure from index-stat-thread when running AutomaticIndexStatisticsTest

    Details

    • Urgency:
      Normal

      Description

      I see the following assertion failure on the console when running AutomaticIndexStatisticsTest standalone against debug jars. This may be related to DERBY-5026, DERBY-5030, and DERBY-5031. The test itself completes successfully:

      ...Exception in thread "index-stat-thread" org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED No page at pagenumber: 1; ContainerHandle = BaseContainerHandle:(Container(0, 1153))
      at org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:162)
      at org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:147)
      at org.apache.derby.impl.store.access.btree.ControlRow.get(ControlRow.java:838)
      at org.apache.derby.impl.store.access.btree.ControlRow.get(ControlRow.java:820)
      at org.apache.derby.impl.store.access.btree.BTreeScan.reposition(BTreeScan.java:850)
      at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:109)
      at org.apache.derby.impl.store.access.btree.BTreeScan.fetchNextGroup(BTreeScan.java:1596)
      at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl$KeyComparator.fetchRows(IndexStatisticsDaemonImpl.java:1103)
      at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.updateIndexStatsMinion(IndexStatisticsDaemonImpl.java:453)
      at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.generateStatistics(IndexStatisticsDaemonImpl.java:324)
      at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.run(IndexStatisticsDaemonImpl.java:710)
      at java.lang.Thread.run(Thread.java:637)
      ---------------
      Stack traces for all live threads:
      Thread name=derby.rawStoreDaemon id=13 priority=5 state=TIMED_WAITING isdaemon=true
      java.lang.Object.wait(Native Method)
      org.apache.derby.impl.services.daemon.BasicDaemon.rest(BasicDaemon.java:576)
      org.apache.derby.impl.services.daemon.BasicDaemon.run(BasicDaemon.java:390)
      java.lang.Thread.run(Thread.java:637)

      Thread name=Finalizer id=3 priority=8 state=WAITING isdaemon=true
      java.lang.Object.wait(Native Method)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
      java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

      Thread name=Reference Handler id=2 priority=10 state=WAITING isdaemon=true
      java.lang.Object.wait(Native Method)
      java.lang.Object.wait(Object.java:485)
      java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)

      Thread name=main id=1 priority=5 state=RUNNABLE isdaemon=false
      java.security.AccessController.doPrivileged(Native Method)
      org.apache.derby.impl.store.raw.data.BaseDataFileFactory.releaseJBMSLockOnDB(BaseDataFileFactory.java:2040)
      org.apache.derby.impl.store.raw.data.BaseDataFileFactory.stop(BaseDataFileFactory.java:519)
      org.apache.derby.impl.services.monitor.TopService.stop(TopService.java:442)
      org.apache.derby.impl.services.monitor.TopService.shutdown(TopService.java:393)
      org.apache.derby.impl.services.monitor.BaseMonitor.shutdown(BaseMonitor.java:229)
      org.apache.derby.impl.db.DatabaseContextImpl.cleanupOnError(DatabaseContextImpl.java:62)
      org.apache.derby.iapi.services.context.ContextManager.cleanupOnError(ContextManager.java:343)
      org.apache.derby.impl.jdbc.TransactionResourceImpl.cleanupOnError(TransactionResourceImpl.java:433)
      org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:633)
      org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73)
      org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:56)
      org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:70)
      org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:248)
      org.apache.derby.jdbc.EmbeddedDataSource.getConnection(EmbeddedDataSource.java:480)
      org.apache.derby.jdbc.EmbeddedDataSource.getConnection(EmbeddedDataSource.java:424)
      org.apache.derbyTesting.junit.JDBCDataSource.shutdownDatabase(JDBCDataSource.java:266)
      org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStatisticsTest.testShutdownWhileScanningThenDelete(AutomaticIndexStatisticsTest.java:180)
      sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      java.lang.reflect.Method.invoke(Method.java:597)
      junit.framework.TestCase.runTest(TestCase.java:164)
      junit.framework.TestCase.runBare(TestCase.java:130)
      org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:112)
      junit.framework.TestResult$1.protect(TestResult.java:106)
      junit.framework.TestResult.runProtected(TestResult.java:124)
      junit.framework.TestResult.run(TestResult.java:109)
      junit.framework.TestCase.run(TestCase.java:120)
      junit.framework.TestSuite.runTest(TestSuite.java:230)
      junit.framework.TestSuite.run(TestSuite.java:225)
      junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      junit.framework.TestResult.runProtected(TestResult.java:124)
      junit.extensions.TestSetup.run(TestSetup.java:25)
      org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
      junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      junit.framework.TestResult.runProtected(TestResult.java:124)
      junit.extensions.TestSetup.run(TestSetup.java:25)
      junit.textui.TestRunner.doRun(TestRunner.java:121)
      junit.textui.TestRunner.start(TestRunner.java:185)
      junit.textui.TestRunner.main(TestRunner.java:143)

      Thread name=index-stat-thread id=18 priority=5 state=RUNNABLE isdaemon=true
      java.lang.Thread.dumpThreads(Native Method)
      java.lang.Thread.getAllStackTraces(Thread.java:1511)
      org.apache.derby.shared.common.sanity.ThreadDump.getStackDumpString(ThreadDump.java:34)
      sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      java.lang.reflect.Method.invoke(Method.java:597)
      org.apache.derby.shared.common.sanity.AssertFailure$1.run(AssertFailure.java:165)
      java.security.AccessController.doPrivileged(Native Method)
      org.apache.derby.shared.common.sanity.AssertFailure.dumpThreads(AssertFailure.java:159)
      org.apache.derby.shared.common.sanity.AssertFailure.<init>(AssertFailure.java:72)
      org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:162)
      org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:147)
      org.apache.derby.impl.store.access.btree.ControlRow.get(ControlRow.java:838)
      org.apache.derby.impl.store.access.btree.ControlRow.get(ControlRow.java:820)
      org.apache.derby.impl.store.access.btree.BTreeScan.reposition(BTreeScan.java:850)
      org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:109)
      org.apache.derby.impl.store.access.btree.BTreeScan.fetchNextGroup(BTreeScan.java:1596)
      org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl$KeyComparator.fetchRows(IndexStatisticsDaemonImpl.java:1103)
      org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.updateIndexStatsMinion(IndexStatisticsDaemonImpl.java:453)
      org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.generateStatistics(IndexStatisticsDaemonImpl.java:324)
      org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.run(IndexStatisticsDaemonImpl.java:710)
      java.lang.Thread.run(Thread.java:637)

      Thread name=Signal Dispatcher id=5 priority=9 state=RUNNABLE isdaemon=true

      Thread name=Timer-0 id=9 priority=5 state=WAITING isdaemon=true
      java.lang.Object.wait(Native Method)
      java.lang.Object.wait(Object.java:485)
      java.util.TimerThread.mainLoop(Timer.java:483)
      java.util.TimerThread.run(Timer.java:462)

      ---------------

      ....
      Time: 153.799

      OK (7 tests)

      1. derby-5037-01-aa-checkForShutdown.diff
        3 kB
        Rick Hillegas
      2. derby-5037-01-ab-checkForShutdown.diff
        3 kB
        Rick Hillegas
      3. derby-5037-2a-alternative_patch.diff
        2 kB
        Kristian Waagan
      4. derby_5037-01-ac-checkForShutdown.diff
        3 kB
        Rick Hillegas

        Issue Links

          Activity

          Hide
          Rick Hillegas added a comment -

          I have commented out all of the test cases in AutomaticIndexStatisticsTest except for testShutdownWhileScanningThenDelete(). The assertion still occurs with that test case left in.

          Show
          Rick Hillegas added a comment - I have commented out all of the test cases in AutomaticIndexStatisticsTest except for testShutdownWhileScanningThenDelete(). The assertion still occurs with that test case left in.
          Hide
          Mike Matrigali added a comment -

          Looking at the stack traces this looks like a problem with the istat thread running while another thread is shutting down the database. Looking at the stacks
          printed the test is at line 180:
          JDBCDataSource.shutdownDatabase(ds);

          Meanwhile the background thread is likely just trying to process the queue for the next bit of work. Derby monitor support for coordinated shutdown is a known issue, but I think at least for a very "ordered" shutdown where there is a request to shutdown we should be able to shutdown the known background thread
          in this case. I think it is a bigger problem if the whole system is shutting down due to some error found at the lowest level.

          Show
          Mike Matrigali added a comment - Looking at the stack traces this looks like a problem with the istat thread running while another thread is shutting down the database. Looking at the stacks printed the test is at line 180: JDBCDataSource.shutdownDatabase(ds); Meanwhile the background thread is likely just trying to process the queue for the next bit of work. Derby monitor support for coordinated shutdown is a known issue, but I think at least for a very "ordered" shutdown where there is a request to shutdown we should be able to shutdown the known background thread in this case. I think it is a bigger problem if the whole system is shutting down due to some error found at the lowest level.
          Hide
          Mike Matrigali added a comment -

          ps. kudo's to lily's work to get all the threads dumped on sanity error, made it very easy to see what was happening in this case.

          Show
          Mike Matrigali added a comment - ps. kudo's to lily's work to get all the threads dumped on sanity error, made it very easy to see what was happening in this case.
          Hide
          Rick Hillegas added a comment -

          Thanks to Mike for spotting that and to Lily for the instrumentation. Note that DataDictionary.stop() is supposed to shut down the the istat thread gracefully.

          Show
          Rick Hillegas added a comment - Thanks to Mike for spotting that and to Lily for the instrumentation. Note that DataDictionary.stop() is supposed to shut down the the istat thread gracefully.
          Hide
          Knut Anders Hatlen added a comment -

          Thanks to Erlend, who fixed DERBY-3618, you mean...

          Show
          Knut Anders Hatlen added a comment - Thanks to Erlend, who fixed DERBY-3618 , you mean...
          Hide
          Rick Hillegas added a comment - - edited

          Attaching derby-5037-01-aa-checkForShutdown.diff. This is a first attempt to fix this bug. I would like to hear your opinions.

          The approach taken here is to assume that exceptions raised during database shutdown are meaningless and can be thrown away. That is, the istat thread now tries to ignore exceptions which are raised during database shutdown.

          There is then the tricky bit of figuring out whether the database is being shutdown. I have found that it is not sufficient to check whether the istat thread itself has been marked for shutdown. Sometimes I see daemonStopped set to true (meaning that the DataDictionary has marked the thread for shutdown) and sometimes daemonStopped is still false when Store raises an exception.

          As a backup, I am also checking the status of Database.isActive(). I am not sure this is the best global sign that the database is being shutdown. Please let me know if you think there is a better global flag. I have a hunch that TopService.inShutdown is a better global flag but I do not see how to get to it.

          Touches the following file:

          M java/engine/org/apache/derby/impl/services/daemon/IndexStatisticsDaemonImpl.java

          Show
          Rick Hillegas added a comment - - edited Attaching derby-5037-01-aa-checkForShutdown.diff. This is a first attempt to fix this bug. I would like to hear your opinions. The approach taken here is to assume that exceptions raised during database shutdown are meaningless and can be thrown away. That is, the istat thread now tries to ignore exceptions which are raised during database shutdown. There is then the tricky bit of figuring out whether the database is being shutdown. I have found that it is not sufficient to check whether the istat thread itself has been marked for shutdown. Sometimes I see daemonStopped set to true (meaning that the DataDictionary has marked the thread for shutdown) and sometimes daemonStopped is still false when Store raises an exception. As a backup, I am also checking the status of Database.isActive(). I am not sure this is the best global sign that the database is being shutdown. Please let me know if you think there is a better global flag. I have a hunch that TopService.inShutdown is a better global flag but I do not see how to get to it. Touches the following file: M java/engine/org/apache/derby/impl/services/daemon/IndexStatisticsDaemonImpl.java
          Hide
          Kathey Marsden added a comment -

          Rick said: "The approach taken here is to assume that exceptions raised during database shutdown are meaningless and can be thrown away."

          I can recall cases where errors in shutdown were important to diagnosing user problems, so would prefer we not introduce a blanket assumption like that. If possible, I think it would be good for the shutdown process to do an orderly shutdown of the istat daemon if is running before shutdown.

          Pardon if this this an ignorant approach. I am not familiar with the istat implementation, but just know that general error suppression can be problematic.

          Show
          Kathey Marsden added a comment - Rick said: "The approach taken here is to assume that exceptions raised during database shutdown are meaningless and can be thrown away." I can recall cases where errors in shutdown were important to diagnosing user problems, so would prefer we not introduce a blanket assumption like that. If possible, I think it would be good for the shutdown process to do an orderly shutdown of the istat daemon if is running before shutdown. Pardon if this this an ignorant approach. I am not familiar with the istat implementation, but just know that general error suppression can be problematic.
          Hide
          Knut Anders Hatlen added a comment - - edited

          It sounds reasonable to me that the istat daemon simply ignores any exceptions if the database is being shut down under its feet. However, I think the patch also ignores exceptions when statistics are updated explicitly (e.g., by using ALTER TABLE or SYSCS_UPDATE_STATISTICS) because of the changes in runExplicitly(). We should probably continue raising exceptions if these explicit calls fail during shutdown.

          Show
          Knut Anders Hatlen added a comment - - edited It sounds reasonable to me that the istat daemon simply ignores any exceptions if the database is being shut down under its feet. However, I think the patch also ignores exceptions when statistics are updated explicitly (e.g., by using ALTER TABLE or SYSCS_UPDATE_STATISTICS) because of the changes in runExplicitly(). We should probably continue raising exceptions if these explicit calls fail during shutdown.
          Hide
          Mike Matrigali added a comment -

          I have not looked at patch yet.

          In keeping with trying to have as much zero admin as possible I am ok with the istat deamon handling it's own errors and not making those errors affect the rest of the server. It's job is to work in background and OPTIONALLY complete units of work. Because the
          work it does is optional, it is in a unique situation for error handling and should take advantage of it - basically it can catch everything
          clean up its resources move on. If it gets an error
          doing a piece of work it should catch it and try to figure out what to do. Maybe it throws it away, maybe it retries it. Deciding to throw away the unit of work when it detects that a shutdown is in progress is reasonable to me. As I understand the
          current design it is well suited to throwing away the unit of work, because it has a way to pick it up again the next time a query is run. I think a good design would be that it's errors do not affect user threads in any way. Once it throws away a unit of work and see's that
          shutdown is in progress it should just shutdown.

          For some sorts of database shutdown this "bottom-up" shutdown may be the only way it will work. For example when store gets
          a serious problem while logging, it raises a database shutdown level error and for safety basically nulls out the ability to do i/o to
          the log or the database. This results in the kind of errors that the istat daemon is seeing.

          For an orderly shutdown on the database, should the system wait for istat daemon to complete it's current unit of work? If so it
          seems like it should be possible to make the system wait for istat daemon to shutdown, but I am not sure how easy that would be.

          There may be some value to logging information about failures in the background istat thread to derby.log, but i don't think by default
          it should be enabled. I guess the worst case is if there is some bug causing the istat daemon to always fail it's unit of work. I know there
          is already some toggle for istat logging, so maybe it's error logging could be tied to this somehow.

          This is a similar methodology done for background processing done in store using the monitor provided background daemon thread.

          Show
          Mike Matrigali added a comment - I have not looked at patch yet. In keeping with trying to have as much zero admin as possible I am ok with the istat deamon handling it's own errors and not making those errors affect the rest of the server. It's job is to work in background and OPTIONALLY complete units of work. Because the work it does is optional, it is in a unique situation for error handling and should take advantage of it - basically it can catch everything clean up its resources move on. If it gets an error doing a piece of work it should catch it and try to figure out what to do. Maybe it throws it away, maybe it retries it. Deciding to throw away the unit of work when it detects that a shutdown is in progress is reasonable to me. As I understand the current design it is well suited to throwing away the unit of work, because it has a way to pick it up again the next time a query is run. I think a good design would be that it's errors do not affect user threads in any way. Once it throws away a unit of work and see's that shutdown is in progress it should just shutdown. For some sorts of database shutdown this "bottom-up" shutdown may be the only way it will work. For example when store gets a serious problem while logging, it raises a database shutdown level error and for safety basically nulls out the ability to do i/o to the log or the database. This results in the kind of errors that the istat daemon is seeing. For an orderly shutdown on the database, should the system wait for istat daemon to complete it's current unit of work? If so it seems like it should be possible to make the system wait for istat daemon to shutdown, but I am not sure how easy that would be. There may be some value to logging information about failures in the background istat thread to derby.log, but i don't think by default it should be enabled. I guess the worst case is if there is some bug causing the istat daemon to always fail it's unit of work. I know there is already some toggle for istat logging, so maybe it's error logging could be tied to this somehow. This is a similar methodology done for background processing done in store using the monitor provided background daemon thread.
          Hide
          Rick Hillegas added a comment -

          Thanks to Kathey, Knut, and Mike for the quick feedback. Tests passed cleanly on the first rev of the patch. Attaching derby-5037-01-ab-checkForShutdown.diff. This second rev addresses Knut's concern that the user is entitled to an error if database shutdown aborts an ALTER TABLE statement or an explicit attempt to recompute statistics.

          Concerning Kathey's comment: As I read the code, the orderly shutdown of the istat thread will happen regardless of whether the shutdown-induced exception is thrown away. I think that the system will wait for the DataDictionary to shutdown and DataDictionary shutdown will, in turn, wait for the istat stop() logic to finish.

          Concerning Mike's comments: I don't think that there is much value in trying to coax istat into finishing the current unit of work if the rest of the system is shutting down. The worst that can happen is that the current unit of work will be rolled back. For this particular problem, I think that's what the exiting Store has already done and there is no point in trying to ask Store to do anything else. Rolling back the current unit of work is pretty much equivalent to what will happen to the other queued up units of work during orderly shutdown: they will simply be thrown away. I recommend against prolonging or complicating the shutdown.

          There might be some value in adding trace logic around the exception-swallowing but I'm not sure how to filter the signal out of the noise here.

          Thanks,
          -Rick

          Show
          Rick Hillegas added a comment - Thanks to Kathey, Knut, and Mike for the quick feedback. Tests passed cleanly on the first rev of the patch. Attaching derby-5037-01-ab-checkForShutdown.diff. This second rev addresses Knut's concern that the user is entitled to an error if database shutdown aborts an ALTER TABLE statement or an explicit attempt to recompute statistics. Concerning Kathey's comment: As I read the code, the orderly shutdown of the istat thread will happen regardless of whether the shutdown-induced exception is thrown away. I think that the system will wait for the DataDictionary to shutdown and DataDictionary shutdown will, in turn, wait for the istat stop() logic to finish. Concerning Mike's comments: I don't think that there is much value in trying to coax istat into finishing the current unit of work if the rest of the system is shutting down. The worst that can happen is that the current unit of work will be rolled back. For this particular problem, I think that's what the exiting Store has already done and there is no point in trying to ask Store to do anything else. Rolling back the current unit of work is pretty much equivalent to what will happen to the other queued up units of work during orderly shutdown: they will simply be thrown away. I recommend against prolonging or complicating the shutdown. There might be some value in adding trace logic around the exception-swallowing but I'm not sure how to filter the signal out of the noise here. Thanks, -Rick
          Hide
          Rick Hillegas added a comment -

          Tests passed cleanly for me on derby-5037-01-ab-checkForShutdown.diff except for some variation of the istat-related instability in updatelocksJDBC30 tracked by DERBY-5038 and DERBY-5039:

                          • Diff file derbyall/encryptionAll/storemats/storemats/updatelocksJDBC30.diff
              • Start: updatelocksJDBC30 jdk1.5.0_22 storemats:storemats 2011-02-15 11:10:10 ***
                2504,2513d2503
                < APP |UserTran|TABLE |1 |IX |A |Tablelock |GRANT|ACTIVE
                < ij> next scan_cursor;
                < A |B |C
                < --------------------------------------------------------------------------------------------------------------------------------------------------------
                < 3 |-30 |-three
                < ij> update a set b=30,c='three' where current of scan_cursor;
                < 1 row inserted/updated/deleted
                < ij> select * from lock_table order by tabname, type desc, mode, cnt, lockname;
                < USERNAME|TRANTYPE|TYPE |CNT |MODE|TABNAME |LOCKNAME |STATE|STATUS
                < ---------------------------------------------------------------------------
                2514a2505,2514
                > ij> next scan_cursor;
                > A |B |C
                > --------------------------------------------------------------------------------------------------------------------------------------------------------
                > 3 |-30 |-three
                > ij> update a set b=30,c='three' where current of scan_cursor;
                > 1 row inserted/updated/deleted
                > ij> select * from lock_table order by tabname, type desc, mode, cnt, lockname;
                > USERNAME|TRANTYPE|TYPE |CNT |MODE|TABNAME |LOCKNAME |STATE|STATUS
                > ---------------------------------------------------------------------------
                > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE
                2524 del
                < APP |UserTran|TABLE |2 |IX |A |Tablelock |GRANT|ACTIVE
                2524a2524
                > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE
                2531 del
                < APP |UserTran|TABLE |2 |IX |A |Tablelock |GRANT|ACTIVE
                2531a2531
                > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE
                Test Failed.
              • End: updatelocksJDBC30 jdk1.5.0_22 storemats:storemats 2011-02-15 11:10:24 ***
                ------------------------------------------------------
          Show
          Rick Hillegas added a comment - Tests passed cleanly for me on derby-5037-01-ab-checkForShutdown.diff except for some variation of the istat-related instability in updatelocksJDBC30 tracked by DERBY-5038 and DERBY-5039 : Diff file derbyall/encryptionAll/storemats/storemats/updatelocksJDBC30.diff Start: updatelocksJDBC30 jdk1.5.0_22 storemats:storemats 2011-02-15 11:10:10 *** 2504,2513d2503 < APP |UserTran|TABLE |1 |IX |A |Tablelock |GRANT|ACTIVE < ij> next scan_cursor; < A |B |C < -------------------------------------------------------------------------------------------------------------------------------------------------------- < 3 |-30 |-three < ij> update a set b=30,c='three' where current of scan_cursor; < 1 row inserted/updated/deleted < ij> select * from lock_table order by tabname, type desc, mode, cnt, lockname; < USERNAME|TRANTYPE|TYPE |CNT |MODE|TABNAME |LOCKNAME |STATE|STATUS < --------------------------------------------------------------------------- 2514a2505,2514 > ij> next scan_cursor; > A |B |C > -------------------------------------------------------------------------------------------------------------------------------------------------------- > 3 |-30 |-three > ij> update a set b=30,c='three' where current of scan_cursor; > 1 row inserted/updated/deleted > ij> select * from lock_table order by tabname, type desc, mode, cnt, lockname; > USERNAME|TRANTYPE|TYPE |CNT |MODE|TABNAME |LOCKNAME |STATE|STATUS > --------------------------------------------------------------------------- > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE 2524 del < APP |UserTran|TABLE |2 |IX |A |Tablelock |GRANT|ACTIVE 2524a2524 > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE 2531 del < APP |UserTran|TABLE |2 |IX |A |Tablelock |GRANT|ACTIVE 2531a2531 > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE Test Failed. End: updatelocksJDBC30 jdk1.5.0_22 storemats:storemats 2011-02-15 11:10:24 *** ------------------------------------------------------
          Hide
          Knut Anders Hatlen added a comment -

          Thanks for making the changes, Rick. I'm fine with that patch.

          One small nit is that the comments in tryToGatherStats() seem to imply that StandardException can only be raised by non-debug jars and RuntimeException only by debug jars. I'm not sure that's necessarily correct. For example, in DERBY-5030 a NullPointerException is raised in this code when running with non-debug jars. I suppose the opposite could happen as well.

          Show
          Knut Anders Hatlen added a comment - Thanks for making the changes, Rick. I'm fine with that patch. One small nit is that the comments in tryToGatherStats() seem to imply that StandardException can only be raised by non-debug jars and RuntimeException only by debug jars. I'm not sure that's necessarily correct. For example, in DERBY-5030 a NullPointerException is raised in this code when running with non-debug jars. I suppose the opposite could happen as well.
          Hide
          Kristian Waagan added a comment -

          Attaching patch 2a.

          Providing my input as a patch I wrote when investigating this issue. I have not taken daemonStopped into consideration, as I don't know how it relates to db.isActive(). If the order in which they are set varies, the variable has to be considered too.

          Note also the debug code in the catch-block for RuntimeException, which should cause another RuntimeException to be thrown if DERBY-5030 is hit.

          I think Mike's comments/observations above agree pretty much with my thinking when writing the code. Seems there are several error-handling issues to iron out though...
          A few specific comments:
          o I decided to not make Derby wait for the background thread to finish on shutdown, as it might potentially be scanning a very large table.
          o Logging is rather verbose now during testing, but I agree it should be less verbose (or maybe turned off completely) when released.
          o I'm logging a lot of exceptions to aid testing/debugging. These should also go away, or be enabled by a property if the user wishes to do so.

          Show
          Kristian Waagan added a comment - Attaching patch 2a. Providing my input as a patch I wrote when investigating this issue. I have not taken daemonStopped into consideration, as I don't know how it relates to db.isActive(). If the order in which they are set varies, the variable has to be considered too. Note also the debug code in the catch-block for RuntimeException, which should cause another RuntimeException to be thrown if DERBY-5030 is hit. I think Mike's comments/observations above agree pretty much with my thinking when writing the code. Seems there are several error-handling issues to iron out though... A few specific comments: o I decided to not make Derby wait for the background thread to finish on shutdown, as it might potentially be scanning a very large table. o Logging is rather verbose now during testing, but I agree it should be less verbose (or maybe turned off completely) when released. o I'm logging a lot of exceptions to aid testing/debugging. These should also go away, or be enabled by a property if the user wishes to do so.
          Hide
          Kathey Marsden added a comment -

          Are the 376 failures on Win Vista 64 since istat was enabled the same thing as this issue?
          http://dbtg.foundry.sun.com/derby/test/Daily/jvm1.7/testing/testlog/vista-64/1069888-suitesAll_diff.txt
          Mostly it complains that wombat already exists, but has happened consistently since revision 1069888.

          Show
          Kathey Marsden added a comment - Are the 376 failures on Win Vista 64 since istat was enabled the same thing as this issue? http://dbtg.foundry.sun.com/derby/test/Daily/jvm1.7/testing/testlog/vista-64/1069888-suitesAll_diff.txt Mostly it complains that wombat already exists, but has happened consistently since revision 1069888.
          Hide
          Lily Wei added a comment -

          Apply derby-5037-2a-alternative_patch.diff. On Windows 7, AutomaticIndexStatisticsTest failed on testShutdownWhileScanningThenDelete(line 181) on assertDirectoryDeleted(constructDbPath(db));
          This is the stacktrace:
          [Error/failure logged at Tue Feb 15 19:54:25 PST 2011]
          junit.framework.AssertionFailedError: Failed to delete 3 files (root=c:\derby2\t
          runk\testtmp\system\singleUse\copyShutdown: c:\derby2\trunk\testtmp\system\singl
          eUse\copyShutdown\seg0\c481.dat (isDir=false, canRead=true, canWrite=true, size=
          22351872), c:\derby2\trunk\testtmp\system\singleUse\copyShutdown\seg0 (isDir=tru
          e, canRead=true, canWrite=true, size=12288), c:\derby2\trunk\testtmp\system\sing
          leUse\copyShutdown (isDir=true, canRead=true, canWrite=true, size=4096)
          at junit.framework.Assert.fail(Assert.java:47)
          at org.apache.derbyTesting.junit.BaseJDBCTestCase.assertDirectoryDeleted
          (BaseJDBCTestCase.java:1496)
          at org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStati
          sticsTest.testShutdownWhileScanningThenDelete(AutomaticIndexStatisticsTest.java:
          181)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.
          java:39)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
          sorImpl.java:25)
          at java.lang.reflect.Method.invoke(Method.java:597)
          at junit.framework.TestCase.runTest(TestCase.java:154)
          at junit.framework.TestCase.runBare(TestCase.java:127)
          at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:
          112)
          Without study too much of the code, , should we put more sleep between "JDBCDataSource.shutdownDatabase(ds); and assertDirectoryDeleted(constructDbPath(db));"?

          Will try derby-5037-01-ab-checkForShutdown.diff patch next? Thanks.

          Show
          Lily Wei added a comment - Apply derby-5037-2a-alternative_patch.diff. On Windows 7, AutomaticIndexStatisticsTest failed on testShutdownWhileScanningThenDelete(line 181) on assertDirectoryDeleted(constructDbPath(db)); This is the stacktrace: [Error/failure logged at Tue Feb 15 19:54:25 PST 2011] junit.framework.AssertionFailedError: Failed to delete 3 files (root=c:\derby2\t runk\testtmp\system\singleUse\copyShutdown: c:\derby2\trunk\testtmp\system\singl eUse\copyShutdown\seg0\c481.dat (isDir=false, canRead=true, canWrite=true, size= 22351872), c:\derby2\trunk\testtmp\system\singleUse\copyShutdown\seg0 (isDir=tru e, canRead=true, canWrite=true, size=12288), c:\derby2\trunk\testtmp\system\sing leUse\copyShutdown (isDir=true, canRead=true, canWrite=true, size=4096) at junit.framework.Assert.fail(Assert.java:47) at org.apache.derbyTesting.junit.BaseJDBCTestCase.assertDirectoryDeleted (BaseJDBCTestCase.java:1496) at org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStati sticsTest.testShutdownWhileScanningThenDelete(AutomaticIndexStatisticsTest.java: 181) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl. java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces sorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at junit.framework.TestCase.runTest(TestCase.java:154) at junit.framework.TestCase.runBare(TestCase.java:127) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java: 112) Without study too much of the code, , should we put more sleep between "JDBCDataSource.shutdownDatabase(ds); and assertDirectoryDeleted(constructDbPath(db));"? Will try derby-5037-01-ab-checkForShutdown.diff patch next? Thanks.
          Hide
          Kristian Waagan added a comment -

          I've seen the delete error before too. If it is always c481.dat it would maybe be helpful to find out which conglomerate/table this is.
          I've also seen intermittent delete errors in other tests before the istat code was committed, so that may be a separate issue.

          Lily, did you run the tests with a sane or an insane build?
          The 2a patch will only help with sane builds, with insane builds you will still get DERBY-5030.

          Show
          Kristian Waagan added a comment - I've seen the delete error before too. If it is always c481.dat it would maybe be helpful to find out which conglomerate/table this is. I've also seen intermittent delete errors in other tests before the istat code was committed, so that may be a separate issue. Lily, did you run the tests with a sane or an insane build? The 2a patch will only help with sane builds, with insane builds you will still get DERBY-5030 .
          Hide
          Rick Hillegas added a comment -

          Thanks for the continued analysis, everyone. Attaching derby-5037-01-ac-checkForShutdown.diff. This patch removes a comment line, hopefully addressing Knut's concerns about muddy wording. Committed at subversion revision 1071310.

          I have committed this patch in the interests of cleaning up the noise in the regression tests. Let's see if this does address DERBY-5030 also.

          No doubt, additional work can be done in the area of error logging and exception swallowing. If people want to recommend other approaches, I recommend filing new JIRAs to track those efforts.

          Thanks,
          -Rick

          Show
          Rick Hillegas added a comment - Thanks for the continued analysis, everyone. Attaching derby-5037-01-ac-checkForShutdown.diff. This patch removes a comment line, hopefully addressing Knut's concerns about muddy wording. Committed at subversion revision 1071310. I have committed this patch in the interests of cleaning up the noise in the regression tests. Let's see if this does address DERBY-5030 also. No doubt, additional work can be done in the area of error logging and exception swallowing. If people want to recommend other approaches, I recommend filing new JIRAs to track those efforts. Thanks, -Rick
          Hide
          Lily Wei added a comment -

          Thanks, Kristian and Rick. With with svn 1071319. I did not see DERBY-5030 (no delete problem from AutomaticIndexStatisticsTest). I still see it on the insane build for Windows 7.

          Show
          Lily Wei added a comment - Thanks, Kristian and Rick. With with svn 1071319. I did not see DERBY-5030 (no delete problem from AutomaticIndexStatisticsTest). I still see it on the insane build for Windows 7.
          Hide
          Lily Wei added a comment -

          Thanks Rick for point out generateStatistics() no longer calls updateIndexStatsMinion() directly. This is delete problem stack trace I am seeing on Windows 7 (insane build)
          [Error/failure logged at Fri Feb 18 11:09:46 PST 2011]
          junit.framework.AssertionFailedError: Failed to delete 3 files (root=c:\derby2\t
          runk\testtmp\system\singleUse\copyShutdown: c:\derby2\trunk\testtmp\system\singl
          eUse\copyShutdown\seg0\c481.dat (isDir=false, canRead=true, canWrite=true, size=
          22351872), c:\derby2\trunk\testtmp\system\singleUse\copyShutdown\seg0 (isDir=tru
          e, canRead=true, canWrite=true, size=12288), c:\derby2\trunk\testtmp\system\sing
          leUse\copyShutdown (isDir=true, canRead=true, canWrite=true, size=4096)
          at junit.framework.Assert.fail(Assert.java:47)
          at org.apache.derbyTesting.junit.BaseJDBCTestCase.assertDirectoryDeleted
          (BaseJDBCTestCase.java:1496)
          at org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStati
          sticsTest.testShutdownWhileScanningThenDelete(AutomaticIndexStatisticsTest.java:
          188)
          at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
          at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.
          java:39)
          at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces
          sorImpl.java:25)
          at java.lang.reflect.Method.invoke(Method.java:597)
          at junit.framework.TestCase.runTest(TestCase.java:154)
          at junit.framework.TestCase.runBare(TestCase.java:127)
          at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:
          112)
          at junit.framework.TestResult$1.protect(TestResult.java:106)
          at junit.framework.TestResult.runProtected(TestResult.java:124)
          at junit.framework.TestResult.run(TestResult.java:109)
          at junit.framework.TestCase.run(TestCase.java:118)
          at junit.framework.TestSuite.runTest(TestSuite.java:208)
          at junit.framework.TestSuite.run(TestSuite.java:203)
          at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22)
          I think it is like what Kristian said earlier, it is relate to unable to delete singleUse/copyShutdown/seg0/c481.dat. Thanks!

          Show
          Lily Wei added a comment - Thanks Rick for point out generateStatistics() no longer calls updateIndexStatsMinion() directly. This is delete problem stack trace I am seeing on Windows 7 (insane build) [Error/failure logged at Fri Feb 18 11:09:46 PST 2011] junit.framework.AssertionFailedError: Failed to delete 3 files (root=c:\derby2\t runk\testtmp\system\singleUse\copyShutdown: c:\derby2\trunk\testtmp\system\singl eUse\copyShutdown\seg0\c481.dat (isDir=false, canRead=true, canWrite=true, size= 22351872), c:\derby2\trunk\testtmp\system\singleUse\copyShutdown\seg0 (isDir=tru e, canRead=true, canWrite=true, size=12288), c:\derby2\trunk\testtmp\system\sing leUse\copyShutdown (isDir=true, canRead=true, canWrite=true, size=4096) at junit.framework.Assert.fail(Assert.java:47) at org.apache.derbyTesting.junit.BaseJDBCTestCase.assertDirectoryDeleted (BaseJDBCTestCase.java:1496) at org.apache.derbyTesting.functionTests.tests.store.AutomaticIndexStati sticsTest.testShutdownWhileScanningThenDelete(AutomaticIndexStatisticsTest.java: 188) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl. java:39) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAcces sorImpl.java:25) at java.lang.reflect.Method.invoke(Method.java:597) at junit.framework.TestCase.runTest(TestCase.java:154) at junit.framework.TestCase.runBare(TestCase.java:127) at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java: 112) at junit.framework.TestResult$1.protect(TestResult.java:106) at junit.framework.TestResult.runProtected(TestResult.java:124) at junit.framework.TestResult.run(TestResult.java:109) at junit.framework.TestCase.run(TestCase.java:118) at junit.framework.TestSuite.runTest(TestSuite.java:208) at junit.framework.TestSuite.run(TestSuite.java:203) at junit.extensions.TestDecorator.basicRun(TestDecorator.java:22) I think it is like what Kristian said earlier, it is relate to unable to delete singleUse/copyShutdown/seg0/c481.dat. Thanks!
          Hide
          Rick Hillegas added a comment -

          The patch appears to have fixed this problem.

          Show
          Rick Hillegas added a comment - The patch appears to have fixed this problem.
          Hide
          Kristian Waagan added a comment -

          Closing issue.

          Show
          Kristian Waagan added a comment - Closing issue.

            People

            • Assignee:
              Rick Hillegas
              Reporter:
              Rick Hillegas
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development