Content and media loads twice from SQL to nucache on a fresh server

[nzdev]

Media and Content loads twice into NuCache from the sql database when a fresh server (no nucache .db files and no last synced file).
1st load is when the PublishedSnapshotService starts. Then once the DatabaseServerMessenger starts, the server is determined as out of sync, then the content and media is loaded from sql again. This significantly increases the time for a new instance to be ready to serve requests.

Umbraco version

I am seeing this issue on Umbraco version: 8.11.1

Reproduction

Bug summary

Content and media is loaded twice from sql on startup when the app_data/TEMP directory is empty

Specifics

{"@t":"2021-02-09T02:22:30.4893268Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Loading content from database","TimingId":"fdee707","SourceContext":"Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:28:53.0727284Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Completed.","Duration":382583,"TimingId":"fdee707","SourceContext":"Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:29:46.3024482Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Loading media from database","TimingId":"431c4fe","SourceContext":"Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:34:10.7644523Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Completed.","Duration":264461,"TimingId":"431c4fe","SourceContext":"Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:34:16.7334473Z","@mt":"Initializing Umbraco internal event handlers for cache refreshing.","SourceContext":"Umbraco.Web.Cache.DistributedCacheBinderComponent","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:34:16.8644506Z","@mt":"Adding examine event handlers for {RegisteredIndexers} index providers.","RegisteredIndexers":3,"SourceContext":"Umbraco.Web.Search.ExamineComponent","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:34:16.9094477Z","@mt":"No last synced Id found, this generally means this is a new server/install. The server will build its caches and indexes, and then adjust its last synced Id to the latest found in the database and maintain cache updates based on that Id.","@l":"Warning","SourceContext":"Umbraco.Core.Sync.DatabaseServerMessenger","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"WARN ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:34:16.9674502Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Loading content from database","TimingId":"ff5eaac","SourceContext":"Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:41:24.7408795Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Completed.","Duration":427773,"TimingId":"ff5eaac","SourceContext":"Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:41:24.8038806Z","@mt":"{StartMessage} [Timing {TimingId}]","StartMessage":"Loading media from database","TimingId":"4fe97e6","SourceContext":"Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}
{"@t":"2021-02-09T02:46:05.0505265Z","@mt":"{EndMessage} ({Duration}ms) [Timing {TimingId}]","EndMessage":"Completed.","Duration":280246,"TimingId":"4fe97e6","SourceContext":"Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService","ProcessId":8744,"ProcessName":"iisexpress","ThreadId":1,"AppDomainId":2,"AppDomainAppId":"LMW3SVC13ROOT","MachineName":"","Log4NetLevel":"INFO ","HttpRequestNumber":1,"HttpRequestId":"424ac081-8206-4296-843b-85d2a2c25d43"}

Steps to reproduce

Delete contents of App_Data/TEMP.
Start site.
Watch logs for loading content/media from the database entries.

Expected result

Content and media is loaded only once on start up from SQL into nucache

Actual result

Content and media is loaded twice on start up from SQL into nucache

[emma-hq]

Hey @nzdev,

Thanks for reporting this performance issue. I'll take a look and label to ensure the right people get to see this.

Emma

[umbrabot]

Hi @nzdev,

We're writing to let you know that we would love some help with this issue. We feel that this issue is ideal to flag for a community member to work on it. Once flagged here, folk looking for issues to work on will know to look at yours. Of course, please feel free work on this yourself ;-). If there are any changes to this status, we'll be sure to let you know.

For more information about issues and states, have a look at this blog post

Thanks muchly, from your friendly Umbraco GitHub bot :-)

[Shazwazza]

@nul800sebastiaan I've marked this one as 8.15 too (and removed the tags from the PR targeting this one ... I think that's what we want?). I'm not 100% sure this wasn't already released though but I think it's for 8.15. Let me know what you think.

[nul800sebastiaan]

The PR (#9859) was merged into the PR #10182 fixing issue #8893 which is already marked as 8.15.

I guess this is fine for adding to the release notes as it makes clear that this is a fix that was added to the release. So while a bit of a confusing journey for this one, good to mark it as fixed in 8.15 yep! 👍