Skip to Main Content

SQL & PL/SQL

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!

Why my mview is not refreshing after commit?

JackKFeb 7 2022 — edited Feb 7 2022

Hi All.
I have tables:

create table OS_OUTAGES (
 out_id       NUMBER(22) generated by default on null as identity (nocache),
 out_number     VARCHAR2(40) not null,
 out_status     VARCHAR2(10) not null,
 out_dscr      VARCHAR2(4000),
 out_is_proposition VARCHAR2(1),
 out_usr_id     INTEGER not null,
 out_oki_code    VARCHAR2(20) not null,
 out_bup_code    NUMBER(12) not null,
 out_oup_id     NUMBER(20),
 out_gel_mrid    VARCHAR2(70) not null,
 out_vl_mrid    VARCHAR2(70),
 out_oty_code    VARCHAR2(20) not null,
 out_ouv_id     NUMBER(22) not null,
 out_swl_id     NUMBER(4),
 out_locked_by   NUMBER(22),
 out_locked_until  DATE,
 out_out_id     NUMBER(22),
 out_sch_id     NUMBER(22),
 out_ois_id     NUMBER(22),
 out_number__sort  as ("OMSW"."OS_UTIL"."OBJNUMBER2SORT"("OUT_NUMBER")),
 out_root_out_id  NUMBER(22),
 out_usid      VARCHAR2(55) invisible
);

alter table OS_OUTAGES add constraint OUT_PK primary key (OUT_ID);

alter table OS_OUTAGES
 add constraint OUT_OUV_FK foreign key (OUT_OUV_ID)
 references OS_OUTAGE_VERSIONS (OUV_ID) on delete set null
 deferrable initially deferred;

---

create table OS_OUTAGE_VERSIONS (
 ouv_id           NUMBER(22) generated by default on null as identity (nocache),
 ouv_change_time       DATE default sysdate not null,
 ouv_start          TIMESTAMP(0) WITH TIME ZONE not null,
 ouv_end           TIMESTAMP(0) WITH TIME ZONE not null,
 ouv_readiness        NUMBER,
 ouv_cycle          VARCHAR2(2) not null,
 ouv_break_possibility    CHAR(1),
 ouv_night_work       CHAR(1),
 ouv_saturday_work      CHAR(1),
 ouv_sunday_work       CHAR(1),
 ouv_out_id         NUMBER(22) not null,
 ouv_usr_id         INTEGER not null,
 ouv_status         VARCHAR2(10),
 ouv_version         VARCHAR2(43) not null,
 ouv_ouv_id         NUMBER(22),
 ouv_readiness_u       VARCHAR2(1),
 ouv_required_time      NUMBER,
 ouv_required_time_u     VARCHAR2(1),
 ouv_required_time__sort   as ("OUV_REQUIRED_TIME"*DECODE("OUV_REQUIRED_TIME_U",'d',1440,'h',60,'m',1)),
 ouv_prefered_start     TIMESTAMP(0) WITH TIME ZONE,
 ouv_prefered_end      TIMESTAMP(0) WITH TIME ZONE,
 ouv_cost          NUMBER,
 ouv_refusing_cost      NUMBER,
 ouv_readiness__sort     as ("OUV_READINESS"*DECODE("OUV_READINESS_U",'d',1440,'h',60,'m',1)),
 ouv_crr_id         NUMBER(4),
 ouv_rb2_09_valid      CHAR(1) default 'n' not null,
 ouv_in_cartesian      CHAR(1) default 'y' not null,
 ouv_weekend_work      CHAR(1),
 ouv_holiday_work      CHAR(1),
 ouv_priority        NUMBER(1) default 1,
 ouv_night_readiness     NUMBER(3),
 ouv_night_readiness_u    CHAR(1),
 ouv_busbar_work_possibility CHAR(1),
 ouv_schedule_required    CHAR(1),
 ouv_programme_required   CHAR(1),
 ouv_temp_ver        NUMBER(3),
 ouv_length         as ("OMSW"."OS_OUTAGE"."OUV_LENGTH_CALC"("OUV_START","OUV_END"))
);

