Click here to create a new issue on GitHub

U4-10897 - Timing issue when refreshing content caches

Created by Claus Jensen 29 Jan 2018, 12:17:45 Updated by Claus Jensen 01 Mar 2018, 12:27:27

Tags: Unscheduled Gold partner

Subtask of: U4-9609

Seems to be a timing issue with the events triggered when updating content caches.

Steps to replicate:

  • Umbraco on vLatest (tested 7.7.6-7.7.10)

  • Add a IApplicationHandler hooking into the GatheringNodeData event (see attached file!)

  • Create a simple doctype

  • Put a breakpoint in PageCacheRefresher.cs line 88.

  • Put a breakpoint in handler at this line: IPublishedContent content = helper.TypedContent(e.NodeId);

  • Create a new content item (has to be a new one so there's no existing old entries of it in the caches)

  • SavePublish

You should hit the PageCacheRefresher breakpoint

  • If you now hit F5 and let the code run - you should hit the breakpoint in the handler and (most of the time) content resolves to null.

  • If you instead hit F10 and let it run the base.Refresh(instance); in PageCacheRefresher ... wait for a few seconds .. and then hit F5. Now you should hit the breakpoint in the handler and content should ''not'' be null.

'''Remember to do this with a new content item every time for consistent results...'''

I'm not sure if it is Examine that should find a better event to hook into - or if we can ensure that the order of the underlying events happening when the TypedCacheRefresher triggers:

OnCacheUpdated(Instance, new CacheRefresherEventArgs(instance, MessageType.RefreshByInstance));

can be somehow ordered to make sure they aren't executed in an order where things could end up being null.

1 Attachments

Download test.cs

Comments

Stephan 30 Jan 2018, 10:02:37

@claus in the posted code, you create an UmbracoHelper instance in ExamineCultureEvents OnApplicationStated, thus capturing ... the "current" UmbracoContext at that time ... which is wrong. What you want is to create a new helper in the event handler, each time the event triggers.

Not 100% sure that's the cause of your problems but...

Making sense?
Stephan 30 Jan 2018, 10:54:51

so... that UmbracoContext capture is not elegant, but it's not the cause of the issue - from what I'm seeing, ExamineManager.Instance.IndexProviderCollection["ExternalIndexer"].GatheringNodeData triggers after the PageCacheRefresher CacheUpdated even has triggered - which causes Examine to re-index the content - that event is dispatched by the Scope - and then, setting the updated XmlDocument on the content cache happens when the corresponding Scope enlisted object triggers - and enlisted objects trigger after events have been dispatched - so we have a race condition here
Stephan 30 Jan 2018, 11:00:41

notes to self: enlisted objects are enlisted in the ScopeContext which lives longer than the Scope precisely to carry objects that have operations that need to run after all events etc have run, such as updating the Xml cache only once per scope - so switching events and enlisted objects is... not really an option
Stephan 30 Jan 2018, 11:14:20

in other words: the Xml cache is ''not'' updated when events trigger - which raises the question: what if someone wants to do something that ''requires'' the Xml cache to be updated?
Stephan 30 Jan 2018, 11:49:59

Details:

  • a Scope queues all events and dispatches the events when (and only if) it is completed
  • the CacheRefresherEventHandler handles these events and triggers cache refreshes
  • if the XmlCache were to be updated on each cache refresh, we would clone the XmlDocument many times
  • we did this in the past, and it was bad, huge memory usage
  • so now one unique, cloned, XmlDocument Reader/Writer is ''enlisted'' with the Scope
  • and all events use this Reader/Write to update the unique cloned XmlDocument
  • and ''after'' all events have triggered, the Scope ensures that the enlisted changes are applied

Scope enlisting is a generic, Scope-level, mechanism - which is used by the Xml cache exclusively as of current v7 versions.

It is somewhat understandable, from a user point of view, that the Xml cache is immediately updated and thus immediately available in any event handler - but then, if we keep updating the current XmlDocument, we re-introduce the associated performance and memory issues
Stephan 30 Jan 2018, 12:54:04

Done: when requesting the Xml content, looking for an enlisted, mutable clone, and returning that clone. So now, event handlers immediately see the updated Xml. Caveat: the Xml they see is mutable.

But: the GP code hooks into an Examine event, which runs ... in a separate threads, and therefore has no access to the enlisted clone - also explains why, depending on how fast Examine reindexes things, they see the updated Xml or not.
Stephan 30 Jan 2018, 12:59:07

Done: have refactored ExamineEvents to defer the actual re-indexing until the Xml cache has been refreshed. This is done by enlisting (in the Scope) the list of actions to execute. The Xml cache writer is enlisted with priority 90, and the ExamineEvents with priority 99 - thus ensuring actions are executed after the cache refresh, but before anything that would be enlisted by users at the default priority, which is 100.

Note that it is very unlikely that anyone ever tried to enlist anything. It's a kinda hidden feature.

So... it's in branch https://github.com/umbraco/Umbraco-CMS/tree/temp-u4-10897 - there is no PR yet, I'd love @claus to test and tell me if it fixes his issues + I need to do some code review to ensure I haven't done anything stupid.
Stephan 31 Jan 2018, 10:10:05

looks good to me, here is the PR https://github.com/umbraco/Umbraco-CMS/pull/2423

ready for review - should not break our tests, should not break indexing, should fix the reported issue

CHANGES: (1) now, during events, ppl see the (mutable) current Xml so they see all changes immediately - this is a change, but probably a GOOD THING. (2) the Examine indexing takes place AFTER the Xml cache has been updated, again a GOOD THING.
Shane Marsden 01 Mar 2018, 12:21:42

marked as fixed and merged, which version of Umbraco is this fix first available in?
Claus Jensen 01 Mar 2018, 12:27:27

@shane.marsden Should be included in 7.7.10 as far as I can see from the commits.

I've updated the 'due in' here :)

Priority: Normal

Type: Bug

State: Fixed

Assignee:

Difficulty: Normal

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions: 7.7.6, 7.7.7, 7.7.9

Due in version: 7.7.10

Sprint: Sprint 77

Story Points: 2

Cycle: