EnvironmentFailureException

-= MyX =-

Hello!

I've upgraded my systems to use 6.0.11 instead of 5.0.97. Everything works fine, storage is 20+ percent more compact and so on, BUT.

1) Under load (all the time) on production server, after every 25-40 minutes uptime the

    > (JE 6.0.11) Environment must be closed, caused by: com.sleepycat.je.EnvironmentFailureException: Environment invalid because of previous exception: (JE 6.0.11) /usr/local/ae3/private/data/bdbj-lcl java.lang.AssertionError UNCAUGHT_EXCEPTION: Uncaught Exception in internal thread, unable to continue. Environment is invalid and must be closed.

    > com.sleepycat.je.EnvironmentFailureException

        > Environment invalid because of previous exception: (JE 6.0.11) /usr/local/ae3/private/data/bdbj-lcl java.lang.AssertionError UNCAUGHT_EXCEPTION: Uncaught Exception in internal thread, unable to continue. Environment is invalid and must be closed.

        > com.sleepycat.je.EnvironmentFailureException

            > null

            > java.lang.AssertionError

              : com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2014)

              : com.sleepycat.je.evictor.LRUEvictor.findParentAndRetry(LRUEvictor.java:2182)

              : com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2019)

              : com.sleepycat.je.evictor.LRUEvictor.evictBatch(LRUEvictor.java:1689)

              : com.sleepycat.je.evictor.LRUEvictor.doEvict(LRUEvictor.java:1538)

              : com.sleepycat.je.evictor.Evictor$BackgroundEvictTask.run(Evictor.java:739)

              : java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

              : java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

              : java.lang.Thread.run(Thread.java:724)

error appears and floods everything, I have to restart the instance and then it works another 30 minutes approx.

Same thing was happening on non heavy loaded (all) servers during log file upgrade to new format, timing was random tough. None of the environments that are bigger than 1G size were upgraded 'in one go' - I had to restart several times because of the same error.

2) I had to reduce the number of cleaner threads to 1 (config.setConfigParam( EnvironmentConfig.CLEANER_THREADS, "1" )) - otherwise it was not starting AT ALL, on every database instance it was failing on with words like "expect BEING_CLEANED but CLEANED"

I am using low-level BDB JE API with cursors and byte arrays. No secondary databases. No DPL. Does anyone experiencing anything like that?

ArtemGr

Same here,

AssertionError

        at com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2014)

        at com.sleepycat.je.evictor.LRUEvictor.findParentAndRetry(LRUEvictor.java:2182)

        at com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2019)

        at com.sleepycat.je.evictor.LRUEvictor.evictBatch(LRUEvictor.java:1689)

        at com.sleepycat.je.evictor.LRUEvictor.doEvict(LRUEvictor.java:1538)

        at com.sleepycat.je.evictor.Evictor$BackgroundEvictTask.run(Evictor.java:739)

AssertionError

        at com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2014)

        at com.sleepycat.je.evictor.LRUEvictor.findParentAndRetry(LRUEvictor.java:2182)

        at com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2019)

        at com.sleepycat.je.evictor.LRUEvictor.evictBatch(LRUEvictor.java:1689)

        at com.sleepycat.je.evictor.LRUEvictor.doEvict(LRUEvictor.java:1538)

        at com.sleepycat.je.evictor.Evictor.doCriticalEviction(Evictor.java:469)

        at com.sleepycat.je.dbi.EnvironmentImpl.criticalEviction(EnvironmentImpl.java:2726)

        at com.sleepycat.je.dbi.CursorImpl.criticalEviction(CursorImpl.java:624)

        at com.sleepycat.je.Cursor.endMoveCursor(Cursor.java:4257)

        at com.sleepycat.je.Cursor.putAllowPhantoms(Cursor.java:2415)

        at com.sleepycat.je.Cursor.putNoNotify(Cursor.java:2363)

        at com.sleepycat.je.Cursor.putNotify(Cursor.java:2272)

        at com.sleepycat.je.Cursor.putNoDups(Cursor.java:2155)

        at com.sleepycat.je.Cursor.putInternal(Cursor.java:2123)

        at com.sleepycat.je.Database.putInternal(Database.java:1595)

        at com.sleepycat.je.Database.put(Database.java:1463)

