Sign in Register
Go to solution
Copied to clipboard

Flag this post as spam?

This post will be reported to the moderators as potential spam to be looked at


  • Murray Roke 503 posts 966 karma points c-trib
    May 14, 2013 @ 03:04
    Murray Roke
    0

    Sleeping on the job

    Hi all

    I have a site I've upgraded from umbraco 4.0.3 to 4.11.8 (I don't know if that's relevant)

    When I publish something it takes a very long time. (many minutes.)

    If I pause the process I see this call stack:

    mscorlib.dll!System.Threading.Thread.Sleep(int millisecondsTimeout) + 0x5 bytes    
Umbraco.Core.DLL!Umbraco.Core.Logging.AsynchronousRollingFileAppender.AppendLoggingEvents() + 0x94 bytes    
mscorlib.dll!System.Threading.Tasks.Task.InnerInvoke() + 0x27 bytes 
mscorlib.dll!System.Threading.Tasks.Task.Execute() + 0x43 bytes 
mscorlib.dll!System.Threading.Tasks.Task.ExecutionContextCallback(object obj) + 0x27 bytes  
mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool ignoreSyncCtx) + 0xb0 bytes    
mscorlib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal(ref System.Threading.Tasks.Task currentTaskSlot = Id = Cannot evaluate expression because the current thread is in a sleep, wait, or join, Status = Cannot evaluate expression because the current thread is in a sleep, wait, or join, Method = Cannot evaluate expression because the current thread is in a sleep, wait, or join) + 0x154 bytes  
mscorlib.dll!System.Threading.Tasks.Task.ExecuteEntry(bool bPreventDoubleExecution) + 0x8b bytes    
mscorlib.dll!System.Threading.Tasks.ThreadPoolTaskScheduler.LongRunningThreadWork(object obj) + 0x17 bytes  
mscorlib.dll!System.Threading.ThreadHelper.ThreadStart_Context(object state) + 0x93 bytes   
mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool ignoreSyncCtx) + 0xb0 bytes    
mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) + 0x2c bytes    
mscorlib.dll!System.Threading.ThreadHelper.ThreadStart(object obj) + 0x4e bytes
    or
       [In a sleep, wait, or join] 
>    mscorlib.dll!System.Threading.WaitHandle.WaitAny(System.Threading.WaitHandle[] waitHandles, int millisecondsTimeout, bool exitContext) + 0x8b bytes 
    System.dll!System.Net.TimerThread.ThreadProc() + 0x376 bytes    
    mscorlib.dll!System.Threading.ThreadHelper.ThreadStart_Context(object state) + 0x63 bytes   
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool ignoreSyncCtx) + 0xb0 bytes    
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) + 0x2c bytes    
    mscorlib.dll!System.Threading.ThreadHelper.ThreadStart() + 0x44 bytes   
    [Native to Managed Transition]  
    [Appdomain Transition]  
    [Native to Managed Transition]

    or

       [In a sleep, wait, or join] 
