Derby
  1. Derby
  2. DERBY-4181

SQLState.LANG_IGNORE_MISSING_INDEX_ROW_DURING_DELETE during NsTest run

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Invalid
    • Affects Version/s: 10.4.2.0, 10.5.1.1, 10.6.1.0
    • Fix Version/s: None
    • Component/s: Store
    • Labels:
      None
    • Environment:
      Suse Linux 10, IBM 1.6 SR4

      Description

      During the NsTest runs for 10.5.1.0 and 10.5.1.1 I initially ignored warnings showing up in the server's derby.log file:

      WARNING: While deleting a row from a table the index row for base table row (594,12) was not found in index with conglomerate id 1,185. This problem has automatically been corrected as part of the delete operation.

      However, I don't think this is a completely healthy warning, I think it indicates there was corruption in the index.
      I'll investigate further.

      1. derby.log
        40 kB
        Mike Matrigali
      2. derby.properties
        1 kB
        Mike Matrigali
      3. derby4181debug.diff
        3 kB
        Mike Matrigali
      4. log_excerpt_sample_assert.txt
        5 kB
        Kathey Marsden
      5. ReproDerby4181.derby.log
        258 kB
        Kathey Marsden
      6. ReproDerby4181.java
        2 kB
        Kathey Marsden
      7. ReproDerby4181.java
        5 kB
        Kathey Marsden
      8. ReproDerby4181.out
        158 kB
        Kathey Marsden
      9. run1serverlog.jar
        13 kB
        Myrna van Lunteren
      10. serverlog.jar
        6.13 MB
        Myrna van Lunteren

        Activity

        Hide
        Knut Anders Hatlen added a comment -

        Not sure if it's related, but we recently had a similar report on derby-user: http://mail-archives.apache.org/mod_mbox/db-derby-user/200904.mbox/%3c49E5A9CF.ECB9.0090.0@gwava.com%3e

        Show
        Knut Anders Hatlen added a comment - Not sure if it's related, but we recently had a similar report on derby-user: http://mail-archives.apache.org/mod_mbox/db-derby-user/200904.mbox/%3c49E5A9CF.ECB9.0090.0@gwava.com%3e
        Hide
        Myrna van Lunteren added a comment -

        Attaching 2 jarred up derby.log files.
        run1server.jar contains the 10.5.rc2 server's derby.log file when run with sane jars but no derby.properties.
        It shows an assert which I think is similar to the warning I saw in my insane jar runs:
        org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED Index row (9475777.6508320800,(590,44)) not found in conglomerateid 1185Current scan =
        btree = BTREE: containerid = Container(0, 1185);nKeyFields = 2;nUniqueColumns = 2;allowDuplicates = false
        [....]
        serverlog.jar is from a run with 10.5.rc2 and sane jars and with derby.properties in place (both in the dir for the server and for the client: derby.language.logStatementText=true, derby.stream.error.logSeverityLevel=0, derby.infolog.append=tru).
        This one first shows a different but I think related index AssertFailure:
        ERROR 38000: The exception 'org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED last row on left page 233 > than first row on right page 110
        left last row = col[0]=4988358813.6843080000col[1]=(155,20)col[2]=214right first row = col[0]=16968984.2552292000col[1]=(180,14)col[2]=147
        BRANCH(233)(lev=1): num recs = 80
        left = 106;right = 110;parent = 1;isRoot = false;left child page = 227; last > first of
        BRANCH(110)(lev=1): num recs = 96
        left = 233;right = 200;parent = 1;isRoot = false;left child page = 94;' was thrown while evaluating an expression.
        at org.apache.derby.iapi.error.StandardException.newException(StandardException.java:296)
        at org.apache.derby.iapi.error.StandardException.unexpectedUserException(StandardException.java:583)
        at org.apache.derby.impl.services.reflect.DirectCall.invoke(ReflectGeneratedClass.java:164)
        at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.doProjection(ProjectRestrictResultSet.java:497)
        at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(ProjectRestrictResultSet.java:291)
        at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(BasicNoPutResultSetImpl.java:460)
        at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:427)
        at org.apache.derby.impl.jdbc.EmbedResultSet.next(EmbedResultSet.java:371)
        at org.apache.derby.impl.drda.DRDAConnThread.writeFDODTA(DRDAConnThread.java:6866)
        at org.apache.derby.impl.drda.DRDAConnThread.writeQRYDTA(DRDAConnThread.java:6762)
        at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:859)
        at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:290)
        Caused by: org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED last row on left page 233 > than first row on right page 110
        left last row = col[0]=4988358813.6843080000col[1]=(155,20)col[2]=214right first row = col[0]=16968984.2552292000col[1]=(180,14)col[2]=147
        BRANCH(233)(lev=1): num recs = 80
        left = 106;right = 110;parent = 1;isRoot = false;left child page = 227; last > first of
        BRANCH(110)(lev=1): num recs = 96
        left = 233;right = 200;parent = 1;isRoot = false;left child page = 94;
        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.compareRowsOnSiblings(ControlRow.java:1532)
        at org.apache.derby.impl.store.access.btree.ControlRow.checkSiblings(ControlRow.java:1642)
        at org.apache.derby.impl.store.access.btree.ControlRow.checkGeneric(ControlRow.java:1423)
        at org.apache.derby.impl.store.access.btree.BranchControlRow.checkConsistency(BranchControlRow.java:942)
        at org.apache.derby.impl.store.access.btree.BranchControlRow.checkChildren(BranchControlRow.java:1038)
        at org.apache.derby.impl.store.access.btree.BranchControlRow.checkConsistency(BranchControlRow.java:1013)
        at org.apache.derby.impl.store.access.btree.OpenBTree.checkConsistency(OpenBTree.java:283)
        at org.apache.derby.iapi.db.ConsistencyChecker.checkTable(ConsistencyChecker.java:204)
        at org.apache.derby.catalog.SystemProcedures.SYSCS_CHECK_TABLE(SystemProcedures.java:977)
        at org.apache.derby.exe.acb05c5046x0120xd4b9xebbdx00000454210e0.e3(Unknown Source)
        at org.apache.derby.impl.services.reflect.DirectCall.invoke(ReflectGeneratedClass.java:145)
        ... 9 more
        ============= begin nested exception, level (1) ===========
        org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED last row on left page 233 > than first row on right page 110
        left last row = col[0]=4988358813.6843080000col[1]=(155,20)col[2]=214right first row = col[0]=16968984.2552292000col[1]=(180,14)col[2]=147
        BRANCH(233)(lev=1): num recs = 80
        left = 106;right = 110;parent = 1;isRoot = false;left child page = 227; last > first of
        BRANCH(110)(lev=1): num recs = 96
        left = 233;right = 200;parent = 1;isRoot = false;left child page = 94;
        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.compareRowsOnSiblings(ControlRow.java:1532)
        at org.apache.derby.impl.store.access.btree.ControlRow.checkSiblings(ControlRow.java:1642)
        at org.apache.derby.impl.store.access.btree.ControlRow.checkGeneric(ControlRow.java:1423)
        at org.apache.derby.impl.store.access.btree.BranchControlRow.checkConsistency(BranchControlRow.java:942)
        at org.apache.derby.impl.store.access.btree.BranchControlRow.checkChildren(BranchControlRow.java:1038)
        at org.apache.derby.impl.store.access.btree.BranchControlRow.checkConsistency(BranchControlRow.java:1013)
        at org.apache.derby.impl.store.access.btree.OpenBTree.checkConsistency(OpenBTree.java:283)
        at org.apache.derby.iapi.db.ConsistencyChecker.checkTable(ConsistencyChecker.java:204)
        at org.apache.derby.catalog.SystemProcedures.SYSCS_CHECK_TABLE(SystemProcedures.java:977)
        at org.apache.derby.exe.acb05c5046x0120xd4b9xebbdx00000454210e0.e3(Unknown Source)
        at org.apache.derby.impl.services.reflect.DirectCall.invoke(ReflectGeneratedClass.java:145)
        at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.doProjection(ProjectRestrictResultSet.java:497)
        at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(ProjectRestrictResultSet.java:291)
        at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(BasicNoPutResultSetImpl.java:460)
        at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:427)
        at org.apache.derby.impl.jdbc.EmbedResultSet.next(EmbedResultSet.java:371)
        at org.apache.derby.impl.drda.DRDAConnThread.writeFDODTA(DRDAConnThread.java:6866)
        at org.apache.derby.impl.drda.DRDAConnThread.writeQRYDTA(DRDAConnThread.java:6762)
        at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:859)
        at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:290)
        (Skipping thread dump because of insufficient permissions:
        java.security.AccessControlException: Access denied (java.lang.RuntimePermission getStackTrace))

        ============= end nested exception, level (1) ===========

        followed somewhat later by:
        2009-04-23 20:05:05.986 GMT Thread[DRDAConnThread_11,5,main] (XID = 94271), (SESSIONID = 23), (DATABASE = nstestdb), (DRDAID = NF000001.PCA5-4470665814578243875

        {12}

        ), Failed Statement is: delete from nstesttab where serialkey = ? with 1 parameters begin parameter #1: 36022 :end parameter
        org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED Index row (9475777.6508320800,(590,44)) not found in conglomerateid 1185Current scan =
        btree = BTREE: containerid = Container(0, 1185);nKeyFields = 2;nUniqueColumns = 2;allowDuplicates = false
        scan direction = forward
        (scan_state:SCAN_DONE
        rh:null
        key:null)
        init_rawtran = 94271
        init_hold = false
        init_forUpdate = true
        init_useUpdateLocks = false
        init_scanColumnList = null
        init_scanColumnList.size() = 0
        init_template = col[0]=9484797.0792001040col[1]=(359,27)
        init_startKeyValue = col[0]=9475777.6508320800col[1]=(590,44)
        init_startSearchOperator = GE
        init_qualifier[] = null
        init_stopKeyValue = col[0]=9475777.6508320800col[1]=(590,44)
        init_stopSearchOperator = GT
        stat_numpages_visited = 3
        stat_numrows_visited = 1
        stat_numrows_qualified = 0
        stat_numdeleted_rows_visited = 0
        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.sql.execute.IndexChanger.doDelete(IndexChanger.java:351)
        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.execute.DeleteResultSet.deleteDeferredRows(DeleteResultSet.java:527)
        at org.apache.derby.impl.sql.execute.DeleteResultSet.open(DeleteResultSet.java:154)
        at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:416)
        at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:297)
        at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235)
        at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1648)
        at org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute(EmbedPreparedStatement.java:1303)
        at org.apache.derby.impl.drda.DRDAStatement.execute(DRDAStatement.java:672)
        at org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTTobjects(DRDAConnThread.java:4280)
        at org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTT(DRDAConnThread.java:4084)
        at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:1003)
        at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:290)

        Show
        Myrna van Lunteren added a comment - Attaching 2 jarred up derby.log files. run1server.jar contains the 10.5.rc2 server's derby.log file when run with sane jars but no derby.properties. It shows an assert which I think is similar to the warning I saw in my insane jar runs: org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED Index row (9475777.6508320800,(590,44)) not found in conglomerateid 1185Current scan = btree = BTREE: containerid = Container(0, 1185);nKeyFields = 2;nUniqueColumns = 2;allowDuplicates = false [....] serverlog.jar is from a run with 10.5.rc2 and sane jars and with derby.properties in place (both in the dir for the server and for the client: derby.language.logStatementText=true, derby.stream.error.logSeverityLevel=0, derby.infolog.append=tru). This one first shows a different but I think related index AssertFailure: ERROR 38000: The exception 'org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED last row on left page 233 > than first row on right page 110 left last row = col [0] =4988358813.6843080000col [1] =(155,20)col [2] =214right first row = col [0] =16968984.2552292000col [1] =(180,14)col [2] =147 BRANCH(233)(lev=1): num recs = 80 left = 106;right = 110;parent = 1;isRoot = false;left child page = 227; last > first of BRANCH(110)(lev=1): num recs = 96 left = 233;right = 200;parent = 1;isRoot = false;left child page = 94;' was thrown while evaluating an expression. at org.apache.derby.iapi.error.StandardException.newException(StandardException.java:296) at org.apache.derby.iapi.error.StandardException.unexpectedUserException(StandardException.java:583) at org.apache.derby.impl.services.reflect.DirectCall.invoke(ReflectGeneratedClass.java:164) at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.doProjection(ProjectRestrictResultSet.java:497) at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(ProjectRestrictResultSet.java:291) at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(BasicNoPutResultSetImpl.java:460) at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:427) at org.apache.derby.impl.jdbc.EmbedResultSet.next(EmbedResultSet.java:371) at org.apache.derby.impl.drda.DRDAConnThread.writeFDODTA(DRDAConnThread.java:6866) at org.apache.derby.impl.drda.DRDAConnThread.writeQRYDTA(DRDAConnThread.java:6762) at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:859) at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:290) Caused by: org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED last row on left page 233 > than first row on right page 110 left last row = col [0] =4988358813.6843080000col [1] =(155,20)col [2] =214right first row = col [0] =16968984.2552292000col [1] =(180,14)col [2] =147 BRANCH(233)(lev=1): num recs = 80 left = 106;right = 110;parent = 1;isRoot = false;left child page = 227; last > first of BRANCH(110)(lev=1): num recs = 96 left = 233;right = 200;parent = 1;isRoot = false;left child page = 94; 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.compareRowsOnSiblings(ControlRow.java:1532) at org.apache.derby.impl.store.access.btree.ControlRow.checkSiblings(ControlRow.java:1642) at org.apache.derby.impl.store.access.btree.ControlRow.checkGeneric(ControlRow.java:1423) at org.apache.derby.impl.store.access.btree.BranchControlRow.checkConsistency(BranchControlRow.java:942) at org.apache.derby.impl.store.access.btree.BranchControlRow.checkChildren(BranchControlRow.java:1038) at org.apache.derby.impl.store.access.btree.BranchControlRow.checkConsistency(BranchControlRow.java:1013) at org.apache.derby.impl.store.access.btree.OpenBTree.checkConsistency(OpenBTree.java:283) at org.apache.derby.iapi.db.ConsistencyChecker.checkTable(ConsistencyChecker.java:204) at org.apache.derby.catalog.SystemProcedures.SYSCS_CHECK_TABLE(SystemProcedures.java:977) at org.apache.derby.exe.acb05c5046x0120xd4b9xebbdx00000454210e0.e3(Unknown Source) at org.apache.derby.impl.services.reflect.DirectCall.invoke(ReflectGeneratedClass.java:145) ... 9 more ============= begin nested exception, level (1) =========== org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED last row on left page 233 > than first row on right page 110 left last row = col [0] =4988358813.6843080000col [1] =(155,20)col [2] =214right first row = col [0] =16968984.2552292000col [1] =(180,14)col [2] =147 BRANCH(233)(lev=1): num recs = 80 left = 106;right = 110;parent = 1;isRoot = false;left child page = 227; last > first of BRANCH(110)(lev=1): num recs = 96 left = 233;right = 200;parent = 1;isRoot = false;left child page = 94; 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.compareRowsOnSiblings(ControlRow.java:1532) at org.apache.derby.impl.store.access.btree.ControlRow.checkSiblings(ControlRow.java:1642) at org.apache.derby.impl.store.access.btree.ControlRow.checkGeneric(ControlRow.java:1423) at org.apache.derby.impl.store.access.btree.BranchControlRow.checkConsistency(BranchControlRow.java:942) at org.apache.derby.impl.store.access.btree.BranchControlRow.checkChildren(BranchControlRow.java:1038) at org.apache.derby.impl.store.access.btree.BranchControlRow.checkConsistency(BranchControlRow.java:1013) at org.apache.derby.impl.store.access.btree.OpenBTree.checkConsistency(OpenBTree.java:283) at org.apache.derby.iapi.db.ConsistencyChecker.checkTable(ConsistencyChecker.java:204) at org.apache.derby.catalog.SystemProcedures.SYSCS_CHECK_TABLE(SystemProcedures.java:977) at org.apache.derby.exe.acb05c5046x0120xd4b9xebbdx00000454210e0.e3(Unknown Source) at org.apache.derby.impl.services.reflect.DirectCall.invoke(ReflectGeneratedClass.java:145) at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.doProjection(ProjectRestrictResultSet.java:497) at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(ProjectRestrictResultSet.java:291) at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(BasicNoPutResultSetImpl.java:460) at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:427) at org.apache.derby.impl.jdbc.EmbedResultSet.next(EmbedResultSet.java:371) at org.apache.derby.impl.drda.DRDAConnThread.writeFDODTA(DRDAConnThread.java:6866) at org.apache.derby.impl.drda.DRDAConnThread.writeQRYDTA(DRDAConnThread.java:6762) at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:859) at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:290) (Skipping thread dump because of insufficient permissions: java.security.AccessControlException: Access denied (java.lang.RuntimePermission getStackTrace)) ============= end nested exception, level (1) =========== followed somewhat later by: 2009-04-23 20:05:05.986 GMT Thread [DRDAConnThread_11,5,main] (XID = 94271), (SESSIONID = 23), (DATABASE = nstestdb), (DRDAID = NF000001.PCA5-4470665814578243875 {12} ), Failed Statement is: delete from nstesttab where serialkey = ? with 1 parameters begin parameter #1: 36022 :end parameter org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED Index row (9475777.6508320800,(590,44)) not found in conglomerateid 1185Current scan = btree = BTREE: containerid = Container(0, 1185);nKeyFields = 2;nUniqueColumns = 2;allowDuplicates = false scan direction = forward (scan_state:SCAN_DONE rh:null key:null) init_rawtran = 94271 init_hold = false init_forUpdate = true init_useUpdateLocks = false init_scanColumnList = null init_scanColumnList.size() = 0 init_template = col [0] =9484797.0792001040col [1] =(359,27) init_startKeyValue = col [0] =9475777.6508320800col [1] =(590,44) init_startSearchOperator = GE init_qualifier[] = null init_stopKeyValue = col [0] =9475777.6508320800col [1] =(590,44) init_stopSearchOperator = GT stat_numpages_visited = 3 stat_numrows_visited = 1 stat_numrows_qualified = 0 stat_numdeleted_rows_visited = 0 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.sql.execute.IndexChanger.doDelete(IndexChanger.java:351) 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.execute.DeleteResultSet.deleteDeferredRows(DeleteResultSet.java:527) at org.apache.derby.impl.sql.execute.DeleteResultSet.open(DeleteResultSet.java:154) at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:416) at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:297) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1648) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute(EmbedPreparedStatement.java:1303) at org.apache.derby.impl.drda.DRDAStatement.execute(DRDAStatement.java:672) at org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTTobjects(DRDAConnThread.java:4280) at org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTT(DRDAConnThread.java:4084) at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:1003) at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:290)
        Hide
        Myrna van Lunteren added a comment -

        Tested this with 10.4.2.0 and I'm seeing the same behavior.

        Show
        Myrna van Lunteren added a comment - Tested this with 10.4.2.0 and I'm seeing the same behavior.
        Hide
        Myrna van Lunteren added a comment -

        Perhaps someone else can try this out - maybe this time someone else can see this trouble.
        The problems start occurring after about 7 minutes in my runs.

        Info on how to run the test is in java/testing/org/apache/derbyTesting/system/nstest/README.txt.
        I started the network server like so:
        java org.apache.derby.drda.NetworkServerControl -p 1900 -h 0.0.0.0 start &
        and the test like so:
        java org.apache.derbyTesting.system.nstest.NsTest > nstest.out 2>&1

        Show
        Myrna van Lunteren added a comment - Perhaps someone else can try this out - maybe this time someone else can see this trouble. The problems start occurring after about 7 minutes in my runs. Info on how to run the test is in java/testing/org/apache/derbyTesting/system/nstest/README.txt. I started the network server like so: java org.apache.derby.drda.NetworkServerControl -p 1900 -h 0.0.0.0 start & and the test like so: java org.apache.derbyTesting.system.nstest.NsTest > nstest.out 2>&1
        Hide
        Kathey Marsden added a comment -

        On trunk, I saw the assertion only a minute into the run. On 10.3 I have been running the test for 1/2 hour without seeing it. Marking as a regression. I will run using the trunk test against 10.3, just to make sure it is not a test change that is popping the issue.

        Show
        Kathey Marsden added a comment - On trunk, I saw the assertion only a minute into the run. On 10.3 I have been running the test for 1/2 hour without seeing it. Marking as a regression. I will run using the trunk test against 10.3, just to make sure it is not a test change that is popping the issue.
        Hide
        Kathey Marsden added a comment -

        Running the trunk tests against 10.3 I did not see the assertion but after 35 minutes saw server side OutOfMemoryError exceptions. I assume I just didn't let the previous 10.3 run run long enough to hit this. The only change to the test since contribution was an expected errorCode change which I wouldn't think would cause the difference.

        Show
        Kathey Marsden added a comment - Running the trunk tests against 10.3 I did not see the assertion but after 35 minutes saw server side OutOfMemoryError exceptions. I assume I just didn't let the previous 10.3 run run long enough to hit this. The only change to the test since contribution was an expected errorCode change which I wouldn't think would cause the difference.
        Hide
        Mike Matrigali added a comment -

        I also repro'd this on a 2 processor XP laptop, running IBM 1.6 SR3 jvm. I verified that the affected index is not an "allow duplicates" index so not similar to the other problems we have seen with that new index that allows duplicate
        null values in an otherwise unique index.

        I repro'd running SANE classes and got:
        org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED Index row (8167710.5025663700,(591,88)) not found in conglomerateid 1185Current sca
        n =
        btree = BTREE: containerid = Container(0, 1185);nKeyFields = 2;nUniqueColumns = 2;allowDuplicates = false
        scan direction = forward
        (scan_state:SCAN_DONE
        rh:null
        key:null)
        init_rawtran = 95000
        init_hold = false
        init_forUpdate = true
        init_useUpdateLocks = false
        init_scanColumnList = null
        init_scanColumnList.size() = 0
        init_template = col[0]=8168831.1746247970col[1]=(195,30)
        init_startKeyValue = col[0]=8167710.5025663700col[1]=(591,88)
        init_startSearchOperator = GE
        init_qualifier[] = null
        init_stopKeyValue = col[0]=8167710.5025663700col[1]=(591,88)
        init_stopSearchOperator = GT
        stat_numpages_visited = 3
        stat_numrows_visited = 1
        stat_numrows_qualified = 0
        stat_numdeleted_rows_visited = 0^M
        at org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:162)^M
        at org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:147)^M
        at org.apache.derby.impl.sql.execute.IndexChanger.doDelete(IndexChanger.java:351)^M
        at org.apache.derby.impl.sql.execute.IndexChanger.delete(IndexChanger.java:544)^M
        at org.apache.derby.impl.sql.execute.IndexSetChanger.delete(IndexSetChanger.java:250)^M
        at org.apache.derby.impl.sql.execute.RowChangerImpl.deleteRow(RowChangerImpl.java:476)^M
        at org.apache.derby.impl.sql.execute.DeleteResultSet.deleteDeferredRows(DeleteResultSet.java:527)^M
        at org.apache.derby.impl.sql.execute.DeleteResultSet.open(DeleteResultSet.java:154)^M
        at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:416)^M
        at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:297)^M
        at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235)^M
        at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1648)^M
        at org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute(EmbedPreparedStatement.java:1303)^M
        at org.apache.derby.impl.drda.DRDAStatement.execute(DRDAStatement.java:672)^M
        at org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTTobjects(DRDAConnThread.java:4280)^M
        at org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTT(DRDAConnThread.java:4084)^M
        at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:1003)^M
        at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:290)^M

        Show
        Mike Matrigali added a comment - I also repro'd this on a 2 processor XP laptop, running IBM 1.6 SR3 jvm. I verified that the affected index is not an "allow duplicates" index so not similar to the other problems we have seen with that new index that allows duplicate null values in an otherwise unique index. I repro'd running SANE classes and got: org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED Index row (8167710.5025663700,(591,88)) not found in conglomerateid 1185Current sca n = btree = BTREE: containerid = Container(0, 1185);nKeyFields = 2;nUniqueColumns = 2;allowDuplicates = false scan direction = forward (scan_state:SCAN_DONE rh:null key:null) init_rawtran = 95000 init_hold = false init_forUpdate = true init_useUpdateLocks = false init_scanColumnList = null init_scanColumnList.size() = 0 init_template = col [0] =8168831.1746247970col [1] =(195,30) init_startKeyValue = col [0] =8167710.5025663700col [1] =(591,88) init_startSearchOperator = GE init_qualifier[] = null init_stopKeyValue = col [0] =8167710.5025663700col [1] =(591,88) init_stopSearchOperator = GT stat_numpages_visited = 3 stat_numrows_visited = 1 stat_numrows_qualified = 0 stat_numdeleted_rows_visited = 0^M at org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:162)^M at org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:147)^M at org.apache.derby.impl.sql.execute.IndexChanger.doDelete(IndexChanger.java:351)^M at org.apache.derby.impl.sql.execute.IndexChanger.delete(IndexChanger.java:544)^M at org.apache.derby.impl.sql.execute.IndexSetChanger.delete(IndexSetChanger.java:250)^M at org.apache.derby.impl.sql.execute.RowChangerImpl.deleteRow(RowChangerImpl.java:476)^M at org.apache.derby.impl.sql.execute.DeleteResultSet.deleteDeferredRows(DeleteResultSet.java:527)^M at org.apache.derby.impl.sql.execute.DeleteResultSet.open(DeleteResultSet.java:154)^M at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:416)^M at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:297)^M at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235)^M at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1648)^M at org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute(EmbedPreparedStatement.java:1303)^M at org.apache.derby.impl.drda.DRDAStatement.execute(DRDAStatement.java:672)^M at org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTTobjects(DRDAConnThread.java:4280)^M at org.apache.derby.impl.drda.DRDAConnThread.parseEXCSQLSTT(DRDAConnThread.java:4084)^M at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:1003)^M at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:290)^M
        Hide
        Kathey Marsden added a comment -

        My 10.3 workspace was picking up the Sun JVM, so that is why I did not see it with 10.3. I see the assert on both 10.3 and trunk with:

        java version "1.6.0"
        Java(TM) SE Runtime Environment (build pwi3260sr3-20081106_07(SR3))
        IBM J9 VM (build 2.4, J2RE 1.6.0 IBM J9 2.4 Windows XP x86-32 jvmwi3260-20081105_25433 (JIT enabled, AOT enabled)
        J9VM - 20081105_025433_lHdSMr
        JIT - r9_20081031_1330
        GC - 20081027_AB)
        JCL - 20081106_01

        On 10.3 using the Sun JVM I didn't see it.
        java version "1.6.0_01"
        Java(TM) SE Runtime Environment (build 1.6.0_01-b06)
        Java HotSpot(TM) Client VM (build 1.6.0_01-b06, mixed mode)

        Show
        Kathey Marsden added a comment - My 10.3 workspace was picking up the Sun JVM, so that is why I did not see it with 10.3. I see the assert on both 10.3 and trunk with: java version "1.6.0" Java(TM) SE Runtime Environment (build pwi3260sr3-20081106_07(SR3)) IBM J9 VM (build 2.4, J2RE 1.6.0 IBM J9 2.4 Windows XP x86-32 jvmwi3260-20081105_25433 (JIT enabled, AOT enabled) J9VM - 20081105_025433_lHdSMr JIT - r9_20081031_1330 GC - 20081027_AB) JCL - 20081106_01 On 10.3 using the Sun JVM I didn't see it. java version "1.6.0_01" Java(TM) SE Runtime Environment (build 1.6.0_01-b06) Java HotSpot(TM) Client VM (build 1.6.0_01-b06, mixed mode)
        Hide
        Myrna van Lunteren added a comment -

        For what it's worth, I ran a consistency check on the database, and it definitely falls over on table NSTEST.NSTESTTAB:
        -------------------
        38000:The exception 'org.apache.derby.shared.common.sanity.AssertFailure: ASSERT
        FAILED last row on left page 226 > than first row on right page 109
        left last row = col[0]=9094871101.2662800000col[1]=(160,43)col[2]=177right first
        row = col[0]=7784998.6583844800col[1]=(195,48)col[2]=144
        BRANCH(226)(lev=1): num recs = 89
        left = 105;right = 109;parent = 1;isRoot = false;left child page = 54; last > first of
        BRANCH(109)(lev=1): num recs = 95
        left = 226;right = 202;parent = 1;isRoot = false;left child page = 40;'
        was thrown while evaluating an expression.
        -------------------------------

        Show
        Myrna van Lunteren added a comment - For what it's worth, I ran a consistency check on the database, and it definitely falls over on table NSTEST.NSTESTTAB: ------------------- 38000:The exception 'org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED last row on left page 226 > than first row on right page 109 left last row = col [0] =9094871101.2662800000col [1] =(160,43)col [2] =177right first row = col [0] =7784998.6583844800col [1] =(195,48)col [2] =144 BRANCH(226)(lev=1): num recs = 89 left = 105;right = 109;parent = 1;isRoot = false;left child page = 54; last > first of BRANCH(109)(lev=1): num recs = 95 left = 226;right = 202;parent = 1;isRoot = false;left child page = 40;' was thrown while evaluating an expression. -------------------------------
        Hide
        Mike Matrigali added a comment -

        In my environment (xp, 2 processor laptop, trunk) I reproduced a couple
        of times
        within 5 minutes on ibm16. I tried in same environment 2 times with ibm15
        and 2 times with sun16 and let them go at least 15 minutes each as did not
        see any issues.

        So now the question is whether this is an ibm16 jvm bug, or is ibm16 just more concurrent and showing up a derby bug. I have definitely seem real
        derby bugs that are multi-thread timing only show up on ibm16. I think this
        may be the first time we have run this test against ibm16, as I think ibm15
        was the chosen ibm jvm during the 10.3 and 10.4 release cycles.

        Here is my exact jvm info:
        ibm16:
        m2_ibm16:55>java -version
        java version "1.6.0"
        Java(TM) SE Runtime Environment (build pwi3260sr3-20081106_07(SR3))
        IBM J9 VM (build 2.4, J2RE 1.6.0 IBM J9 2.4 Windows XP x86-32 jvmwi3260-2008110
        _25433 (JIT enabled, AOT enabled)
        J9VM - 20081105_025433_lHdSMr
        JIT - r9_20081031_1330
        GC - 20081027_AB)
        JCL - 20081106_01

        ibm15:
        java version "1.5.0"
        Java(TM) 2 Runtime Environment, Standard Edition (build pwi32dev-20080315 (SR7))

        IBM J9 VM (build 2.3, J2RE 1.5.0 IBM J9 2.3 Windows XP x86-32 j9vmwi3223-2008031
        5 (JIT enabled)
        J9VM - 20080314_17962_lHdSMr
        JIT - 20080130_0718ifx2_r8
        GC - 200802_08)
        JCL - 20080314

        sun16:
        java version "1.6.0_01"
        Java(TM) SE Runtime Environment (build 1.6.0_01-b06)
        Java HotSpot(TM) Client VM (build 1.6.0_01-b06, mixed mode)

        Show
        Mike Matrigali added a comment - In my environment (xp, 2 processor laptop, trunk) I reproduced a couple of times within 5 minutes on ibm16. I tried in same environment 2 times with ibm15 and 2 times with sun16 and let them go at least 15 minutes each as did not see any issues. So now the question is whether this is an ibm16 jvm bug, or is ibm16 just more concurrent and showing up a derby bug. I have definitely seem real derby bugs that are multi-thread timing only show up on ibm16. I think this may be the first time we have run this test against ibm16, as I think ibm15 was the chosen ibm jvm during the 10.3 and 10.4 release cycles. Here is my exact jvm info: ibm16: m2_ibm16:55>java -version java version "1.6.0" Java(TM) SE Runtime Environment (build pwi3260sr3-20081106_07(SR3)) IBM J9 VM (build 2.4, J2RE 1.6.0 IBM J9 2.4 Windows XP x86-32 jvmwi3260-2008110 _25433 (JIT enabled, AOT enabled) J9VM - 20081105_025433_lHdSMr JIT - r9_20081031_1330 GC - 20081027_AB) JCL - 20081106_01 ibm15: java version "1.5.0" Java(TM) 2 Runtime Environment, Standard Edition (build pwi32dev-20080315 (SR7)) IBM J9 VM (build 2.3, J2RE 1.5.0 IBM J9 2.3 Windows XP x86-32 j9vmwi3223-2008031 5 (JIT enabled) J9VM - 20080314_17962_lHdSMr JIT - 20080130_0718ifx2_r8 GC - 200802_08) JCL - 20080314 sun16: java version "1.6.0_01" Java(TM) SE Runtime Environment (build 1.6.0_01-b06) Java HotSpot(TM) Client VM (build 1.6.0_01-b06, mixed mode)
        Hide
        Kathey Marsden added a comment -

        I ran with IBM 1.6 SR3 with jit off on the server and the issue occurred after 45 minutes, so it does not appear to be a JIT issue.

        I ran 2 hours with IBM 1.5 (pwi32dev-20080315 (SR7)) on trunk and did not see the issue.

        I ran with derby.language.logStatementText turned on and noticed that the failure occurred when there was a concurrent attempt to update and delete of the same row from different threads. I will attach the log excerpt (log_excerpt_sample_assert.txt)

        I tried to make a smaller program to reproduce this but ran into DERBY-4193 You can see my attempt attached to that issue. ScanPosSaved.java.

        Show
        Kathey Marsden added a comment - I ran with IBM 1.6 SR3 with jit off on the server and the issue occurred after 45 minutes, so it does not appear to be a JIT issue. I ran 2 hours with IBM 1.5 (pwi32dev-20080315 (SR7)) on trunk and did not see the issue. I ran with derby.language.logStatementText turned on and noticed that the failure occurred when there was a concurrent attempt to update and delete of the same row from different threads. I will attach the log excerpt (log_excerpt_sample_assert.txt) I tried to make a smaller program to reproduce this but ran into DERBY-4193 You can see my attempt attached to that issue. ScanPosSaved.java.
        Hide
        Kathey Marsden added a comment -

        I see the assertion also with the latest on the 10.2 branch (using the trunk test) and IBM 1.6 SR3. I haven't had any luck building up a small reproduction from scratch so will start trying to strip down the test to see what I can eliminate. Mike said he already eliminated backup. I will try to make it run in embedded mode and see if the issue still occurs.

        Show
        Kathey Marsden added a comment - I see the assertion also with the latest on the 10.2 branch (using the trunk test) and IBM 1.6 SR3. I haven't had any luck building up a small reproduction from scratch so will start trying to strip down the test to see what I can eliminate. Mike said he already eliminated backup. I will try to make it run in embedded mode and see if the issue still occurs.
        Hide
        Kathey Marsden added a comment -

        This is what I discovered today regarding this issue:
        It always seems to happen on record 36XXX even with no jit run. It just took 45 minutes to get there.
        Reproduces with embedded. You can run with embedded by passing the "Embedded" argument to the test.
        Reproduces without backup. You can run with -Dderby.nstest.backupRestore=false
        Reproduces without encryption.
        Reproduces without Tester3 threads (was just doing selects) and without Tester2 threads (doing the same operation as Tester1 but getting a new connection each time.)
        Reproduces without updates (just inserts and deletes)
        Reproduces with just one Tester1 thread, doing sequential insert and delete operations.
        Trying now with just one INIT thread (was 6) and it has been running for 10 minutes. So I am guessing the corruption is occurring with the mulithreaded insert used to set up the test, but we don't see it until later when we try a delete. If this runs ok for a while I will go back to multithreaded and put a consistency check in after the inserts complete to verify this theory.

        Show
        Kathey Marsden added a comment - This is what I discovered today regarding this issue: It always seems to happen on record 36XXX even with no jit run. It just took 45 minutes to get there. Reproduces with embedded. You can run with embedded by passing the "Embedded" argument to the test. Reproduces without backup. You can run with -Dderby.nstest.backupRestore=false Reproduces without encryption. Reproduces without Tester3 threads (was just doing selects) and without Tester2 threads (doing the same operation as Tester1 but getting a new connection each time.) Reproduces without updates (just inserts and deletes) Reproduces with just one Tester1 thread, doing sequential insert and delete operations. Trying now with just one INIT thread (was 6) and it has been running for 10 minutes. So I am guessing the corruption is occurring with the mulithreaded insert used to set up the test, but we don't see it until later when we try a delete. If this runs ok for a while I will go back to multithreaded and put a consistency check in after the inserts complete to verify this theory.
        Hide
        Bryan Pendleton added a comment -

        > It always seems to happen on record 36XXX even with no jit run

        Perhaps the Btree has to get to a certain height? That is, maybe the pre-conditions involve a Btree of height 3, or 4, or ...

        Show
        Bryan Pendleton added a comment - > It always seems to happen on record 36XXX even with no jit run Perhaps the Btree has to get to a certain height? That is, maybe the pre-conditions involve a Btree of height 3, or 4, or ...
        Hide
        Kathey Marsden added a comment -

        Attached is a smaller reproduction with just a single thread calling the tests DbUtil.add_one_row method in a loop and checking tables after each insert. Unfortunately this still has some randomness but fails quickly, sometimes after as few as 5 rows.
        I tried just inserting one row, using values that I saw fail from the derby.log, but could not pop it that way.

        Note: this is not a multi-threaded problem. The reason we always had a problem at 36XXX was because our setup had 6 insert threads doing 6000 inserts each and we never did any kind of integrity checking until the first delete after the setup was complete.

        I will continue to try to narrow it down and remove the randomness, but thought I would post what I had so far.

        Show
        Kathey Marsden added a comment - Attached is a smaller reproduction with just a single thread calling the tests DbUtil.add_one_row method in a loop and checking tables after each insert. Unfortunately this still has some randomness but fails quickly, sometimes after as few as 5 rows. I tried just inserting one row, using values that I saw fail from the derby.log, but could not pop it that way. Note: this is not a multi-threaded problem. The reason we always had a problem at 36XXX was because our setup had 6 insert threads doing 6000 inserts each and we never did any kind of integrity checking until the first delete after the setup was complete. I will continue to try to narrow it down and remove the randomness, but thought I would post what I had so far.
        Hide
        Kathey Marsden added a comment -

        Attaching updated repro that has just the numeric column t_numeric_large and index t_num_lrg_ind and inserts only 2 rows with problematic values. I think there are many other value combinations that are problematic. This is just an example.

        Show
        Kathey Marsden added a comment - Attaching updated repro that has just the numeric column t_numeric_large and index t_num_lrg_ind and inserts only 2 rows with problematic values. I think there are many other value combinations that are problematic. This is just an example.
        Hide
        Mike Matrigali added a comment -

        thanks kathey for the test case. it also repro's in my environment on ibm16.
        i am going to work on this to see what point in the code it breaks, thinking it must be some wierd jvm bug in comparison.

        Show
        Mike Matrigali added a comment - thanks kathey for the test case. it also repro's in my environment on ibm16. i am going to work on this to see what point in the code it breaks, thinking it must be some wierd jvm bug in comparison.
        Hide
        Mike Matrigali added a comment -

        This attachment is not meant for commit, it has a bunch of debug statements in SQLDecimal.java which show that this is some sort of JVM bug.

        Show
        Mike Matrigali added a comment - This attachment is not meant for commit, it has a bunch of debug statements in SQLDecimal.java which show that this is some sort of JVM bug.
        Hide
        Mike Matrigali added a comment -

        I believe this is some sort of BigDecimal jvm bug in ibm16 jvm's. I have attached derby4181debug.diff which has added debug statements in SQLDecimal.typeCompare. The routine gets 2
        BigDecimals and then compares them. Using the Kathey's most
        recent repro, the first time this routine is called the compare of
        the 2 values is incorrect. This then leads to the btree index corruption that shows up at various times.

        I have included the derby.log and the derby.properties that I used for my run. Using the derby.debug.true=enableBtreeConsistencyCheck
        property in SANE mode catches this problem quicker.

        The debug statements also show that comparing the 2 values
        twice get the wrong answer, but then after printing one of the
        values and then doing the compare you then get the right answer from the compare.

        I tried repro'ing this outside of derby but did not have any luck.

        Here is the interesting part from the derby.log that shows it
        returning that 2959688338890040800.0000000000 < 464202.5974272370 twice and then reversing the compare
        result after the BigDecimal with 464202.5974272370 is
        printed.
        :
        DEBUG SQLDecimal OUTPUT: typeCompare result after 1st compare:
        otherValue.scale = 10
        localValue.scale = 10
        ret_val (result of localValue.compareTo(otherValue) ) = -1^M
        DEBUG SQLDecimal OUTPUT: typeCompare after 2nd compare, no change in result:
        otherValue.scale = 10
        localValue.scale = 10
        ret_val (result of localValue.compareTo(otherValue) ) = -1^M
        DEBUG SQLDecimal OUTPUT: otherValue = 464202.5974272370^M
        DEBUG SQLDecimal OUTPUT: typeCompare result after printing otherValue:
        otherValue.scale = 10
        localValue.scale = 10
        ret_val3 (result of localValue.compareTo(otherValue) ) = 1^M
        DEBUG SQLDecimal OUTPUT: localValue = 2959688338890040800.0000000000^M
        DEBUG SQLDecimal OUTPUT: typeCompare result after printing otherValue:
        otherValue.scale = 10
        localValue.scale = 10
        ret_val2 (result of localValue.compareTo(otherValue) ) = 1^M
        DEBUG SQLDecimal OUTPUT: typeCompare initial values:localValue double = 2.959688
        3388900408E18otherValue.scale = 10localValue.scale = 10^M
        Exception trace: ^M

        Show
        Mike Matrigali added a comment - I believe this is some sort of BigDecimal jvm bug in ibm16 jvm's. I have attached derby4181debug.diff which has added debug statements in SQLDecimal.typeCompare. The routine gets 2 BigDecimals and then compares them. Using the Kathey's most recent repro, the first time this routine is called the compare of the 2 values is incorrect. This then leads to the btree index corruption that shows up at various times. I have included the derby.log and the derby.properties that I used for my run. Using the derby.debug.true=enableBtreeConsistencyCheck property in SANE mode catches this problem quicker. The debug statements also show that comparing the 2 values twice get the wrong answer, but then after printing one of the values and then doing the compare you then get the right answer from the compare. I tried repro'ing this outside of derby but did not have any luck. Here is the interesting part from the derby.log that shows it returning that 2959688338890040800.0000000000 < 464202.5974272370 twice and then reversing the compare result after the BigDecimal with 464202.5974272370 is printed. : DEBUG SQLDecimal OUTPUT: typeCompare result after 1st compare: otherValue.scale = 10 localValue.scale = 10 ret_val (result of localValue.compareTo(otherValue) ) = -1^M DEBUG SQLDecimal OUTPUT: typeCompare after 2nd compare, no change in result: otherValue.scale = 10 localValue.scale = 10 ret_val (result of localValue.compareTo(otherValue) ) = -1^M DEBUG SQLDecimal OUTPUT: otherValue = 464202.5974272370^M DEBUG SQLDecimal OUTPUT: typeCompare result after printing otherValue: otherValue.scale = 10 localValue.scale = 10 ret_val3 (result of localValue.compareTo(otherValue) ) = 1^M DEBUG SQLDecimal OUTPUT: localValue = 2959688338890040800.0000000000^M DEBUG SQLDecimal OUTPUT: typeCompare result after printing otherValue: otherValue.scale = 10 localValue.scale = 10 ret_val2 (result of localValue.compareTo(otherValue) ) = 1^M DEBUG SQLDecimal OUTPUT: typeCompare initial values:localValue double = 2.959688 3388900408E18otherValue.scale = 10localValue.scale = 10^M Exception trace: ^M
        Hide
        Mike Matrigali added a comment -

        I don't plan on doing more on this issue, it looks like a jvm bug to me.

        Show
        Mike Matrigali added a comment - I don't plan on doing more on this issue, it looks like a jvm bug to me.
        Hide
        Kristian Waagan added a comment -

        FWIW, I didn't see the problem with Sun JDK 1.6.0_13.

        Show
        Kristian Waagan added a comment - FWIW, I didn't see the problem with Sun JDK 1.6.0_13.
        Hide
        Kathey Marsden added a comment -

        Thanks Mike. I think this should be enough information to file a bug against the JVM.

        I will take over tracking of this issue and close it invalid as soon as soon as the JVM team accepts it as a bug.

        Show
        Kathey Marsden added a comment - Thanks Mike. I think this should be enough information to file a bug against the JVM. I will take over tracking of this issue and close it invalid as soon as soon as the JVM team accepts it as a bug.
        Hide
        Kathey Marsden added a comment -

        Confirmed this is a JVM bug and got a test fix which I verified fixed the problem. It should be in an upcoming release of the IBM 1.6 JDK. I will post the actual version here once it is released.

        Show
        Kathey Marsden added a comment - Confirmed this is a JVM bug and got a test fix which I verified fixed the problem. It should be in an upcoming release of the IBM 1.6 JDK. I will post the actual version here once it is released.

          People

          • Assignee:
            Kathey Marsden
            Reporter:
            Myrna van Lunteren
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development