The database works okay for a while, then this.

CPU 8-core AMD Opteron 3280; OS Debian Jessie.

$ java -version

java version "1.7.0_51"

OpenJDK Runtime Environment (IcedTea 2.4.6) (7u51-2.4.6-1)

OpenJDK 64-Bit Server VM (build 24.51-b03, mixed mode)

Greybird-Oracle

Hi,

I'm sorry to hear that this is happening.  This is not something we encountered in our testing.  We'll look into it this morning and report back on this thread as soon as we have more information.

User 1003218 or ArtemGr, do you have the ability to reproduce this in a non-production environment?

--mark

Greybird-Oracle

User 1003218 and ArtemGr,

If you are willing to reproduce this with an instrumented JE jar, please contact me via email -- mark.hayes at the obvious .com.  I will give you a JE jar file that is the same as 6.0.11 but outputs additional information when the problematic assertion fires.  This will help us to determine exactly what's happening.

If you are encountering this in production and you need a quick workaround, I suggest that you disable assertions in the LRUEvictor class or entirely.  We currently think the problem is a minor performance issue, but causes an assertion to fire.

To disable assertions entirely, do not pass -ea (or pass -da after -ea) on the Java command line.  To disable assertions only for the LRUEvictor class (where the problem assertion occurs), you can disable assertions selectively by passing:

   -ea -da:com.sleepycat.je.evictor.LRUEvictor

The -ea enables all assertions, and the -da (as shown above) disables them for the one class only.

If you are comfortable building the JE jar file yourself, another option is to comment out the line containing the assertion.

Our internal ticket for this item is [#23620].  If you have Oracle support for JE, be sure to file an SR through the support channel.

--mark

-= MyX =-

2nd issue regarding @ I had to reduce the number of cleaner threads to 1 (config.setConfigParam( EnvironmentConfig.CLEANER_THREADS, "1" )) - otherwise it was not starting AT ALL, on every database instance it was failing on with words like "expect BEING_CLEANED but CLEANED"@ is 100% reproducible.

The main issue with com.sleepycat.je.evictor.LRUEvictor is happening on one production server currently (57G data, 3/4 of that rotates per week (new data added, old data cleaned)), but it was happening on other servers while upgrading from previous log format.

My workaround was:

  if (environment != null && !environment.isValid()) {

       WorkerBdbj.LOG.event( "BDBJ-WORKER:FAILURE:FATAL",

            "Environment is invalid!",

            Convert.Throwable.toText( new IllegalStateException( "this:" + this + ", env:" + environment ) ) );

       try {

            environment.close();

       } catch (final Throwable t) {

            // ignore

       }

       Runtime.getRuntime().exit( -37 );

  }

Thanks for -da:com.sleepycat.je.evictor.LRUEvictor hint, anyway I wouldn't be able to assert it is safe to do so without your reply!

Several times I noticed different stack traces (normally it is like in initial post).

    > (JE 6.0.11) JAVA_ERROR: Java Error occurred, recovery may not be possible.

    > com.sleepycat.je.EnvironmentFailureException

        > null

        > java.lang.AssertionError

          : com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2014)

          : com.sleepycat.je.evictor.LRUEvictor.findParentAndRetry(LRUEvictor.java:2182)

          : com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2019)

          : com.sleepycat.je.evictor.LRUEvictor.evictBatch(LRUEvictor.java:1689)

          : com.sleepycat.je.evictor.LRUEvictor.doEvict(LRUEvictor.java:1538)

          : com.sleepycat.je.evictor.Evictor.doCriticalEviction(Evictor.java:469)

          : com.sleepycat.je.dbi.EnvironmentImpl.criticalEviction(EnvironmentImpl.java:2726)

          : com.sleepycat.je.dbi.CursorImpl.criticalEviction(CursorImpl.java:624)

          : com.sleepycat.je.Cursor.beginMoveCursor(Cursor.java:4217)

          : com.sleepycat.je.Cursor.beginMoveCursor(Cursor.java:4237)

          : com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:2795)

          : com.sleepycat.je.Cursor.searchNoDups(Cursor.java:2647)

          : com.sleepycat.je.Cursor.search(Cursor.java:2594)

          : com.sleepycat.je.Cursor.search(Cursor.java:2579)

          : com.sleepycat.je.Cursor.getSearchKey(Cursor.java:1698)