alter table OS_OUTAGE_VERSIONS add constraint OUV_PK primary key (OUV_ID);

alter table OS_OUTAGE_VERSIONS
 add constraint OUV_OUT_FK foreign key (OUV_OUT_ID)
 references OS_OUTAGES (OUT_ID) on delete cascade;

---

create table OS_OUTAGE_PACKAGES (
 opa_id      NUMBER(22) generated by default on null as identity (nocache),
 opa_usr_id    NUMBER(22) not null,
 opa_opv_id    NUMBER(22),
 opa_locked_by  NUMBER(22),
 opa_locked_until DATE,
 opa_status    VARCHAR2(5) not null,
 opa_opa_id    NUMBER(22),
 opa_number    VARCHAR2(40),
 opa_sch_id    NUMBER(22),
 opa_pis_id    NUMBER(22),
 opa_bup_code   NUMBER(12) not null,
 opa_number__sort as ("OMSW"."OS_UTIL"."OBJNUMBER2SORT"("OPA_NUMBER")),
 opa_root_opa_id NUMBER(22),
 opa_type     CHAR(1) default 'P' not null,
 opa_category   CHAR(1)
);

alter table OS_OUTAGE_PACKAGES add constraint OPA_PK primary key (OPA_ID);

alter table OS_OUTAGE_PACKAGES
 add constraint OPA_OPV_FK foreign key (OPA_OPV_ID)
 references OS_OUTAGE_PACKAGE_VERSIONS (OPV_ID)
 deferrable initially deferred;

---

create table OS_OUTAGE_PACKAGE_VERSIONS (
 opv_id     NUMBER(22) generated by default on null as identity (nocache),
 opv_change_time DATE default sysdate not null,
 opv_opa_id   NUMBER(22) not null,
 opv_opv_id   NUMBER(22),
 opv_crr_id   NUMBER(4),
 opv_usr_id   NUMBER(22) not null,
 opv_version   VARCHAR2(43) not null,
 opv_management VARCHAR2(4),
 opv_pp_demand  CHAR(1),
 opv_h_demand  CHAR(1),
 opv_bw_demand  CHAR(1),
 opv_pca_code  VARCHAR2(10),
 opv_out_id   NUMBER(22),
 opv_temp_ver  NUMBER(3),
 opv_dscr    VARCHAR2(1500)
);

alter table OS_OUTAGE_PACKAGE_VERSIONS add constraint OPV_PK primary key (OPV_ID);

alter table OS_OUTAGE_PACKAGE_VERSIONS
 add constraint OPV_OPA_FK foreign key (OPV_OPA_ID)
 references OS_OUTAGE_PACKAGES (OPA_ID) on delete cascade;

alter table OS_OUTAGE_PACKAGE_VERSIONS
 add constraint OPV_OUT_FK foreign key (OPV_OUT_ID)
 references OS_OUTAGES (OUT_ID);

---

create table OS_OUTS_IN_PACKAGE (
 oip_id   NUMBER(22) generated by default on null as identity (nocache),
 oip_opv_id NUMBER(22) not null,
 oip_ouv_id NUMBER(22) not null,
 oip_status CHAR(1),
 oip_created DATE default sysdate
);

alter table OS_OUTS_IN_PACKAGE
 add constraint OIP_OPV_FK foreign key (OIP_OPV_ID)
 references OS_OUTAGE_PACKAGE_VERSIONS (OPV_ID) on delete cascade;

alter table OS_OUTS_IN_PACKAGE
 add constraint OIP_OUV_FK foreign key (OIP_OUV_ID)
 references OS_OUTAGE_VERSIONS (OUV_ID) on delete cascade;

There are of course some indexes created on FK columns.
I create materialized view log created:

