Reputation: 5381
We have a production site running Umbraco 7.6.0. Every morning, we receive a monitoring alert due to 30s+ response times on the home page, and about 10-15 minutes later, the issue resolves itself. Last night, we changed the log verbosity to DEBUG, and we are still unable to pinpoint the cause of the issue this morning. Every time this issue has occurred, we see what I believe to be some effects of the issue - the Keep Alive and Scheduled Publish tasks failing (likely timing out):
ERROR Umbraco.Web.Scheduling.ScheduledPublishing - Failed (at "https://www.[domainredacted].com:443/umbraco").
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Umbraco.Web.Scheduling.ScheduledPublishing.<PerformRunAsync>d__7.MoveNext()
Because the CPU and Memory Usage on the Azure App Service plan during the outage were stable, this leads me to believe there is some sort of deadlock - and it only occurs once a day. Unfortunately, the DEBUG logs aren't helpful either. I am trying to look for a task/procedure that starts but never ends. I see a Scheduled Publish that took 100 seconds (which is quite long), but again this could just be an effect caused by the issue, and not necessarily the cause itself. Does anyone have any ideas what the issue could be and/or how to better investigate?
Here is a log with redacted project-sensitive information:
2017-08-17 13:14:47,066 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: Begin finders
2017-08-17 13:14:47,066 [P4824/D11/T56] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,066 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - [route redacted]
2017-08-17 13:14:47,082 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - Got content, id=39911
2017-08-17 13:14:47,082 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: End finders, no document was found (took 8ms)
2017-08-17 13:14:47,082 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandlePublishedContent: Begin
2017-08-17 13:14:47,082 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - EnsurePublishedContentAccess: Page is not protected
2017-08-17 13:14:47,082 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandlePublishedContent: End
2017-08-17 13:14:47,082 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Look for template id=1191
2017-08-17 13:14:47,098 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Got template id=1191 alias="Property"
2017-08-17 13:14:47,098 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Running with template id=1191 alias="Property"
2017-08-17 13:14:47,098 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandleWildcardDomains: Path="-1,1054,1194,39911"
2017-08-17 13:14:47,098 [P4824/D11/T71] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandleWildcardDomains: No match.
2017-08-17 13:14:47,098 [P4824/D11/T71] DEBUG Umbraco.Web.UmbracoModule - Response status: Redirect=none, Is404=false, StatusCode=0
2017-08-17 13:14:47,238 [P4824/D11/T30] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,285 [P4824/D11/T60] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,301 [P4824/D11/T81] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,332 [P4824/D11/T56] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,332 [P4824/D11/T10] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,379 [P4824/D11/T71] DEBUG Umbraco.Web.UmbracoModule - Total milliseconds for umbraco request to process: 312.4882
2017-08-17 13:14:47,394 [P4824/D11/T23] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,551 [P4824/D11/T81] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,598 [P4824/D11/T58] DEBUG Umbraco.Core.Sync.ServerMessengerBase - Invoking refresher Umbraco.Web.Cache.UnpublishedPageCacheRefresher on local server for message type RefreshByInstance
2017-08-17 13:14:47,629 [P4824/D11/T58] DEBUG UmbracoExamine.DataServices.UmbracoLogService - ReIndexNode with type: content, Provider=InternalIndexer, NodeId=40744
2017-08-17 13:14:47,629 [P4824/D11/T58] DEBUG UmbracoExamine.DataServices.UmbracoLogService - AddSingleNodeToIndex with type: content, Provider=InternalIndexer, NodeId=40744
2017-08-17 13:14:47,738 [P4824/D11/T10] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,738 [P4824/D11/T10] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:47,816 [P4824/D11/T58] DEBUG Umbraco.Core.Sync.ServerMessengerBase - Invoking refresher Umbraco.Web.Cache.PageCacheRefresher on local server for message type RefreshByInstance
2017-08-17 13:14:47,879 [P4824/D11/T71] DEBUG UmbracoExamine.DataServices.UmbracoLogService - Index created for node 40744, Provider=InternalIndexer, NodeId=40744
2017-08-17 13:14:48,160 [P4824/D11/T58] DEBUG UmbracoExamine.DataServices.UmbracoLogService - ReIndexNode with type: content, Provider=InternalIndexer, NodeId=40744
2017-08-17 13:14:48,160 [P4824/D11/T58] DEBUG UmbracoExamine.DataServices.UmbracoLogService - AddSingleNodeToIndex with type: content, Provider=InternalIndexer, NodeId=40744
2017-08-17 13:14:48,160 [P4824/D11/T58] DEBUG UmbracoExamine.DataServices.UmbracoLogService - ReIndexNode with type: content, Provider=ExternalIndexer, NodeId=40744
2017-08-17 13:14:48,160 [P4824/D11/T58] DEBUG UmbracoExamine.DataServices.UmbracoLogService - AddSingleNodeToIndex with type: content, Provider=ExternalIndexer, NodeId=40744
2017-08-17 13:14:48,160 [P4824/D11/T23] DEBUG UmbracoExamine.DataServices.UmbracoLogService - Index created for node 40744, Provider=InternalIndexer, NodeId=40744
2017-08-17 13:14:48,207 [P4824/D11/T58] DEBUG Umbraco.Web.PublishedCache.XmlPublishedCache.XmlCacheFilePersister - Touched, was idle, start and save in 4000ms.
2017-08-17 13:14:48,223 [P4824/D11/T58] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Uri="[url redacted]"
2017-08-17 13:14:48,223 [P4824/D11/T58] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Matches no domain
2017-08-17 13:14:48,223 [P4824/D11/T58] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Culture="en-US"
2017-08-17 13:14:48,223 [P4824/D11/T58] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: Begin finders
2017-08-17 13:14:48,223 [P4824/D11/T58] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - [route redacted]
2017-08-17 13:14:48,238 [P4824/D11/T58] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - Got content, id=40744
2017-08-17 13:14:48,238 [P4824/D11/T58] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: End finders, no document was found (took 9ms)
2017-08-17 13:14:48,285 [P4824/D11/T61] DEBUG UmbracoExamine.DataServices.UmbracoLogService - Index created for node 40744, Provider=ExternalIndexer, NodeId=40744
2017-08-17 13:14:48,363 [P4824/D11/T15] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:48,379 [P4824/D11/T60] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:48,816 [P4824/D11/T71] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:49,332 [P4824/D11/T81] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:49,504 [P4824/D11/T81] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:49,848 [P4824/D11/T23] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:49,894 [P4824/D11/T10] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:51,316 [P4824/D11/T68] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:51,316 [P4824/D11/T68] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Syncing from database...
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Complete (took 29ms)
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Uri="[url redacted]"
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Matches no domain
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Culture="en-US"
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContentAndTemplate: Path="/"
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: Begin finders
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - [route redacted]
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - Got content, id=1054
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: End finders, no document was found (took 3ms)
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandlePublishedContent: Begin
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - EnsurePublishedContentAccess: Page is not protected
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandlePublishedContent: End
2017-08-17 13:14:51,348 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Look for template id=1048
2017-08-17 13:14:51,363 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Got template id=1048 alias="Homepage"
2017-08-17 13:14:51,363 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Running with template id=1048 alias="Homepage"
2017-08-17 13:14:51,363 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandleWildcardDomains: Path="-1,1054"
2017-08-17 13:14:51,363 [P4824/D11/T68] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandleWildcardDomains: No match.
2017-08-17 13:14:51,363 [P4824/D11/T68] DEBUG Umbraco.Web.UmbracoModule - Response status: Redirect=none, Is404=false, StatusCode=0
2017-08-17 13:14:51,426 [P4824/D11/T68] DEBUG Umbraco.Web.UmbracoModule - Total milliseconds for umbraco request to process: 109.3749
2017-08-17 13:14:52,223 [P4824/D11/T65] DEBUG Umbraco.Web.PublishedCache.XmlPublishedCache.XmlCacheFilePersister - Timer: release.
2017-08-17 13:14:52,223 [P4824/D11/T65] DEBUG Umbraco.Web.PublishedCache.XmlPublishedCache.XmlCacheFilePersister - Run now (sync).
2017-08-17 13:14:52,223 [P4824/D11/T65] INFO umbraco.content - Save Xml to file...
2017-08-17 13:14:53,100 [P4824/D11/T10] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:53,631 [P4824/D11/T65] INFO umbraco.content - Saved Xml to file.
2017-08-17 13:14:54,563 [P4824/D11/T60] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:56,003 [P4824/D11/T71] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:14:59,953 [P4824/D11/T61] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks executing
2017-08-17 13:14:59,953 [P4824/D11/T61] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks complete (took 0ms)
2017-08-17 13:14:59,953 [P4824/D11/T61] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Task added Umbraco.Web.Scheduling.ScheduledTasks
2017-08-17 13:15:01,940 [P4824/D11/T60] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:01,940 [P4824/D11/T60] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Syncing from database...
2017-08-17 13:15:01,940 [P4824/D11/T60] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Complete (took 12ms)
2017-08-17 13:15:11,904 [P4824/D11/T56] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:12,007 [P4824/D11/T30] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:12,069 [P4824/D11/T61] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:12,413 [P4824/D11/T23] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:13,317 [P4824/D11/T15] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:15,133 [P4824/D11/T68] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:24,516 [P4824/D11/T15] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:24,532 [P4824/D11/T15] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Syncing from database...
2017-08-17 13:15:24,532 [P4824/D11/T15] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Complete (took 11ms)
2017-08-17 13:15:24,532 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Uri="[url redacted]"
2017-08-17 13:15:24,532 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Matches no domain
2017-08-17 13:15:24,532 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Culture="en-US"
2017-08-17 13:15:24,532 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContentAndTemplate: Path="[path redacted]"
2017-08-17 13:15:24,532 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: Begin finders
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - [route redacted]
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - Got content, id=39911
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: End finders, no document was found (took 7ms)
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandlePublishedContent: Begin
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - EnsurePublishedContentAccess: Page is not protected
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandlePublishedContent: End
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Look for template id=1191
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Got template id=1191 alias="Property"
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Running with template id=1191 alias="Property"
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandleWildcardDomains: Path="-1,1054,1194,39911"
2017-08-17 13:15:24,547 [P4824/D11/T15] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandleWildcardDomains: No match.
2017-08-17 13:15:24,563 [P4824/D11/T15] DEBUG Umbraco.Web.UmbracoModule - Response status: Redirect=none, Is404=false, StatusCode=0
2017-08-17 13:15:24,625 [P4824/D11/T15] DEBUG Umbraco.Web.UmbracoModule - Total milliseconds for umbraco request to process: 93.7463
2017-08-17 13:15:24,672 [P4824/D11/T56] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:24,844 [P4824/D11/T81] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:24,860 [P4824/D11/T65] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Task added Umbraco.Web.Strategies.ServerRegistrationEventHandler+TouchServerTask
2017-08-17 13:15:27,042 [P4824/D11/T30] DEBUG Umbraco.Web.Scheduling.ScheduledPublishing - Scheduled publishing executing @ [url redacted]
2017-08-17 13:15:27,542 [P4824/D11/T15] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:27,542 [P4824/D11/T58] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:30,562 [P4824/D11/T56] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:31,570 [P4824/D11/T68] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:31,570 [P4824/D11/T30] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:31,570 [P4824/D11/T68] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Syncing from database...
2017-08-17 13:15:31,586 [P4824/D11/T68] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Complete (took 10ms)
2017-08-17 13:15:44,659 [P4824/D11/T23] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:44,659 [P4824/D11/T23] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Syncing from database...
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Core.Sync.DatabaseServerMessenger - Complete (took 10ms)
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Uri="[url redacted]"
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Matches no domain
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindDomain: Culture="en-US"
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContentAndTemplate: Path="[path redacted]"
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: Begin finders
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - [route redacted]
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.ContentFinderByNiceUrl - Got content, id=39911
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindPublishedContent: End finders, no document was found (took 3ms)
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandlePublishedContent: Begin
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - EnsurePublishedContentAccess: Page is not protected
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandlePublishedContent: End
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Look for template id=1191
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Got template id=1191 alias="Property"
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - FindTemplate: Running with template id=1191 alias="Property"
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandleWildcardDomains: Path="-1,1054,1194,39911"
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.Routing.PublishedContentRequestEngine - HandleWildcardDomains: No match.
2017-08-17 13:15:44,674 [P4824/D11/T23] DEBUG Umbraco.Web.UmbracoModule - Response status: Redirect=none, Is404=false, StatusCode=0
2017-08-17 13:15:44,754 [P4824/D11/T23] DEBUG Umbraco.Web.UmbracoModule - Total milliseconds for umbraco request to process: 95.139
2017-08-17 13:15:47,585 [P4824/D11/T60] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:47,960 [P4824/D11/T30] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:48,006 [P4824/D11/T15] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:48,073 [P4824/D11/T56] DEBUG Umbraco.Web.UmbracoModule - Begin request: [url redacted]
2017-08-17 13:15:59,958 [P4824/D11/T60] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks executing
2017-08-17 13:15:59,958 [P4824/D11/T60] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks complete (took 0ms)
2017-08-17 13:15:59,958 [P4824/D11/T60] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Task added Umbraco.Web.Scheduling.ScheduledTasks
2017-08-17 13:16:24,966 [P4824/D11/T56] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Task added Umbraco.Web.Strategies.ServerRegistrationEventHandler+TouchServerTask
2017-08-17 13:16:59,968 [P4824/D11/T56] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks executing
2017-08-17 13:16:59,968 [P4824/D11/T56] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks complete (took 0ms)
2017-08-17 13:16:59,968 [P4824/D11/T56] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Task added Umbraco.Web.Scheduling.ScheduledTasks
2017-08-17 13:17:07,056 [P4824/D11/T15] ERROR Umbraco.Web.Scheduling.ScheduledPublishing - Failed (at "[url redacted]").
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Umbraco.Web.Scheduling.ScheduledPublishing.<PerformRunAsync>d__7.MoveNext()
2017-08-17 13:17:07,056 [P4824/D11/T15] DEBUG Umbraco.Web.Scheduling.ScheduledPublishing - Scheduled publishing complete (took 100027ms)
2017-08-17 13:17:07,056 [P4824/D11/T15] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Task added Umbraco.Web.Scheduling.ScheduledPublishing
2017-08-17 13:17:25,037 [P4824/D11/T56] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Task added Umbraco.Web.Strategies.ServerRegistrationEventHandler+TouchServerTask
2017-08-17 13:17:59,197 [P4824/D11/T15] DEBUG Umbraco.Web.Scheduling.KeepAlive - Keep alive executing
2017-08-17 13:17:59,973 [P4824/D11/T61] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks executing
2017-08-17 13:17:59,973 [P4824/D11/T61] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks complete (took 0ms)
2017-08-17 13:17:59,973 [P4824/D11/T61] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Task added Umbraco.Web.Scheduling.ScheduledTasks
2017-08-17 13:18:07,064 [P4824/D11/T23] DEBUG Umbraco.Web.Scheduling.ScheduledPublishing - Scheduled publishing executing @ [url redacted]
2017-08-17 13:18:25,077 [P4824/D11/T60] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Task added Umbraco.Web.Strategies.ServerRegistrationEventHandler+TouchServerTask
2017-08-17 13:18:59,982 [P4824/D11/T56] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks executing
2017-08-17 13:18:59,982 [P4824/D11/T56] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks complete (took 0ms)
2017-08-17 13:18:59,982 [P4824/D11/T56] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Task added Umbraco.Web.Scheduling.ScheduledTasks
2017-08-17 13:19:25,184 [P4824/D11/T60] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Task added Umbraco.Web.Strategies.ServerRegistrationEventHandler+TouchServerTask
2017-08-17 13:19:39,208 [P4824/D11/T65] ERROR Umbraco.Web.Scheduling.KeepAlive - Failed (at "[url redacted]").
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Umbraco.Web.Scheduling.KeepAlive.<PerformRunAsync>d__4.MoveNext()
2017-08-17 13:19:39,208 [P4824/D11/T65] DEBUG Umbraco.Web.Scheduling.KeepAlive - Keep alive complete (took 100016ms)
2017-08-17 13:19:39,208 [P4824/D11/T65] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [KeepAlive] Task added Umbraco.Web.Scheduling.KeepAlive
2017-08-17 13:19:47,085 [P4824/D11/T61] ERROR Umbraco.Web.Scheduling.ScheduledPublishing - Failed (at "[url redacted]").
System.Threading.Tasks.TaskCanceledException: A task was canceled.
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Umbraco.Web.Scheduling.ScheduledPublishing.<PerformRunAsync>d__7.MoveNext()
2017-08-17 13:19:47,085 [P4824/D11/T61] DEBUG Umbraco.Web.Scheduling.ScheduledPublishing - Scheduled publishing complete (took 100023ms)
2017-08-17 13:19:47,085 [P4824/D11/T61] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Task added Umbraco.Web.Scheduling.ScheduledPublishing
2017-08-17 13:19:59,992 [P4824/D11/T15] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks executing
2017-08-17 13:19:59,992 [P4824/D11/T15] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks complete (took 0ms)
2017-08-17 13:19:59,992 [P4824/D11/T15] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Task added Umbraco.Web.Scheduling.ScheduledTasks
2017-08-17 13:20:25,261 [P4824/D11/T60] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [Umbraco.Web.Scheduling.IBackgroundTask] Task added Umbraco.Web.Strategies.ServerRegistrationEventHandler+TouchServerTask
2017-08-17 13:20:47,105 [P4824/D11/T23] DEBUG Umbraco.Web.Scheduling.ScheduledPublishing - Scheduled publishing executing @ [url redacted]
2017-08-17 13:20:54,710 [P4824/D11/T75] DEBUG Umbraco.Web.Scheduling.ScheduledPublishing - Scheduled publishing complete (took 7608ms)
2017-08-17 13:20:54,710 [P4824/D11/T75] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledPublishing] Task added Umbraco.Web.Scheduling.ScheduledPublishing
2017-08-17 13:21:00,012 [P4824/D11/T23] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks executing
2017-08-17 13:21:00,012 [P4824/D11/T23] DEBUG Umbraco.Web.Scheduling.ScheduledTasks - Scheduled tasks complete (took 0ms)
2017-08-17 13:21:00,012 [P4824/D11/T23] DEBUG Umbraco.Web.Scheduling.BackgroundTaskRunner - [ScheduledTasks] Task added Umbraco.Web.Scheduling.ScheduledTasks
Upvotes: 1
Views: 687
Reputation: 4257
If it's hosted on an Azure App, it's likely to be an App Startup/App move. Unless your site is pretty well optimised, you can sometimes see a fairly slow startup times on Azure Apps, I've seen over 20 minutes on particularly poorly optimised sites.
The main culprit is file IO during app startup I think. Is the site quite large? Also does it have many custom Examine indexes?
There are some useful tips for improving performance on Azure here: https://cultiv.nl/blog/making-sure-your-umbraco-site-performs-on-azure/
Upvotes: 0