.....

    > (JE 6.0.11) JAVA_ERROR: Java Error occurred, recovery may not be possible.

    > com.sleepycat.je.EnvironmentFailureException

        > null

        > java.lang.AssertionError

          : com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2014)

          : com.sleepycat.je.evictor.LRUEvictor.findParentAndRetry(LRUEvictor.java:2182)

          : com.sleepycat.je.evictor.LRUEvictor.processTarget(LRUEvictor.java:2019)

          : com.sleepycat.je.evictor.LRUEvictor.evictBatch(LRUEvictor.java:1689)

          : com.sleepycat.je.evictor.LRUEvictor.doEvict(LRUEvictor.java:1538)

          : com.sleepycat.je.evictor.Evictor.doCriticalEviction(Evictor.java:469)

          : com.sleepycat.je.dbi.EnvironmentImpl.criticalEviction(EnvironmentImpl.java:2726)

          : com.sleepycat.je.dbi.CursorImpl.criticalEviction(CursorImpl.java:624)

          : com.sleepycat.je.dbi.CursorImpl.close(CursorImpl.java:583)

          : com.sleepycat.je.Cursor.endMoveCursor(Cursor.java:4269)

          : com.sleepycat.je.Cursor.searchAllowPhantoms(Cursor.java:2811)

          : com.sleepycat.je.Cursor.searchNoDups(Cursor.java:2647)

          : com.sleepycat.je.Cursor.search(Cursor.java:2594)

          : com.sleepycat.je.Cursor.search(Cursor.java:2579)

          : com.sleepycat.je.Cursor.getSearchKeyRange(Cursor.java:1757)

.......

Greybird-Oracle

Yes, the two stack traces are the same problem.

I don't know whether the cleaner problem you mentioned is the same or not, without more information.  Please send the complete output for this problem.  When it happens, are there exceptions in the je.info file?

I will work with you off-list to get more info using the instrumented JE jar.

--mark

Greybird-Oracle

Thanks to help from user 1003218 and ArtemGr we have confirmed what we thought -- there is a performance related bug, and an assertion that fires because of it.  You can safely disable assertions in this class as a workaround.  And we will work on a complete fix for the problem.

On a slightly different topic, we don't expect that JE applications will enable assertions in production.  It is your choice to do so, but you should be aware that you will pay a performance penalty because JE contains many assertions that are fairly expensive/slow.  We use assertions for expensive checks because they can be disabled, and normally should be disabled in performance critical applications.  For less expensive checks, and checks that are critical to ensuring data integrity, we do not use assertions -- in those cases, we use checks that are unconditionally performed.

--mark

-= MyX =-

The 'cleaner' problem (2nd issue from initial post) is looking like this:

1) I enable more than 1 Cleaner thread in EnvironmentConfig and

2) I have this assertion failed straight away regardless of load and database size:

May 20, 2014 1:13:20 PM com.sleepycat.je.utilint.DaemonThread run

SEVERE: Error caught in <DaemonThread name="Cleaner-2"/>

