Skip to Main Content

Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

DDL Triggers invoked on DROP COLUMN in 11.2.0.4.0

user10881119Sep 24 2015 — edited Sep 25 2015

Hi,


If you run the following code snippet below the trigger on the table is invoked when a clumn is dropped which had been added after the table creation and has a default value and not null defined. This is behaviour I could only reproduce in Oracle 11.2.0.4.0 but not in 11.2.0.3.0. COuld somebody please help me with this? Is this expected behaviour? How can I drop the column without running the trigger?


CREATE TABLE T (

    DESCRIPTION VARCHAR2(50)

);


INSERT INTO T (DESCRIPTION) VALUES ('asd');


COMMIT;


CREATE OR REPLACE TRIGGER BEFORE_T

  BEFORE INSERT OR DELETE OR UPDATE ON T

    REFERENCING OLD AS OLD NEW AS NEW

    FOR EACH ROW

BEGIN

    RAISE_APPLICATION_ERROR(-20001, 'This trigger should not be invoked!');

END BF_TRANSACTIONS;

/

ALTER TABLE T ADD AMOUNT NUMBER DEFAULT 0 NOT NULL;


ALTER TABLE T DROP COLUMN AMOUNT;

Comments

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.

Greybird-Oracle

Thank you for trying it with -da:com.sleepycat.je.cleaner.FileSelector.  Unfortunately, because there was no failure, we don't know the original cause.  It may be that earlier there was a problem with the environment's files that is no longer present, because those files have now been cleaned and deleted.  Based on the information we have, I was not able to deduce what the problem might be.  But if any sort of similar problem occurs again, this will give us more information.

Greybird-Oracle

There is nothing wrong with enabling assertions if you understand the potential performance issues.  But I thought it was important however that you understand that our policy is to freely add assertions without regard to performance.

--mark

1 - 12
Locked Post
New comments cannot be posted to this locked post.

Post Details

Locked on Oct 23 2015
Added on Sep 24 2015
6 comments
619 views