Derby
  1. Derby
  2. DERBY-5038

updatelocks test failing in tinderbox when background update statistics are enabled.

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.8.1.2
    • Fix Version/s: 10.8.1.2
    • Component/s: Test
    • Labels:
      None

      Description

      updatelocks is failing consistently in tinderbox since checkin 1069598 for DERBY-4939: Enable istat daemon and tests

      http://dbtg.foundry.sun.com/derby/test/tinderbox_trunk16/jvm1.6/testing/testlog/SunOS-5.10_i86pc-i386/1070190-derbyall_diff.txt

                      • Diff file derbyall/encryptionAll/storemats/storemats/updatelocks.diff
          • Start: updatelocks jdk1.6.0_18 storemats:storemats 2011-02-13 09:28:29 ***
            2847,2856d2846
            < 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
            < ---------------------------------------------------------------------------
            2857a2848,2857
            > 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
            2867 del
            < APP |UserTran|TABLE |2 |IX |A |Tablelock |GRANT|ACTIVE
            2867a2867
            > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE
            2874 del
            < APP |UserTran|TABLE |2 |IX |A |Tablelock |GRANT|ACTIVE
            2874a2874
            > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE
            14688,14697d14687
            < 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
            < ---------------------------------------------------------------------------
            14698a14689,14698
            > 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
            14708 del
            < APP |UserTran|TABLE |2 |IX |A |Tablelock |GRANT|ACTIVE
            14708a14708
            > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE
            14716 del
            < APP |UserTran|TABLE |2 |IX |A |Tablelock |GRANT|ACTIVE
            14716a14716
            > APP |UserTran|TABLE |3 |IX |A |Tablelock |GRANT|ACTIVE
            Test Failed.
          • End: updatelocks jdk1.6.0_18 storemats:storemats 2011-02-13 09:28:40 ***
      1. derby.log
        113 kB
        Mike Matrigali

        Issue Links

          Activity

          Hide
          Mike Matrigali added a comment -

          DERBY-4833 discusses the possible need to disable the background update statistics for this test.

          Show
          Mike Matrigali added a comment - DERBY-4833 discusses the possible need to disable the background update statistics for this test.
          Hide
          Mike Matrigali added a comment -

          I believe the checkin for DERBY-4939 broke this test.

          Show
          Mike Matrigali added a comment - I believe the checkin for DERBY-4939 broke this test.
          Hide
          Mike Matrigali added a comment -

          I see that there was some discussion that this test might be broken by the istats daemon. I am happy to do this, but would like to get an
          answer first. This test only has very small tables with at most 7 rows. Also when there are indexes the indexes are always created after
          inserting the rows which should create statistics when the indexes are created. Does it make sense that the statistics thread is running in
          background for this test? I would rather not hide the possible bug until know the answer to this.

          Here is some info from the derby.log in a run on my own laptop (was not sure how to get at these files on the public test servers). Inline I have just included
          some of the index-stat-thread info, I'll attach the full derby.log:
          ----------------------------------------------------------------^M
          Sun Feb 13 00:45:28 PST 2011:
          Booting Derby version The Apache Software Foundation - Apache Derby - 10.8.0.0 alpha - (1): instance a816c00e-012e-1e32-2c4f-000008a4d812
          on database directory C:\derby\s1\systest\out\derby\derbyall\storeall\storemats\storemats\updatelocks\wombat with class loader sun.misc.Launcher$AppClassLoader
          @4ae54ae5
          Loaded from Access denied (java.lang.RuntimePermission getProtectionDomain)^M
          java.vendor=IBM Corporation
          java.runtime.version=jvmwi3260sr9-20101124_69295
          java.fullversion=JRE 1.6.0 IBM J9 2.4 Windows XP x86-32 jvmwi3260sr9-20101124_69295 (JIT enabled, AOT enabled)
          J9VM - 20101124_069295
          JIT - r9_20101028_17488ifx2
          GC - 20101027_AA^M
          Database Class Loader started - derby.database.classpath=''^M
          – the non-index tests, and in the index in the index based tests).^M
          ^M
          – cursor, no index run^M
          Sun Feb 13 00:45:41 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - a770417f-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:41 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:41 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index ef1ac193-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2])^M
          Sun Feb 13 00:45:41 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1185=0ms)^M
          Sun Feb 13 00:45:41 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (32 ms)^M
          Sun Feb 13 00:45:41 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - 194c4222-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:41 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:41 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index 0425c236-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2])^M
          Sun Feb 13 00:45:41 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1217=0ms)^M
          Sun Feb 13 00:45:41 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (16 ms)^M
          Sun Feb 13 00:45:42 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - 2a2882b5-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:42 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:42 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index f7e102c9-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1])^M
          Sun Feb 13 00:45:42 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1249=0ms)^M
          Sun Feb 13 00:45:42 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:43 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - ce0ac313-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:43 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:43 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index 1d994327-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1])^M
          Sun Feb 13 00:45:43 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1281=0ms)^M
          Sun Feb 13 00:45:43 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          – conglomerate (heap in the non-index tests, and in the index in the index ^M
          – based tests).^M
          ^M
          – cursor, no index run^M
          Sun Feb 13 00:45:44 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - b596c40e-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:44 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:44 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 97fc0420-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2,2])
          ^M
          Sun Feb 13 00:45:44 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1345=0ms)^M
          Sun Feb 13 00:45:44 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:45 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - 2d1404a1-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:45 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:45 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index 620ec4b3-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2,2])
          ^M
          Sun Feb 13 00:45:45 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1377=0ms)^M
          Sun Feb 13 00:45:45 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:46 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - b9ab8534-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 613bc546-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1,1])
          ^M generation complete (0 ms)^M
          Sun Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1409=0ms)^Mf-000008a4d812 reason=[
          Sun Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:46 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - a4d18584-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^Mhread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 613bc546-012e-1e32-2c4f-00000
          Sun Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 4dc9c596-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1,1])
          ^Mn Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1441=0ms)^Mf-000008a4d812 reason=[
          Sun Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          – the non-index tests, and in the index in the index based tests).^M "APP"."A": generating index statistics^M
          ^Mn Feb 13 00:45:46 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 4dc9c596-012e-1e32-2c4f-00000
          – cursor, no index run^M1])^M
          Sun Feb 13 00:45:47 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - 25b18684-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^Mhread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:47 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:47 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 26750698-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2])^M
          Sun Feb 13 00:45:47 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1505=0ms)^M
          Sun Feb 13 00:45:47 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:48 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - 279f4717-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:48 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:48 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index 8b41c72b-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2])^M
          Sun Feb 13 00:45:48 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1537=0ms)^M
          Sun Feb 13 00:45:48 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:49 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - 9ea747aa-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:49 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:49 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index a528c7be-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1])^M
          Sun Feb 13 00:45:49 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1569=0ms)^M
          Sun Feb 13 00:45:49 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:49 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - f10707f9-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:49 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:49 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index d913880d-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1])^M
          Sun Feb 13 00:45:49 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1601=0ms)^M
          Sun Feb 13 00:45:49 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          – conglomerate (heap in the non-index tests, and in the index in the index ^M
          – based tests).^M
          ^M
          – cursor, no index run^M
          Sun Feb 13 00:45:51 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - a1b6c8f3-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:51 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:51 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 6a228905-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2,2])
          ^M
          Sun Feb 13 00:45:51 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1665=0ms)^M
          Sun Feb 13 00:45:51 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:51 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - 3d13c986-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:51 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:51 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index 38150998-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2,2])
          ^M
          Sun Feb 13 00:45:51 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1697=0ms)^M
          Sun Feb 13 00:45:51 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:52 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - bd8b0a19-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:52 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:52 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 0b21ca2b-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1,1])
          ^M62968495368] (queueSize=1)^M
          Sun Feb 13 00:45:52 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1729=0ms)^MM
          Sun Feb 13 00:45:52 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M20-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2,2])
          Sun Feb 13 00:45:53 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - bffb0a68-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^Mhread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1345=0ms)^M
          Sun Feb 13 00:45:53 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:53 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": wrote stats for index 7ef54a7a-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1,1])
          ^M62968495368] (queueSize=1)^M
          Sun Feb 13 00:45:53 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1761=0ms)^MM
          Sun Feb 13 00:45:53 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^Mb3-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2,2])
          – the non-index tests, and in the index in the index based tests).^M
          ^Mn Feb 13 00:45:45 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": scan durations (c1377=0ms)^M
          – cursor, no index run^M011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:54 PST 2011 Thread[main,5,main] {istat}

          "APP"."A": update scheduled - 79db0b68-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^M
          Sun Feb 13 00:45:54 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:54 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index 93128b7c-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2])^M
          Sun Feb 13 00:45:54 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1825=0ms)^M
          Sun Feb 13 00:45:54 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (16 ms)^M-000008a4d812 reason=[
          Sun Feb 13 00:45:54 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - 0f83cbfb-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^Mhread[main,5,main] {istat}

          "APP"."A": update scheduled - a4d18584-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          Sun Feb 13 00:45:54 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M6-012e-1e32-2c4f-00000
          Sun Feb 13 00:45:54 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index 8b9a4c0f-012e-1e32-2c4f-000008a4d812 (rows=2, card=[2])^M
          Sun Feb 13 00:45:54 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1857=0ms)^M96-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1,1])
          Sun Feb 13 00:45:54 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:55 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - 5a46cc8e-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^Mhread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^M
          Sun Feb 13 00:45:55 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": generating index statistics^M
          Sun Feb 13 00:45:55 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": wrote stats for index 793c4ca2-012e-1e32-2c4f-000008a4d812 (rows=1, card=[1])^M
          Sun Feb 13 00:45:55 PST 2011 Thread[index-stat-thread,5,main]

          {istat} "APP"."A": scan durations (c1889=0ms)^M
          Sun Feb 13 00:45:55 PST 2011 Thread[index-stat-thread,5,main] {istat}

          "APP"."A": generation complete (0 ms)^Mf-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          Sun Feb 13 00:45:55 PST 2011 Thread[main,5,main]

          {istat} "APP"."A": update scheduled - 6d3d8cdd-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25
          2762968495368] (queueSize=1)^Mhread[index-stat-thread,5,main] {istat}

          "APP"."A": generating index statistics^M

          Show
          Mike Matrigali added a comment - I see that there was some discussion that this test might be broken by the istats daemon. I am happy to do this, but would like to get an answer first. This test only has very small tables with at most 7 rows. Also when there are indexes the indexes are always created after inserting the rows which should create statistics when the indexes are created. Does it make sense that the statistics thread is running in background for this test? I would rather not hide the possible bug until know the answer to this. Here is some info from the derby.log in a run on my own laptop (was not sure how to get at these files on the public test servers). Inline I have just included some of the index-stat-thread info, I'll attach the full derby.log: ----------------------------------------------------------------^M Sun Feb 13 00:45:28 PST 2011: Booting Derby version The Apache Software Foundation - Apache Derby - 10.8.0.0 alpha - (1): instance a816c00e-012e-1e32-2c4f-000008a4d812 on database directory C:\derby\s1\systest\out\derby\derbyall\storeall\storemats\storemats\updatelocks\wombat with class loader sun.misc.Launcher$AppClassLoader @4ae54ae5 Loaded from Access denied (java.lang.RuntimePermission getProtectionDomain)^M java.vendor=IBM Corporation java.runtime.version=jvmwi3260sr9-20101124_69295 java.fullversion=JRE 1.6.0 IBM J9 2.4 Windows XP x86-32 jvmwi3260sr9-20101124_69295 (JIT enabled, AOT enabled) J9VM - 20101124_069295 JIT - r9_20101028_17488ifx2 GC - 20101027_AA^M Database Class Loader started - derby.database.classpath=''^M – the non-index tests, and in the index in the index based tests).^M ^M – cursor, no index run^M Sun Feb 13 00:45:41 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - a770417f-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:41 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:41 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index ef1ac193-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2] )^M Sun Feb 13 00:45:41 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1185=0ms)^M Sun Feb 13 00:45:41 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (32 ms)^M Sun Feb 13 00:45:41 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 194c4222-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:41 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:41 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 0425c236-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2] )^M Sun Feb 13 00:45:41 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1217=0ms)^M Sun Feb 13 00:45:41 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (16 ms)^M Sun Feb 13 00:45:42 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 2a2882b5-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:42 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:42 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index f7e102c9-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1] )^M Sun Feb 13 00:45:42 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1249=0ms)^M Sun Feb 13 00:45:42 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:43 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - ce0ac313-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:43 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:43 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 1d994327-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1] )^M Sun Feb 13 00:45:43 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1281=0ms)^M Sun Feb 13 00:45:43 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M – conglomerate (heap in the non-index tests, and in the index in the index ^M – based tests).^M ^M – cursor, no index run^M Sun Feb 13 00:45:44 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - b596c40e-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:44 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:44 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 97fc0420-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2,2] ) ^M Sun Feb 13 00:45:44 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1345=0ms)^M Sun Feb 13 00:45:44 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:45 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 2d1404a1-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:45 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:45 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 620ec4b3-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2,2] ) ^M Sun Feb 13 00:45:45 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1377=0ms)^M Sun Feb 13 00:45:45 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:46 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - b9ab8534-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 613bc546-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1,1] ) ^M generation complete (0 ms)^M Sun Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1409=0ms)^Mf-000008a4d812 reason=[ Sun Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:46 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - a4d18584-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^Mhread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 613bc546-012e-1e32-2c4f-00000 Sun Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 4dc9c596-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1,1] ) ^Mn Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1441=0ms)^Mf-000008a4d812 reason=[ Sun Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M – the non-index tests, and in the index in the index based tests).^M "APP"."A": generating index statistics^M ^Mn Feb 13 00:45:46 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 4dc9c596-012e-1e32-2c4f-00000 – cursor, no index run^M1])^M Sun Feb 13 00:45:47 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 25b18684-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^Mhread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:47 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:47 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 26750698-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2] )^M Sun Feb 13 00:45:47 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1505=0ms)^M Sun Feb 13 00:45:47 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:48 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 279f4717-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:48 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:48 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 8b41c72b-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2] )^M Sun Feb 13 00:45:48 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1537=0ms)^M Sun Feb 13 00:45:48 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:49 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 9ea747aa-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:49 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:49 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index a528c7be-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1] )^M Sun Feb 13 00:45:49 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1569=0ms)^M Sun Feb 13 00:45:49 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:49 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - f10707f9-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:49 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:49 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index d913880d-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1] )^M Sun Feb 13 00:45:49 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1601=0ms)^M Sun Feb 13 00:45:49 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M – conglomerate (heap in the non-index tests, and in the index in the index ^M – based tests).^M ^M – cursor, no index run^M Sun Feb 13 00:45:51 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - a1b6c8f3-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:51 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:51 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 6a228905-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2,2] ) ^M Sun Feb 13 00:45:51 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1665=0ms)^M Sun Feb 13 00:45:51 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:51 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 3d13c986-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:51 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:51 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 38150998-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2,2] ) ^M Sun Feb 13 00:45:51 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1697=0ms)^M Sun Feb 13 00:45:51 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:52 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - bd8b0a19-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:52 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:52 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 0b21ca2b-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1,1] ) ^M62968495368] (queueSize=1)^M Sun Feb 13 00:45:52 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1729=0ms)^MM Sun Feb 13 00:45:52 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M20-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2,2] ) Sun Feb 13 00:45:53 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - bffb0a68-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^Mhread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1345=0ms)^M Sun Feb 13 00:45:53 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:53 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 7ef54a7a-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1,1] ) ^M62968495368] (queueSize=1)^M Sun Feb 13 00:45:53 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1761=0ms)^MM Sun Feb 13 00:45:53 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^Mb3-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2,2] ) – the non-index tests, and in the index in the index based tests).^M ^Mn Feb 13 00:45:45 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1377=0ms)^M – cursor, no index run^M011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:54 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 79db0b68-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^M Sun Feb 13 00:45:54 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:54 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 93128b7c-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2] )^M Sun Feb 13 00:45:54 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1825=0ms)^M Sun Feb 13 00:45:54 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (16 ms)^M-000008a4d812 reason=[ Sun Feb 13 00:45:54 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 0f83cbfb-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^Mhread [main,5,main] {istat} "APP"."A": update scheduled - a4d18584-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 Sun Feb 13 00:45:54 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M6-012e-1e32-2c4f-00000 Sun Feb 13 00:45:54 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 8b9a4c0f-012e-1e32-2c4f-000008a4d812 (rows=2, card= [2] )^M Sun Feb 13 00:45:54 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1857=0ms)^M96-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1,1] ) Sun Feb 13 00:45:54 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:55 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 5a46cc8e-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^Mhread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^M Sun Feb 13 00:45:55 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M Sun Feb 13 00:45:55 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": wrote stats for index 793c4ca2-012e-1e32-2c4f-000008a4d812 (rows=1, card= [1] )^M Sun Feb 13 00:45:55 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": scan durations (c1889=0ms)^M Sun Feb 13 00:45:55 PST 2011 Thread [index-stat-thread,5,main] {istat} "APP"."A": generation complete (0 ms)^Mf-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 Sun Feb 13 00:45:55 PST 2011 Thread [main,5,main] {istat} "APP"."A": update scheduled - 6d3d8cdd-012e-1e32-2c4f-000008a4d812 reason=[t-est=2, i-est=7 => cmp=1.25 2762968495368] (queueSize=1)^Mhread [index-stat-thread,5,main] {istat} "APP"."A": generating index statistics^M
          Hide
          Mike Matrigali added a comment -

          Here is a full derby.log from a run with diffs in updatelocks due to locks in background by the stat daemon.

          Show
          Mike Matrigali added a comment - Here is a full derby.log from a run with diffs in updatelocks due to locks in background by the stat daemon.
          Hide
          Knut Anders Hatlen added a comment -

          Maybe the updates happen because of deletes after the index has been created? See for example updateBtreeSetLocks.subsql and updatecursorlocks.subsql, which are invoked from updatelocks.sql. It's probably not necessary to update the statistics when a table shrinks from 7 rows to 2 rows, and I think preventing that was what derby.storage.indexStats.debug.absdiffThreshold was introduced for. But that property currently defaults to 0 so that it doesn't have any effect.

          Show
          Knut Anders Hatlen added a comment - Maybe the updates happen because of deletes after the index has been created? See for example updateBtreeSetLocks.subsql and updatecursorlocks.subsql, which are invoked from updatelocks.sql. It's probably not necessary to update the statistics when a table shrinks from 7 rows to 2 rows, and I think preventing that was what derby.storage.indexStats.debug.absdiffThreshold was introduced for. But that property currently defaults to 0 so that it doesn't have any effect.
          Hide
          Kristian Waagan added a comment -

          In an attempt to stabilize the regression tests, I committed a patch (under DERBY-4940) which increases the default absdiff threshold from zero to 1000.
          Let's see if that's enough, or if there are other aspects of the istat daemon interfering with the test(s).

          Show
          Kristian Waagan added a comment - In an attempt to stabilize the regression tests, I committed a patch (under DERBY-4940 ) which increases the default absdiff threshold from zero to 1000. Let's see if that's enough, or if there are other aspects of the istat daemon interfering with the test(s).
          Hide
          Mike Matrigali added a comment -

          looks like checkin to tune istats as part of DERBY-4090 fixed this issue.

          Show
          Mike Matrigali added a comment - looks like checkin to tune istats as part of DERBY-4090 fixed this issue.
          Hide
          Knut Anders Hatlen added a comment -

          [bulk update] Close all resolved issues that haven't been updated for more than one year.

          Show
          Knut Anders Hatlen added a comment - [bulk update] Close all resolved issues that haven't been updated for more than one year.

            People

            • Assignee:
              Mike Matrigali
              Reporter:
              Mike Matrigali
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development