java.lang.AssertionError: Expected BEING_CLEANED but was CLEANED

  at com.sleepycat.je.cleaner.FileSelector.checkStatus(FileSelector.java:337)

  at com.sleepycat.je.cleaner.FileSelector.putBackFileForCleaning(FileSelector.java:388)

  at com.sleepycat.je.cleaner.FileProcessor.doClean(FileProcessor.java:317)

  at com.sleepycat.je.cleaner.FileProcessor.onWakeup(FileProcessor.java:137)

  at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:148)

  at java.lang.Thread.run(Thread.java:724)

3) environment is invalid after that

There are no exception appearing in je.info file. I've deleted those files, it created new one je.info.0 with:

2014-05-20 01:18:42.016 UTC INFO [/Volumes/workspace/myx/ae3-local-private/data/bdbj-lcl] Chose lowest utilized file for cleaning. fileChosen: 0x45e07 (adjustment disabled) totalUtilization: 59 bestFileUtilization: 4 isProbe: false

2014-05-20 01:18:42.123 UTC INFO [/Volumes/workspace/myx/ae3-local-private/data/bdbj-lcl] Chose file from files-to-migrate for cleaning. fileChosen: 0x45e07 (adjustment disabled) totalUtilization: 59 bestFileUtilization: 5 isProbe: false

2014-05-20 01:18:46.827 UTC INFO [/Volumes/workspace/myx/ae3-local-private/data/bdbj-lcl] CleanerRun 2 ends on file 0x45e07 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=39508 nINsObsolete=3614 nINsCleaned=343 nINsDead=283 nINsMigrated=60 nBINDeltasObsolete=3693 nBINDeltasCleaned=369 nBINDeltasDead=369 nBINDeltasMigrated=0 nLNsObsolete=25226 nLNsCleaned=6246 nLNsDead=6246 nLNsMigrated=0 nLNsMarked=0 nLNQueueHits=0 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x45ed5" initialAdjustments="5" recentLNSizesAndCounts="Cor:156959/1268-Est:6172463/127795 Cor:67852/336-Est:4786902/92389 Cor:16235/185-Est:6835644/138507 Cor:6782449/141235-Est:6782449/141235 Cor:6907652/139289-Est:6907652/139289 Cor:6782449/141235-Est:6782449/141235 Cor:6907652/139289-Est:6907652/139289 Cor:5560961/72665-Est:5849181/77826 Cor:914949/582-Est:4398827/72744 Cor:18712/192-Est:5366407/102775 "> inSummary=<INSummary totalINCount="3957" totalINSize="11585678" totalBINDeltaCount="4062" totalBINDeltaSize="1327646" obsoleteINCount="3614" obsoleteINSize="10917988" obsoleteBINDeltaCount="3693" obsoleteBINDeltaSize="1183915"/> estFileSummary=<summary totalCount="40369" totalSize="15995850" totalINCount="8019" totalINSize="12913324" totalLNCount="31472" totalLNSize="2993862" maxLNSize="13318" obsoleteINCount="7959" obsoleteLNCount="23034" obsoleteLNSize="1110544" obsoleteLNSizeCounted="3771" getObsoleteSize="15325552" getObsoleteINSize="12816704" getObsoleteLNSize="2420184" getMaxObsoleteSize="15764222" getMaxObsoleteLNSize="2858854" getAvgObsoleteLNSizeNotCounted="67.987366"/> recalcFileSummary=<summary totalCount="40369" totalSize="15995850" totalINCount="8019" totalINSize="12913324" totalLNCount="31472" totalLNSize="2993862" maxLNSize="0" obsoleteINCount="7307" obsoleteLNCount="25226" obsoleteLNSize="2560720" obsoleteLNSizeCounted="25226" getObsoleteSize="14416145" getObsoleteINSize="11766761" getObsoleteLNSize="2560720" getMaxObsoleteSize="14416145" getMaxObsoleteLNSize="2560720" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=1.0346907 newLnSizeCorrection=1.0346907 estimatedUtilization=4 correctedUtilization=4 recalcUtilization=10 correctionRejected=true