>    mscorlib.dll!System.Threading.Monitor.Enter(object obj, ref bool lockTaken) + 0x14 bytes    
    umbraco.DLL!umbraco.content.UpdateDocumentCache(umbraco.cms.businesslogic.web.Document d = {umbraco.cms.businesslogic.web.Document}) + 0x66 bytes   
    umbraco.DLL!umbraco.library.UpdateDocumentCache(umbraco.cms.businesslogic.web.Document doc) + 0x75 bytes    
    umbraco.DLL!umbraco.dialogs.publish.Page_Load(object sender, System.EventArgs e) + 0xa27 bytes  
    System.Web.RegularExpressions.dll!System.Web.Util.CalliHelper.EventArgFunctionCaller(System.IntPtr fp, object o, object t, System.EventArgs e) + 0xf bytes  
    System.Web.dll!System.Web.Util.CalliEventHandlerDelegateProxy.Callback(object sender, System.EventArgs e) + 0x24 bytes  
    System.Web.dll!System.Web.UI.Control.OnLoad(System.EventArgs e) + 0x5c bytes    
    businesslogic.DLL!umbraco.BasePages.BasePage.OnLoad(System.EventArgs e) + 0xf bytes 
    System.Web.dll!System.Web.UI.Control.LoadRecursive() + 0x4b bytes   
    System.Web.dll!System.Web.UI.Page.ProcessRequestMain(bool includeStagesBeforeAsyncPoint = true, bool includeStagesAfterAsyncPoint = true) + 0x8a0 bytes 
    System.Web.dll!System.Web.UI.Page.ProcessRequest(bool includeStagesBeforeAsyncPoint, bool includeStagesAfterAsyncPoint = true) + 0x8d bytes 
    System.Web.dll!System.Web.UI.Page.ProcessRequest() + 0x4f bytes 
    System.Web.dll!System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext context) + 0x16 bytes   
    System.Web.dll!System.Web.UI.Page.ProcessRequest(System.Web.HttpContext context) + 0x32 bytes   
    App_Web_publish.aspx.10695ae8.hrvalqhj.dll!ASP.umbraco_dialogs_publish_aspx.ProcessRequest(System.Web.HttpContext context = {System.Web.HttpContext}) + 0x33 bytes  C#
    System.Web.dll!System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() + 0x65 bytes 
    System.Web.dll!System.Web.HttpApplication.ExecuteStep(System.Web.HttpApplication.IExecutionStep step = {System.Web.HttpApplication.CallHandlerExecutionStep}, ref bool completedSynchronously = true) + 0x4c bytes  
    System.Web.dll!System.Web.HttpApplication.ApplicationStepManager.ResumeSteps(System.Exception error) + 0x13e bytes  
    System.Web.dll!System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext context, System.AsyncCallback cb, object extraData) + 0xf8 bytes  
    System.Web.dll!System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest wr = {Microsoft.VisualStudio.WebHost.Request}) + 0x1a2 bytes  
    System.Web.dll!System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest wr) + 0x7d bytes  
    System.Web.dll!System.Web.HttpRuntime.ProcessRequest(System.Web.HttpWorkerRequest wr) + 0x47 bytes  
    WebDev.WebHost40.dll!Microsoft.VisualStudio.WebHost.Request.Process() + 0x17b bytes 
    WebDev.WebHost40.dll!Microsoft.VisualStudio.WebHost.Host.ProcessRequest(Microsoft.VisualStudio.WebHost.Connection conn = {System.Runtime.Remoting.Proxies.__TransparentProxy}) + 0x6c bytes 
    [Appdomain Transition]  
    WebDev.WebHost40.dll!Microsoft.VisualStudio.WebHost.Server.OnSocketAccept(object acceptedSocket) + 0x83 bytes   
    mscorlib.dll!System.Threading.QueueUserWorkItemCallback.WaitCallback_Context(object state) + 0x2d bytes 
    mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool ignoreSyncCtx) + 0xb0 bytes    
    mscorlib.dll!System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem() + 0x5a bytes 
    mscorlib.dll!System.Threading.ThreadPoolWorkQueue.Dispatch() + 0x147 bytes  
    mscorlib.dll!System.Threading._ThreadPoolWaitCallback.PerformWaitCallback() + 0x2d bytes    
    [Native to Managed Transition]

    I'm not sure where to begin looking, I'm working on a custom examine indexer, which may be related or not... so I deleted all the Index and Search providers, and I get the same issue.

    Copy Link
  • Shannon Deminick 1526 posts 5272 karma points MVP 3x
    May 14, 2013 @ 03:33
    Shannon Deminick
    0

    The async logger runs on a dedicated thread, hence the thread sleep. It does not interact with any other thread so that is not your issue.

    Not sure what the 2nd one is but just looks to be .Net doing some stuff.

    The third one has more information about publishing.... but doesn't really tell us much.

    How are you publishing ? the 3rd trace shows: umbraco_dialogs_publish_aspx ... so are you publishing via the dialog? And what options are you choosing ? Does the process actually complete after a few minutes and anything show up in your logs that are alarming ?  Is it for every single page you try to publish, etc... 

    Copy Link
  • Shannon Deminick 1526 posts 5272 karma points MVP 3x
    May 14, 2013 @ 03:34
    Shannon Deminick
    0

    Also, how much data do you have in your install ? If you delete the indexes then Examine will rebuild them when it detects they don't exist... this can take a considerable amount of time to gather all of the data depending on how much data you have in your install.

    Copy Link
  • Murray Roke 503 posts 966 karma points c-trib
    May 14, 2013 @ 04:21
    Murray Roke
    0

    Oh yea, I tried publishing in various ways (from dialog. and unpublishing etc.)

    It seems to be the first publish (unpublish) that is really slow, then it's fast. untill I re-load the app (touch web.config etc)

    The Examine Indexes Folder is 93MB (the default External folder is  33MB, and the umbraco.config file is 28MB )

    I get the slow load for every page I've tried, I tried various doc types.

    If I delete logs, and examine indexes, and recycle the app pool, and check inside the fresh log I get the following (see below)

    I started the site, it built the index, the first publish took about 6 minutes.

    the second publish was very quick.

    I touched the web.config and published again it's now taking aages  (time=14:20 I assume it'll finish in 6 minutes)

     oh here's the log (not v. interetsing)

    2013-05-14 13:50:48,198 [5] INFO  Umbraco.Core.CoreBootManager - [Thread 1] Umbraco application starting
