[MGNLCACHE-199] Excessive cache flush due to wrong event pattern matching Created: 16/Apr/18  Updated: 28/Feb/20  Resolved: 28/Feb/20

Status: Closed
Project: Cache Modules
Component/s: cache core
Affects Version/s: 5.6.1
Fix Version/s: None

Type: Bug Priority: Neutral
Reporter: Viet Nguyen Assignee: Unassigned
Resolution: Not an issue Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Java Source File DefaultListeningFlushPolicy.java    
Template:
Acceptance criteria:
Empty
Task DoD:
[ ]* Doc/release notes changes? Comment present?
[ ]* Downstream builds green?
[ ]* Solution information and context easily available?
[ ]* Tests
[ ]* FixVersion filled and not yet released
[ ]  Architecture Decision Record (ADR)
Bug DoR:
[ ]* Steps to reproduce, expected, and actual results filled
[ ]* Affected version filled
Date of First Response:

 Description   
  • After investigating into detail of cache flush - flush all policy extends from AbstractListeningFlushPolicy, we recognized that function 'info.magnolia.module.cache.AbstractListeningFlushPolicy.CacheCleaner.onEvent(EventIterator)' will trigger info.magnolia.module.cache.FlushAllListeningPolicy.preHandleEvents(Cache, String) on all most all events which leads to the whole cache flush multiple times.
  • Changing the filter from
    if (!event.getPath().startsWith("/jcr:")) {
        eventList.add(event);
    }
    

    to

    if (event.getPath().lastIndexOf("/jcr:")==-1 && event.getPath().lastIndexOf("/mgnl:")==-1) {
        eventList.add(event);
    }
    

    Could help alleviate the situation.

  • Please reference to attachment for a 'debug' version of cache flush policy which could print out all the events with its path for your information.
    Sample output:
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/jcr:lockOwner
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/jcr:lockOwner
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/jcr:lockIsDeep
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/jcr:lockIsDeep
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/main/jcr:created
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/main/jcr:created
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/main/mgnl:lastModifiedBy
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/main/mgnl:created
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/main/mgnl:lastModifiedBy
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/main/jcr:uuid
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/main/mgnl:created
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/main/jcr:uuid
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/main/mgnl:lastModified
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/main/mgnl:lastModified
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/main/jcr:primaryType
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/main/mgnl:createdBy
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/main/jcr:primaryType
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/main/mgnl:createdBy
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/main/jcr:createdBy
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/main/jcr:createdBy
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 1 and path /test/aaaa/main
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 1 and path /test/aaaa/main
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 16 and path /test/aaaa/mgnl:lastModified
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 16 and path /test/aaaa/mgnl:lastModified
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 16 and path /test/aaaa/mgnl:lastModifiedBy
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 8 and path /test/aaaa/jcr:lockOwner
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 8 and path /test/aaaa/jcr:lockIsDeep
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 16 and path /test/aaaa/mgnl:lastModifiedBy
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/jcr:lockOwner
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 8 and path /test/aaaa/jcr:lockOwner
    2018-04-16 14:29:07,193 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/jcr:lockIsDeep
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/footer/mgnl:lastModified
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 8 and path /test/aaaa/jcr:lockIsDeep
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/footer/jcr:created
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/jcr:lockOwner
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/footer/jcr:primaryType
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/jcr:lockIsDeep
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/footer/mgnl:created
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/footer/mgnl:lastModified
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/footer/jcr:createdBy
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/footer/jcr:created
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/footer/jcr:uuid
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/footer/jcr:primaryType
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/footer/mgnl:lastModifiedBy
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/footer/mgnl:created
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 4 and path /test/aaaa/footer/mgnl:createdBy
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 1 and path /test/aaaa/footer
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/footer/jcr:createdBy
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 16 and path /test/aaaa/mgnl:lastModified
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/footer/jcr:uuid
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 16 and path /test/aaaa/mgnl:lastModifiedBy
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/footer/mgnl:lastModifiedBy
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 8 and path /test/aaaa/jcr:lockOwner
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache defaultPageCache in repository website which has event type 8 and path /test/aaaa/jcr:lockIsDeep
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 4 and path /test/aaaa/footer/mgnl:createdBy
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling pre-event cache defaultPageCache in repository website
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 1 and path /test/aaaa/footer
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 16 and path /test/aaaa/mgnl:lastModified
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 16 and path /test/aaaa/mgnl:lastModifiedBy
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 8 and path /test/aaaa/jcr:lockOwner
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling event cache uuid-key-mapping in repository website which has event type 8 and path /test/aaaa/jcr:lockIsDeep
    2018-04-16 14:29:07,194 DEBUG .magnolia.module.cache.DefaultListeningFlushPolicy: Handling pre-event cache uuid-key-mapping in repository website
    


 Comments   
Comment by Viet Nguyen [ 16/Apr/18 ]

Changing '/modules/cache/config/contentCaching/uuid-key-mapping/flushPolicy/policies/flushAll@class' from 'info.magnolia.module.cache.FlushAllListeningPolicy' to 'info.magnolia.module.cache.DefaultListeningFlushPolicy' for testing using DefaultListeningFlushPolicy.java (remember to enable cache log).

Comment by Jan Haderka [ 28/Feb/20 ]

Is there a support ticket this is related to for more details?

Looking at how the flush policies are instantiated, the first number indicates that we wait for up to 5 seconds since receiving the last event before processing it in case there are further events incoming so they can be processed together. The second number indicates that we wait up until 30 seconds in case events keep coming.

                        final EventListener listener = ObservationUtil.instanciateDeferredEventListener(cacheCleaner, 5000, 30000);

Looking at the log in this ticket:
{{ 14:29:07,193}}
{{ ...}}
{{ 14:29:07,194}}

1ms passed between all those events, so they were all processed by same event processing and resulted in single call to preHandleEvents thus to single cache flush.

This can be confirmed by observing the log further and seeing only 2 invocations of preHandleEvents denoted by log

... Handling pre-event ...

One call was for default content cache and one for UUID-key mapping cache.
All other calls are from preprocessing of the events and do not result in cache flush.

As for the other request that cache should not be flushed based on last modification date change of the ticket, this is invalid as well as it is common practice to query content based on the date changes or exclude or prioritize in results based on modification date hence such change is valid reason for flushing the cache.

Closing this ticket as invalid.

Generated at Sun Feb 11 23:53:10 CET 2024 using Jira 9.4.2#940002-sha1:46d1a51de284217efdcb32434eab47a99af2938b.