"files-to-migrate" looks strange, cause it migrated everything couple of days ago already with:

  config.setConfigParam( EnvironmentConfig.CLEANER_UPGRADE_TO_LOG_VERSION, "-1" );

-- MyX

Greybird-Oracle

Thanks for this additional info!

This error:

java.lang.AssertionError: Expected BEING_CLEANED but was CLEANED

is an assertion that keeps us from seeing an exception that occurred earlier.  If this is practical, you could find the original exception by running with assertions disabled in the com.sleepycat.je.cleaner.FileSelector class.

--mark

-= MyX =-

It doesn't fail with

-da:com.sleepycat.je.cleaner.FileSelector

in je.info I see just

2014-05-20 05:23:24.565 UTC INFO [/Volumes/workspace/myx/ae3-local-private/data/bdbj-lcl] Chose lowest utilized file for cleaning. fileChosen: 0x45e07 (adjustment disabled) totalUtilization: 59 bestFileUtilization: 4 isProbe: false

2014-05-20 05:23:24.617 UTC INFO [/Volumes/workspace/myx/ae3-local-private/data/bdbj-lcl] Chose file from files-to-migrate for cleaning. fileChosen: 0x45e07 (adjustment disabled) totalUtilization: 59 bestFileUtilization: 5 isProbe: false

2014-05-20 05:23:26.539 UTC INFO [/Volumes/workspace/myx/ae3-local-private/data/bdbj-lcl] CleanerRun 2 ends on file 0x45e07 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=39508 nINsObsolete=3614 nINsCleaned=343 nINsDead=283 nINsMigrated=60 nBINDeltasObsolete=3693 nBINDeltasCleaned=369 nBINDeltasDead=369 nBINDeltasMigrated=0 nLNsObsolete=25226 nLNsCleaned=6246 nLNsDead=6246 nLNsMigrated=0 nLNsMarked=0 nLNQueueHits=0 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x45ed6" initialAdjustments="5" recentLNSizesAndCounts="Cor:156959/1268-Est:6172463/127795 Cor:67852/336-Est:4786902/92389 Cor:16235/185-Est:6835644/138507 Cor:6782449/141235-Est:6782449/141235 Cor:6907652/139289-Est:6907652/139289 Cor:6782449/141235-Est:6782449/141235 Cor:6907652/139289-Est:6907652/139289 Cor:5560961/72665-Est:5849181/77826 Cor:914949/582-Est:4398827/72744 Cor:18712/192-Est:5366407/102775 "> inSummary=<INSummary totalINCount="3957" totalINSize="11585678" totalBINDeltaCount="4062" totalBINDeltaSize="1327646" obsoleteINCount="3614" obsoleteINSize="10917988" obsoleteBINDeltaCount="3693" obsoleteBINDeltaSize="1183915"/> estFileSummary=<summary totalCount="40369" totalSize="15995850" totalINCount="8019" totalINSize="12913324" totalLNCount="31472" totalLNSize="2993862" maxLNSize="13318" obsoleteINCount="7959" obsoleteLNCount="23034" obsoleteLNSize="1110544" obsoleteLNSizeCounted="3771" getObsoleteSize="15325552" getObsoleteINSize="12816704" getObsoleteLNSize="2420184" getMaxObsoleteSize="15764222" getMaxObsoleteLNSize="2858854" getAvgObsoleteLNSizeNotCounted="67.987366"/> recalcFileSummary=<summary totalCount="40369" totalSize="15995850" totalINCount="8019" totalINSize="12913324" totalLNCount="31472" totalLNSize="2993862" maxLNSize="0" obsoleteINCount="7307" obsoleteLNCount="25226" obsoleteLNSize="2560720" obsoleteLNSizeCounted="25226" getObsoleteSize="14416145" getObsoleteINSize="11766761" getObsoleteLNSize="2560720" getMaxObsoleteSize="14416145" getMaxObsoleteLNSize="2560720" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=1.0346907 newLnSizeCorrection=1.0346907 estimatedUtilization=4 correctedUtilization=4 recalcUtilization=10 correctionRejected=true