2013-05-14 13:50:48,214 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Determining hash of code files on disk
2013-05-14 13:50:48,217 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Hash determined (took 3ms)
2013-05-14 13:50:48,570 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter, found 0 (took 347ms)
2013-05-14 13:50:48,577 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Web.Mvc.SurfaceController, found 0 (took 4ms)
2013-05-14 13:50:48,586 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Media.IThumbnailProvider, found 3 (took 4ms)
2013-05-14 13:50:48,590 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Media.IImageUrlProvider, found 1 (took 4ms)
2013-05-14 13:50:48,597 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IApplicationStartupHandler, found 12 (took 4ms)
2013-05-14 13:50:48,618 [5] INFO  Umbraco.Core.CoreBootManager - [Thread 1] Umbraco application startup complete (took 417ms)
2013-05-14 13:50:50,668 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IDataType, found 42 (took 4ms)
2013-05-14 13:50:50,677 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.ITree, found 38 (took 4ms)
2013-05-14 13:55:05,707 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IApplication, found 7 (took 9ms)
2013-05-14 13:55:05,717 [5] INFO  Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.ITree, found 27 (took 5ms)
2013-05-14 13:55:08,138 [5] INFO  Umbraco.Core.PluginManager - [Thread 17] Completed resolution of types of umbraco.XsltExtensionAttribute, found 0 (took 20ms)
2013-05-14 13:55:18,552 [5] INFO  Umbraco.Core.PluginManager - [Thread 12] Completed resolution of types of umbraco.BusinessLogic.Actions.IActionHandler, found 1 (took 4ms)
2013-05-14 14:20:07,593 [5] INFO  Umbraco.Web.UmbracoApplication - [Thread 55] Application shutdown. Reason: ConfigurationChange
2013-05-14 14:20:09,375 [62] INFO  Umbraco.Core.CoreBootManager - [Thread 26] Umbraco application starting
2013-05-14 14:20:09,390 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Determining hash of code files on disk
2013-05-14 14:20:09,393 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Hash determined (took 3ms)
2013-05-14 14:20:09,749 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter, found 0 (took 350ms)
2013-05-14 14:20:09,755 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Completed resolution of types of Umbraco.Web.Mvc.SurfaceController, found 0 (took 4ms)
2013-05-14 14:20:09,761 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Completed resolution of types of Umbraco.Core.Media.IThumbnailProvider, found 3 (took 4ms)
2013-05-14 14:20:09,765 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Completed resolution of types of Umbraco.Core.Media.IImageUrlProvider, found 1 (took 3ms)
2013-05-14 14:20:09,771 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Completed resolution of types of umbraco.interfaces.IApplicationStartupHandler, found 12 (took 3ms)
2013-05-14 14:20:09,791 [62] INFO  Umbraco.Core.CoreBootManager - [Thread 26] Umbraco application startup complete (took 413ms)
2013-05-14 14:20:09,855 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Completed resolution of types of umbraco.interfaces.IApplication, found 7 (took 5ms)
2013-05-14 14:20:09,867 [62] INFO  Umbraco.Core.PluginManager - [Thread 26] Completed resolution of types of umbraco.interfaces.ITree, found 27 (took 4ms)
2013-05-14 14:20:12,082 [62] INFO  Umbraco.Core.PluginManager - [Thread 53] Completed resolution of types of umbraco.interfaces.IDataType, found 42 (took 4ms)
2013-05-14 14:20:12,089 [62] INFO  Umbraco.Core.PluginManager - [Thread 53] Completed resolution of types of umbraco.interfaces.ITree, found 38 (took 3ms)
2013-05-14 14:20:12,987 [62] INFO  Umbraco.Core.PluginManager - [Thread 53] Completed resolution of types of umbraco.BusinessLogic.Actions.IActionHandler, found 1 (took 9ms)
2013-05-14 14:20:30,198 [62] INFO  Umbraco.Core.PluginManager - [Thread 46] Completed resolution of types of umbraco.XsltExtensionAttribute, found 0 (took 18ms)
    Copy Link
  • Shannon Deminick 1526 posts 5272 karma points MVP 3x
    May 14, 2013 @ 04:31
    Shannon Deminick
    0

    Well, that is a extremely large amount of data :)

    Rebuilding indexes will take quite a while but if the indexes are missing during application startup the examine will try to rebuild them during startup (you can disable that in config though) http://our.umbraco.org/documentation/Reference/Searching/Examine/full-configuration "RebuildOnAppStartup". Once the indexes are there though, Examine just re-indexes the individual nodes and indexing is run async (unless you've disabled that) so you wouldn't really be waiting for that anyways.

    It does seem real strange though and I don't really think it's an Examine issue since your indexes are building no problem. Might be best to get the source and debug at the methods:

            [In a sleep, wait,or join]     
    >       mscorlib.dll!System.Threading.Monitor.Enter(object obj,refbool lockTaken)+0x14 bytes        
            umbraco    .DLL!umbraco.content.UpdateDocumentCache(umbraco.cms.businesslogic.web.Document d ={umbraco.cms.businesslogic.web.Document})+0x66 bytes       
            umbraco    .DLL!umbraco.library.UpdateDocumentCache(umbraco.cms.businesslogic.web.Document doc)+0x75 bytes

    Also, I think you forgot to post the info from your log.


    Copy Link
  • Shannon Deminick 1526 posts 5272 karma points MVP 3x
    May 14, 2013 @ 04:32
    Shannon Deminick
    0

    Doh... sorry now the log info shows up :) 

    Copy Link
  • Murray Roke 503 posts 966 karma points c-trib
    May 14, 2013 @ 04:35
    Murray Roke
    0

    Yea, I'm guessing it's not examine, cos as I mentioned, I tried deleting all the Index and Search providers, and I get the same issue

    Copy Link
  • Tom Fulton 2030 posts 4998 karma points c-trib
    May 14, 2013 @ 21:31
    Tom Fulton
    100

    I've seen a similar issue in 6.1 - the first publish takes forever, but subsequent publishes are super speedy.  My times aren't quite as bad as Murray's (about 10 seconds), but still definitely noticable.

    I just ran a test in order to check out my log file, and I noticed a bunch of SitemapProvider errors on nodes that I wasn't publishing.  So I tried commenting out the <siteMap> section of the web.config, and now the first publish is super speedy again!  Murray, want to give that a shot?

    -Tom

    Copy Link
  • Murray Roke 503 posts 966 karma points c-trib
    May 15, 2013 @ 05:34
    Murray Roke
    0

    Wow, yep, that sorted that out. super crazy! (NB: internalIndexer counts 8628 documents)

    Copy Link
  • Shannon Deminick 1526 posts 5272 karma points MVP 3x
    May 15, 2013 @ 06:07
    Shannon Deminick
    0

    Nice! So its the sitemap provider. This was always enabled (or should have been) previous to 4.11.8... Maybe something has changed to actually make it work now :) TBH I've never used a sitemap provider for anything, it's probably worth investigating how it is currently implemented and who uses it. I can assume that it might not be working the way a sitemap provider was intended to work.

    Copy Link
  • Murray Roke 503 posts 966 karma points c-trib
    May 16, 2013 @ 02:24
    Murray Roke
    0

    We weren't using it.

    The web config for it was the same in 4.03 before we upgraded so... perhaps it did start working in some version albiet very slowly

    Copy Link
Please Sign in or register to post replies

Write your reply to:

Draft