Derby
  1. Derby
  2. DERBY-4294

java.lang.OutOfMemoryError from mailjdbc test after running for one hour from select * from REFRESH.INBOX

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.3.3.0, 10.4.2.0, 10.5.3.0, 10.6.2.1
    • Fix Version/s: 10.7.1.1
    • Component/s: Store
    • Environment:
      Window Vista
    • Urgency:
      Normal
    • Issue & fix info:
      Repro attached
    • Bug behavior facts:
      Crash

      Description

      After running mailjdbc test on 10.3 branch, select * from REFRESH.INBOX gave me error like:
      ERROR XJ001: Java exception: 'Java heap space: java.lang.OutOfMemoryError'

      I also see the same error on 10.5 branch.

      I inculde my mailsdb directory in this bug too.

      How to reproduce this issue:
      1. cd mailjdbc
      2. java org.apache.derbyTesting.system.mailjdbc.MailJdbc embedded
      3. Wait for an hour and ignore Primary key violation error
      ( : INFO :Refresh Thread : Error while inserting attachments:The statement was ab
      orted because it would have caused a duplicate key value in a unique or primary
      key constraint or unique index identified by 'ATTACH__PK' defined on 'ATTACH'.)

      1. Derby4294_pid6920.zip
        1.65 MB
        Lily Wei
      2. Heapspaceerror.zip
        536 kB
        Lily Wei

        Issue Links

          Activity

          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.
          Hide
          Kristian Waagan added a comment -

          Resolving as fixed in 10.7.

          Show
          Kristian Waagan added a comment - Resolving as fixed in 10.7.
          Hide
          Kristian Waagan added a comment -

          Created DERBY-5257 to track the proposed ij improvement.

          Show
          Kristian Waagan added a comment - Created DERBY-5257 to track the proposed ij improvement.
          Hide
          Kristian Waagan added a comment -

          I verified that the OOME doesn't occur with Derby 10.7 when running with a heap of 64 MB (on Solaris). It did happen when I tried with Derby 10.6.

          It would be good to get this issue resolved, which can be done in several ways:
          a) Mark issue as fixed in 10.7 and be done with it.
          b) Back-port DERBY-1511 as far back as is reasonable (10.5?).
          c) Implement ij improvement (use getClob().getSubString()).

          Opinions?

          Option c will only affect the ij tool, not the Derby core (i.e. applications written on top of Derby using JDBC won't benefit from it).
          I'm fine with doing either a or b, but I think that in addition we should at least log a JIRA for the ij improvement.

          Show
          Kristian Waagan added a comment - I verified that the OOME doesn't occur with Derby 10.7 when running with a heap of 64 MB (on Solaris). It did happen when I tried with Derby 10.6. It would be good to get this issue resolved, which can be done in several ways: a) Mark issue as fixed in 10.7 and be done with it. b) Back-port DERBY-1511 as far back as is reasonable (10.5?). c) Implement ij improvement (use getClob().getSubString()). Opinions? Option c will only affect the ij tool, not the Derby core (i.e. applications written on top of Derby using JDBC won't benefit from it). I'm fine with doing either a or b, but I think that in addition we should at least log a JIRA for the ij improvement.
          Hide
          Dag H. Wanvik added a comment -

          Triaged for 10.5.2, checking "Crash", "repro attached" and setting "normal" urgency.

          Show
          Dag H. Wanvik added a comment - Triaged for 10.5.2, checking "Crash", "repro attached" and setting "normal" urgency.
          Hide
          Knut Anders Hatlen added a comment -

          That's interesting. So it would seem that the bulk fetching stores the rows in a DataValueDescriptor[fetchSize][numColumns] object, which shouldn't take that much memory since the CLOBs are represented by unmaterialized SQLClob objects. But when ij calls getString() on the result set, the SQLClob is materialized and will stay materialized until all the rows in the group have been read.

          This problem is somewhat related to DERBY-1511. Disabling bulk fetching for long columns should address both issues, I think. Using getClob().getSubString() would probably address the problem in this issue (but not the one in DERBY-1511).

          Show
          Knut Anders Hatlen added a comment - That's interesting. So it would seem that the bulk fetching stores the rows in a DataValueDescriptor [fetchSize] [numColumns] object, which shouldn't take that much memory since the CLOBs are represented by unmaterialized SQLClob objects. But when ij calls getString() on the result set, the SQLClob is materialized and will stay materialized until all the rows in the group have been read. This problem is somewhat related to DERBY-1511 . Disabling bulk fetching for long columns should address both issues, I think. Using getClob().getSubString() would probably address the problem in this issue (but not the one in DERBY-1511 ).
          Hide
          Kristian Waagan added a comment -

          I think this may be related to prefetching and the default heap size on Windows. If the Sun JVM was used, I think the maximum heap size is set to 64 MB (only client mode on Windows).

          If I disable prefetching (derby.language.bulkFetchDefault=1) I'm able to run the select with 10.3 using a 38 MB heap. With 10.6 I get away with a 37 MB heap.
          I don't know the minimum overhead of Derby, but after running a values clause in ij I see a heap usage of about 2 MB. After the select it rises to about 30 MB. Of these, around 26 MB are byte arrays, and I believe these are the page cache. Since Derby is asked to produce strings from the byte arrays representing the Clobs, we need heap space for these strings as well. If the prefetch is set to 16 rows, all 14 rows will be fetched at once. 30 + 23 = 53 MB.
          The remaining 11 MB must be data from the other columns and overhead. With prefetch disabled, Derby/Java is able to discard some of the data during result set processing.

          It is not clear to me that there is anything wrong with the Clob handling in this case.

          Show
          Kristian Waagan added a comment - I think this may be related to prefetching and the default heap size on Windows. If the Sun JVM was used, I think the maximum heap size is set to 64 MB (only client mode on Windows). If I disable prefetching (derby.language.bulkFetchDefault=1) I'm able to run the select with 10.3 using a 38 MB heap. With 10.6 I get away with a 37 MB heap. I don't know the minimum overhead of Derby, but after running a values clause in ij I see a heap usage of about 2 MB. After the select it rises to about 30 MB. Of these, around 26 MB are byte arrays, and I believe these are the page cache. Since Derby is asked to produce strings from the byte arrays representing the Clobs, we need heap space for these strings as well. If the prefetch is set to 16 rows, all 14 rows will be fetched at once. 30 + 23 = 53 MB. The remaining 11 MB must be data from the other columns and overhead. With prefetch disabled, Derby/Java is able to discard some of the data during result set processing. It is not clear to me that there is anything wrong with the Clob handling in this case.
          Hide
          Lily Wei added a comment -

          This is the heap dump from OOM with the test case.
          Thank to Kathey and espinha for showing me how to do this.
          java -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/kmarsden/repro/derby-4294 org.apache.derby.tools.ij
          run the query and cause the OOM exception. Then exit.
          there will be a java_pid<pid>.hprof file.
          [15:03] jhat java_pid6920.hprof and then with your browser connect to http://localhost:7000
          there are good quick instructions at http://www.marcsturlese.com/2009/05/09/analyzing-java-heaps-with-jmap-and-jhat/

          Show
          Lily Wei added a comment - This is the heap dump from OOM with the test case. Thank to Kathey and espinha for showing me how to do this. java -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/kmarsden/repro/derby-4294 org.apache.derby.tools.ij run the query and cause the OOM exception. Then exit. there will be a java_pid<pid>.hprof file. [15:03] jhat java_pid6920.hprof and then with your browser connect to http://localhost:7000 there are good quick instructions at http://www.marcsturlese.com/2009/05/09/analyzing-java-heaps-with-jmap-and-jhat/
          Hide
          Knut Anders Hatlen added a comment -

          I think you got the the digits right, but the total size of the CLOBs is 24MB, so they may exhaust a small heap if they for some reason aren't freed when moving to the next row.

          For the record, I didn't see the OOME when I tested with default heap settings on JDK 1.6.0_13 on OpenSolaris, but I did see it when reduced the heap size to 64 MB (-Xmx64M).

          Show
          Knut Anders Hatlen added a comment - I think you got the the digits right, but the total size of the CLOBs is 24MB, so they may exhaust a small heap if they for some reason aren't freed when moving to the next row. For the record, I didn't see the OOME when I tested with default heap settings on JDK 1.6.0_13 on OpenSolaris, but I did see it when reduced the heap size to 64 MB (-Xmx64M).
          Hide
          Kathey Marsden added a comment -

          I got it with the Sun 1.6 JDK
          va.sql.SQLException: Java exception: 'Java heap space: java.lang.OutOfMemoryError'.
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95)
          at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:87)
          at org.apache.derby.impl.jdbc.Util.javaException(Util.java:244)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:403)
          at org.apache.derby.impl.jdbc.EmbedResultSet.noStateChangeException(EmbedResultSet.java:4404)
          at org.apache.derby.impl.jdbc.EmbedResultSet.getString(EmbedResultSet.java:679)
          at org.apache.derby.iapi.tools.i18n.LocalizedResource.getLocalizedString(LocalizedResource.java:336)
          at org.apache.derby.tools.JDBCDisplayUtil.DisplayRow(JDBCDisplayUtil.java:678)
          at org.apache.derby.tools.JDBCDisplayUtil.indent_DisplayResults(JDBCDisplayUtil.java:385)
          at org.apache.derby.tools.JDBCDisplayUtil.indent_DisplayResults(JDBCDisplayUtil.java:338)
          at org.apache.derby.tools.JDBCDisplayUtil.indent_DisplayResults(JDBCDisplayUtil.java:241)
          at org.apache.derby.tools.JDBCDisplayUtil.DisplayResults(JDBCDisplayUtil.java:229)
          at org.apache.derby.impl.tools.ij.utilMain.displayResult(utilMain.java:432)
          at org.apache.derby.impl.tools.ij.utilMain.doCatch(utilMain.java:506)
          at org.apache.derby.impl.tools.ij.utilMain.runScriptGuts(utilMain.java:350)
          at org.apache.derby.impl.tools.ij.utilMain.go(utilMain.java:245)
          at org.apache.derby.impl.tools.ij.Main.go(Main.java:210)
          at org.apache.derby.impl.tools.ij.Main.mainCore(Main.java:177)
          at org.apache.derby.impl.tools.ij.Main.main(Main.java:73)
          at org.apache.derby.tools.ij.main(ij.java:59)
          used by: java.sql.SQLException: Java exception: 'Java heap space: java.lang.OutOfMemoryError'.
          at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45)
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:11

          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70)
          ... 19 more
          used by: java.lang.OutOfMemoryError: Java heap space
          at org.apache.derby.iapi.types.SQLChar.readExternal(SQLChar.java:1166)
          at org.apache.derby.iapi.types.SQLClob.readExternal(SQLClob.java:726)
          at org.apache.derby.iapi.types.SQLChar.getString(SQLChar.java:697)
          at org.apache.derby.impl.jdbc.EmbedResultSet.getString(EmbedResultSet.java:665)
          ... 14 more
          >

          The largest message in the 14 rows is 2702475 according to LENGTH(MESSAGE), so even though ij is doing a getString() and materializing the CLOB I am surprised it is running out of memory with a less than 3MB CLOB.

          As an aside, for jdk 1.6 where it can call free, maybe it would make sense for ij to do a getSubString on CLOBS for only the amount it plans to display insted of a getString() to get the whole thing. I still don't think in this case it should run out of memory with this size CLOB unless I have slipped a digit which is not uncommon.

          Show
          Kathey Marsden added a comment - I got it with the Sun 1.6 JDK va.sql.SQLException: Java exception: 'Java heap space: java.lang.OutOfMemoryError'. at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95) at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:87) at org.apache.derby.impl.jdbc.Util.javaException(Util.java:244) at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:403) at org.apache.derby.impl.jdbc.EmbedResultSet.noStateChangeException(EmbedResultSet.java:4404) at org.apache.derby.impl.jdbc.EmbedResultSet.getString(EmbedResultSet.java:679) at org.apache.derby.iapi.tools.i18n.LocalizedResource.getLocalizedString(LocalizedResource.java:336) at org.apache.derby.tools.JDBCDisplayUtil.DisplayRow(JDBCDisplayUtil.java:678) at org.apache.derby.tools.JDBCDisplayUtil.indent_DisplayResults(JDBCDisplayUtil.java:385) at org.apache.derby.tools.JDBCDisplayUtil.indent_DisplayResults(JDBCDisplayUtil.java:338) at org.apache.derby.tools.JDBCDisplayUtil.indent_DisplayResults(JDBCDisplayUtil.java:241) at org.apache.derby.tools.JDBCDisplayUtil.DisplayResults(JDBCDisplayUtil.java:229) at org.apache.derby.impl.tools.ij.utilMain.displayResult(utilMain.java:432) at org.apache.derby.impl.tools.ij.utilMain.doCatch(utilMain.java:506) at org.apache.derby.impl.tools.ij.utilMain.runScriptGuts(utilMain.java:350) at org.apache.derby.impl.tools.ij.utilMain.go(utilMain.java:245) at org.apache.derby.impl.tools.ij.Main.go(Main.java:210) at org.apache.derby.impl.tools.ij.Main.mainCore(Main.java:177) at org.apache.derby.impl.tools.ij.Main.main(Main.java:73) at org.apache.derby.tools.ij.main(ij.java:59) used by: java.sql.SQLException: Java exception: 'Java heap space: java.lang.OutOfMemoryError'. at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:11 at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70) ... 19 more used by: java.lang.OutOfMemoryError: Java heap space at org.apache.derby.iapi.types.SQLChar.readExternal(SQLChar.java:1166) at org.apache.derby.iapi.types.SQLClob.readExternal(SQLClob.java:726) at org.apache.derby.iapi.types.SQLChar.getString(SQLChar.java:697) at org.apache.derby.impl.jdbc.EmbedResultSet.getString(EmbedResultSet.java:665) ... 14 more > The largest message in the 14 rows is 2702475 according to LENGTH(MESSAGE), so even though ij is doing a getString() and materializing the CLOB I am surprised it is running out of memory with a less than 3MB CLOB. As an aside, for jdk 1.6 where it can call free, maybe it would make sense for ij to do a getSubString on CLOBS for only the amount it plans to display insted of a getString() to get the whole thing. I still don't think in this case it should run out of memory with this size CLOB unless I have slipped a digit which is not uncommon.
          Hide
          Lily Wei added a comment -

          Hi Kathey:
          I am not sure. I just tried on my trunk(10.6). I still see the error:
          43 |ABCH

          WXYV abcdefghi
          jklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijk
          lmnopqrstuvwxyzabcdefghijklmnopqrstuvw&
          2009-06-29 21:58:30.101 NULL 0
          NULL 0 This column is used only to by pass the
          space problem. If the problem still exists, then we are going to have a serious
          issue h&
          ERROR XJ001: Java exception: 'Java heap space: java.lang.OutOfMemoryError'.

          However, I don't see it from 10.5. That is sort of good news, Right?

          Show
          Lily Wei added a comment - Hi Kathey: I am not sure. I just tried on my trunk(10.6). I still see the error: 43 |ABCH WXYV abcdefghi jklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijklmnopqrstuvwxyzabcdefghijk lmnopqrstuvwxyzabcdefghijklmnopqrstuvw& 2009-06-29 21:58:30.101 NULL 0 NULL 0 This column is used only to by pass the space problem. If the problem still exists, then we are going to have a serious issue h& ERROR XJ001: Java exception: 'Java heap space: java.lang.OutOfMemoryError'. However, I don't see it from 10.5. That is sort of good news, Right?
          Hide
          Kathey Marsden added a comment -

          Hi Lily, with IBM 1.6 and 10.5 I tried connecting to this database and doing SELECT * FROM REFRESH.INBOX;

          It completed normally and returned 14 rows without the OutOfMemory exception. Am I doing something wrong?

          Show
          Kathey Marsden added a comment - Hi Lily, with IBM 1.6 and 10.5 I tried connecting to this database and doing SELECT * FROM REFRESH.INBOX; It completed normally and returned 14 rows without the OutOfMemory exception. Am I doing something wrong?
          Hide
          Lily Wei added a comment -

          This is the .zip files that contains mailsdb database and log files.

          Show
          Lily Wei added a comment - This is the .zip files that contains mailsdb database and log files.

            People

            • Assignee:
              Unassigned
              Reporter:
              Lily Wei
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development