2014-05-20 05:23:26.539 UTC INFO [/Volumes/workspace/myx/ae3-local-private/data/bdbj-lcl] CleanerRun 1 ends on file 0x45e07 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=39508 nINsObsolete=3614 nINsCleaned=343 nINsDead=283 nINsMigrated=60 nBINDeltasObsolete=3693 nBINDeltasCleaned=369 nBINDeltasDead=369 nBINDeltasMigrated=0 nLNsObsolete=25226 nLNsCleaned=6246 nLNsDead=6246 nLNsMigrated=0 nLNsMarked=0 nLNQueueHits=0 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x45ed6" initialAdjustments="5" recentLNSizesAndCounts="Cor:156959/1268-Est:6172463/127795 Cor:67852/336-Est:4786902/92389 Cor:16235/185-Est:6835644/138507 Cor:6782449/141235-Est:6782449/141235 Cor:6907652/139289-Est:6907652/139289 Cor:6782449/141235-Est:6782449/141235 Cor:6907652/139289-Est:6907652/139289 Cor:5560961/72665-Est:5849181/77826 Cor:914949/582-Est:4398827/72744 Cor:18712/192-Est:5366407/102775 "> inSummary=<INSummary totalINCount="3957" totalINSize="11585678" totalBINDeltaCount="4062" totalBINDeltaSize="1327646" obsoleteINCount="3614" obsoleteINSize="10917988" obsoleteBINDeltaCount="3693" obsoleteBINDeltaSize="1183915"/> estFileSummary=<summary totalCount="40369" totalSize="15995850" totalINCount="8019" totalINSize="12913324" totalLNCount="31472" totalLNSize="2993862" maxLNSize="13318" obsoleteINCount="7959" obsoleteLNCount="23034" obsoleteLNSize="1110544" obsoleteLNSizeCounted="3771" getObsoleteSize="15325552" getObsoleteINSize="12816704" getObsoleteLNSize="2420184" getMaxObsoleteSize="15764222" getMaxObsoleteLNSize="2858854" getAvgObsoleteLNSizeNotCounted="67.987366"/> recalcFileSummary=<summary totalCount="40369" totalSize="15995850" totalINCount="8019" totalINSize="12913324" totalLNCount="31472" totalLNSize="2993862" maxLNSize="0" obsoleteINCount="7307" obsoleteLNCount="25226" obsoleteLNSize="2560720" obsoleteLNSizeCounted="25226" getObsoleteSize="14416145" getObsoleteINSize="11766761" getObsoleteLNSize="2560720" getMaxObsoleteSize="14416145" getMaxObsoleteLNSize="2560720" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=1.0346907 newLnSizeCorrection=1.0346907 estimatedUtilization=4 correctedUtilization=4 recalcUtilization=10 correctionRejected=true

-= MyX =-

Regarding having assertions ON on production server:

I've done some tests and difference between all assertions ON (-ea -esa) and all assertions OFF (-da -dsa) is just 1% less time for a long test task (run many times stable results). Normally assertion fails when something is wrong (not as expected so conditional statements are not designed for situation) and sometimes they provide more info (or more readable info (or point to cause without need to use deduction and know values of variables on stack)) in case of a problem. Many of strange problems are happening on production servers cause there is real data, real users, some 'history' (logically broken stuff from previous bugs, etc...) So I have assertions in the (-ea -dsa) mode normally. And I will always have the option of switching them OFF as a last resort when will go out of capacity, which is well above the need currently 8-)

Thanks.