create materialized view log on OS_OUTAGES
 with primary key, -- uncomment if table has PK
    rowid,
    sequence( -- all but PK columns
out_number
,out_status
,out_dscr
,out_is_proposition
,out_usr_id
,out_oki_code
,out_bup_code
,out_gel_mrid
,out_vl_mrid
,out_oty_code
,out_ouv_id
,out_swl_id
,out_locked_by
,out_locked_until
,out_out_id
,out_sch_id
,out_ois_id
--out_number__sort
,out_root_out_id
--out_usid
) including new values;

create materialized view log on OS_OUTAGE_VERSIONS
 with primary key, -- uncomment if table has PK
    rowid,
    sequence( -- all but PK columns
--ouv_id
ouv_change_time
,ouv_start
,ouv_end
,ouv_readiness
,ouv_cycle
,ouv_break_possibility
,ouv_night_work
,ouv_saturday_work
,ouv_sunday_work
,ouv_out_id
,ouv_usr_id
,ouv_status
,ouv_version
,ouv_ouv_id
,ouv_readiness_u
,ouv_required_time
,ouv_required_time_u
--ouv_required_time__sort
,ouv_prefered_start
,ouv_prefered_end
,ouv_cost
,ouv_refusing_cost
--ouv_readiness__sort
,ouv_crr_id
,ouv_rb2_09_valid
,ouv_in_cartesian
,ouv_weekend_work
,ouv_holiday_work
,ouv_priority
,ouv_night_readiness
,ouv_night_readiness_u
,ouv_busbar_work_possibility
,ouv_schedule_required
,ouv_programme_required
,ouv_temp_ver
--ouv_length
) including new values;

create materialized view log on OS_OUTAGE_PACKAGES
 with primary key, -- uncomment if table has PK
    rowid,
    sequence( -- all but PK columns
--opa_id
opa_usr_id
,opa_opv_id
,opa_locked_by
,opa_locked_until
,opa_status
,opa_opa_id
,opa_number
,opa_sch_id
,opa_pis_id
,opa_bup_code
--,opa_number__sort
,opa_root_opa_id
,opa_type
,opa_category
) including new values;

create materialized view log on OS_OUTAGE_PACKAGE_VERSIONS
 with primary key, -- uncomment if table has PK
    rowid,
    sequence( -- all but PK columns
--opv_id
opv_change_time
,opv_opa_id
,opv_opv_id
,opv_crr_id
,opv_usr_id
,opv_version
,opv_management
,opv_pp_demand
,opv_h_demand
,opv_bw_demand
,opv_pca_code
,opv_out_id
,opv_temp_ver
,opv_dscr
) including new values;

create materialized view log on OS_OUTS_IN_PACKAGE
 with --primary key, -- uncomment if table has PK
    rowid,
    sequence( -- all but PK columns
 oip_id
,oip_opv_id
,oip_ouv_id
,oip_status
,oip_created
) including new values;

Then I create mview:

create materialized view OS_OPV_AGGR_MVW
refresh fast on commit
as
SELECT opa_id, opv_id,
    min(ouv_start) AS min_start,
    max(ouv_end)  AS max_end
   ,count(*)    AS cnt
 FROM OS_OUTAGE_PACKAGES
   ,OS_OUTAGE_PACKAGE_VERSIONS
   ,OS_OUTS_IN_PACKAGE
   ,OS_OUTAGES
   ,OS_OUTAGE_VERSIONS
 WHERE opv_id = opa_opv_id
  AND oip_opv_id = opa_opv_id
  AND out_ouv_id = oip_ouv_id
  AND ouv_id = out_ouv_id
 GROUP BY opa_id, opv_id;

Mview is created correctly. However, when transaction is commited, mview is not being refreshed and rows in mvlogs persist.
I don't know where is the problem.
Could anyone help me?
I am using Oracle 19c.
Best regards,
Jacek

This post has been answered by Jonathan Lewis on Feb 7 2022
Jump to Answer

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

Post Details

Added on Feb 7 2022
12 comments
522 views