having Umbraco 6.0.7 running on our production server, we are experiencing very slow startup times when recycling the application pool. While the Umbraco backend is available (but very slow) just after startup, it takes up to 5 minutes or even longer before the frontend web site is available. The startup log looks like that:
2015-06-08 22:26:42,646 [7] INFO Umbraco.Core.CoreBootManager - [Thread 1] Umbraco application starting 2015-06-08 22:26:42,659 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Determining hash of code files on disk 2015-06-08 22:26:42,665 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Hash determined (took 7ms) 2015-06-08 22:26:42,900 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IApplicationStartupHandler, found 31 (took 229ms) 2015-06-08 22:26:42,915 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Models.IMacroPropertyType, found 0 (took 6ms) 2015-06-08 22:26:42,924 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter, found 0 (took 8ms) 2015-06-08 22:26:42,932 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Web.Mvc.SurfaceController, found 1 (took 7ms) 2015-06-08 22:26:42,944 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Media.IThumbnailProvider, found 3 (took 10ms) 2015-06-08 22:26:42,954 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Media.IImageUrlProvider, found 1 (took 9ms) 2015-06-08 22:26:42,998 [7] INFO Umbraco.Core.CoreBootManager - [Thread 1] Umbraco application startup complete (took 352ms) 2015-06-08 22:26:43,189 [7] INFO XDataService - [Thread 1] Indexing RedsysFilm 2015-06-08 22:26:50,961 [7] INFO XDataService - [Thread 1] Indexing RedsysReihe 2015-06-08 22:26:52,720 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IApplication, found 7 (took 17ms) 2015-06-08 22:26:52,809 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.ITree, found 27 (took 72ms) 2015-06-08 22:26:52,822 [7] INFO umbraco.BusinessLogic.Log - [Thread 13] Redirected log call (please use Umbraco.Core.Logging.LogHelper instead of umbraco.BusinessLogic.Log) | Type: Custom | User: 0 | NodeId: -1 | Comment: [UmbracoExamine] Adding examine event handlers for index providers: 6 2015-06-08 22:26:53,579 [7] INFO umbraco.content - [Thread 13] Loading content from disk cache... 2015-06-08 22:26:54,193 [7] INFO Umbraco.Core.PluginManager - [Thread 13] Completed resolution of types of umbraco.interfaces.IDataType, found 81 (took 104ms) 2015-06-08 22:26:54,270 [7] INFO Umbraco.Core.PluginManager - [Thread 13] Completed resolution of types of umbraco.interfaces.ITree, found 50 (took 71ms) 2015-06-08 22:27:23,733 [7] WARN Umbraco.Web.Routing.NiceUrlProvider - [Thread 27] Couldn't find any page with nodeId=2740. This is most likely caused by the page not being published. 2015-06-08 22:27:23,734 [7] WARN Umbraco.Web.Routing.NiceUrlProvider - [Thread 27] Couldn't find any page with nodeId=2740. This is most likely caused by the page not being published. 2015-06-08 22:27:23,734 [7] WARN Umbraco.Web.Routing.NiceUrlProvider - [Thread 27] Couldn't find any page with nodeId=2740. This is most likely caused by the page not being published. 2015-06-08 22:27:23,734 [7] WARN Umbraco.Web.Routing.NiceUrlProvider - [Thread 27] Couldn't find any page with nodeId=2740. This is most likely caused by the page not being published. 2015-06-08 22:29:34,426 [7] INFO umbraco.BasePages.BasePage - [Thread 25] User X (Id: 0) logged in 2015-06-08 22:29:34,621 [7] INFO Umbraco.Core.PluginManager - [Thread 34] Completed resolution of types of umbraco.BusinessLogic.Actions.IActionHandler, found 1 (took 8ms) 2015-06-08 22:36:23,778 [7] INFO umbraco.BasePages.BasePage - [Thread 31] User Y (Id: 2) logged in
Sometimes even OutOfMemoryExceptions are thrown shortly after an application pool recycle, while memory consumption is quite normal at other times:
2015-06-08 21:37:47,297 [7] INFO Umbraco.Core.CoreBootManager - [Thread 1] Umbraco application starting 2015-06-08 21:37:47,310 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Determining hash of code files on disk 2015-06-08 21:37:47,318 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Hash determined (took 7ms) 2015-06-08 21:37:47,541 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IApplicationStartupHandler, found 31 (took 217ms) 2015-06-08 21:37:47,555 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Models.IMacroPropertyType, found 0 (took 5ms) 2015-06-08 21:37:47,563 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter, found 0 (took 7ms) 2015-06-08 21:37:47,571 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Web.Mvc.SurfaceController, found 1 (took 7ms) 2015-06-08 21:37:47,583 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Media.IThumbnailProvider, found 3 (took 9ms) 2015-06-08 21:37:47,593 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Media.IImageUrlProvider, found 1 (took 9ms) 2015-06-08 21:37:47,636 [7] INFO Umbraco.Core.CoreBootManager - [Thread 1] Umbraco application startup complete (took 338ms) 2015-06-08 21:37:47,791 [7] INFO XDataService - [Thread 1] Indexing RedsysFilm 2015-06-08 21:37:55,689 [7] INFO XDataService - [Thread 1] Indexing RedsysReihe 2015-06-08 21:37:57,382 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IApplication, found 7 (took 17ms) 2015-06-08 21:37:57,471 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.ITree, found 27 (took 72ms) 2015-06-08 21:37:57,481 [7] INFO umbraco.BusinessLogic.Log - [Thread 14] Redirected log call (please use Umbraco.Core.Logging.LogHelper instead of umbraco.BusinessLogic.Log) | Type: Custom | User: 0 | NodeId: -1 | Comment: [UmbracoExamine] Adding examine event handlers for index providers: 6 2015-06-08 21:37:57,984 [7] INFO umbraco.content - [Thread 12] Loading content from disk cache... 2015-06-08 21:38:18,422 [7] INFO umbraco.BasePages.BasePage - [Thread 34] User X (Id: 0) logged in 2015-06-08 22:07:43,879 [7] ERROR Umbraco.Core.UmbracoApplicationBase - [Thread 975] An unhandled exception occurred System.OutOfMemoryException: Eine Ausnahme vom Typ "System.OutOfMemoryException" wurde ausgelöst. bei System.Reflection.Emit.ILGenerator.BakeByteArray() bei System.Reflection.Emit.DynamicResolver..ctor(DynamicILGenerator ilGenerator) bei System.Reflection.Emit.DynamicILGenerator.GetCallableMethod(RuntimeModule module, DynamicMethod dm) bei System.Reflection.Emit.DynamicMethod.GetMethodDescriptor() bei System.Reflection.Emit.DynamicMethod.CreateDelegate(Type delegateType) bei System.Text.RegularExpressions.CompiledRegexRunnerFactory.CreateInstance() bei System.Text.RegularExpressions.Regex.Run(Boolean quick, Int32 prevlen, String input, Int32 beginning, Int32 length, Int32 startat) bei System.Text.RegularExpressions.Regex.IsMatch(String input, Int32 startat) bei System.Text.RegularExpressions.Regex.IsMatch(String input) bei UrlRewritingNet.Web.RegExRewriteRule.IsRewrite(String requestUrl) bei UrlRewritingNet.Web.UrlRewriteModule.RedirectUrl(HttpApplication app) bei UrlRewritingNet.Web.UrlRewriteModule.OnBeginRequest(Object sender, EventArgs e) bei System.Web.HttpApplication.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() bei System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
The web server process then consumes more than 2 GB of memory and the web site is not responding anymore.
Is there anyone having a hint for us where to look for the reasons for the above?
thanks for your reply. There are 6.000 published nodes out of 10.000 in total. Debug is turned off.
It seems that the startup is slow/stuck in times of high traffic, when there are lots of visitors. In case the app pool hangs, the log ends with the message "Loading content from disk cache...":
2015-06-11 05:01:29,943 [7] INFO Umbraco.Core.CoreBootManager - [Thread 1] Umbraco application starting
2015-06-11 05:01:29,957 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Determining hash of code files on disk
2015-06-11 05:01:29,965 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Hash determined (took 7ms)
2015-06-11 05:01:30,187 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IApplicationStartupHandler, found 31 (took 216ms)
2015-06-11 05:01:30,202 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Models.IMacroPropertyType, found 0 (took 5ms)
2015-06-11 05:01:30,209 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.PropertyEditors.IPropertyEditorValueConverter, found 0 (took 7ms)
2015-06-11 05:01:30,217 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Web.Mvc.SurfaceController, found 1 (took 7ms)
2015-06-11 05:01:30,228 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Media.IThumbnailProvider, found 3 (took 9ms)
2015-06-11 05:01:30,238 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of Umbraco.Core.Media.IImageUrlProvider, found 1 (took 9ms)
2015-06-11 05:01:30,280 [7] INFO Umbraco.Core.CoreBootManager - [Thread 1] Umbraco application startup complete (took 336ms)
2015-06-11 05:01:30,432 [7] INFO FilmDataService - [Thread 1] Indexing RedsysFilm
2015-06-11 05:01:37,777 [7] INFO ReiheDataService - [Thread 1] Indexing RedsysReihe
2015-06-11 05:01:39,592 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.IApplication, found 7 (took 22ms)
2015-06-11 05:01:39,684 [7] INFO Umbraco.Core.PluginManager - [Thread 1] Completed resolution of types of umbraco.interfaces.ITree, found 27 (took 74ms)
2015-06-11 05:01:39,693 [7] INFO umbraco.BusinessLogic.Log - [Thread 10] Redirected log call (please use Umbraco.Core.Logging.LogHelper instead of umbraco.BusinessLogic.Log) | Type: Custom | User: 0 | NodeId: -1 | Comment: [UmbracoExamine] Adding examine event handlers for index providers: 6
2015-06-11 05:01:40,282 [7] INFO umbraco.content - [Thread 10] Loading content from disk cache...
When we're lucky and the app pool starts normally, the log continues with the following messages:
2015-06-11 05:01:40,975 [7] INFO Umbraco.Core.PluginManager - [Thread 10] Completed resolution of types of umbraco.interfaces.IDataType, found 81 (took 114ms)
2015-06-11 05:01:41,062 [7] INFO Umbraco.Core.PluginManager - [Thread 10] Completed resolution of types of umbraco.interfaces.ITree, found 50 (took 81ms)
On a test server we didn't have any problems like that so far. So maybe it has something to do with incoming requests while Umbraco is starting up?
We are experiencing the exact same symptoms on the high traffic/lots of content sites we have. I must admit that we have just accepted it as a fact of life :(
My understanding of the XmlCacheEnabled setting is that it disabled any caching, and goes directly the database.
We have XmlCacheEnabled = false in development, as the developers share the same database. This avoids re-publishing of nodes that other developers have edited, to update the umbraco.config xml cache.
It makes sense turn off XmlCache if you will make great performance fixes in your code, and if you have great server with perfect connection between app and sql server.
We've checked the XmlCache settings on our test server and it helped reducing the server response time as well as memory usage. Instead of 2 GB the web server process consumed just 300-500 MB while running the exact same test procedure. So thanks a lot for that suggestion, Alex! =)
We've discovered another issue with the home page, regardless of the XmlCache setting being enabled or disabled: When calling the extension method IPublishedContent.Descendants(String), the call takes about 1 second with IPublishedContent being the root node of the website. The same call takes only 100ms when IPublishedContent is any of the root's sub-nodes. We've replaced that call, so that's no problem anymore.
Regarding the hangs on app pool start-up: It might be related to an exception that is silently thrown in an ISimpleDataService, but we are not sure about that yet. We'll have to update the production server and have a look at that issue again.
Slow load time with 6.0.7
Hi,
having Umbraco 6.0.7 running on our production server, we are experiencing very slow startup times when recycling the application pool. While the Umbraco backend is available (but very slow) just after startup, it takes up to 5 minutes or even longer before the frontend web site is available. The startup log looks like that:
Sometimes even OutOfMemoryExceptions are thrown shortly after an application pool recycle, while memory consumption is quite normal at other times:
The web server process then consumes more than 2 GB of memory and the web site is not responding anymore.
Is there anyone having a hint for us where to look for the reasons for the above?
Regards,
Maurice
hi Maurice,
How many nodes do you have ?
Did you turn off debug ?
Did you use miniprofiler?
Thanks,
Alex
Hi Alex,
thanks for your reply. There are 6.000 published nodes out of 10.000 in total. Debug is turned off. It seems that the startup is slow/stuck in times of high traffic, when there are lots of visitors. In case the app pool hangs, the log ends with the message "Loading content from disk cache...":
When we're lucky and the app pool starts normally, the log continues with the following messages:
On a test server we didn't have any problems like that so far. So maybe it has something to do with incoming requests while Umbraco is starting up?
Regards, Maurice
We are experiencing the exact same symptoms on the high traffic/lots of content sites we have. I must admit that we have just accepted it as a fact of life :(
Best regards Emil
You can turn off XmlCacheEnabled, and use memory cache more and more, it can solve loading content from the disk cache.
I think disk cache isn't perfect for large sites.
Thanks,
Alex
Thanks Alex,
that sounds promising. However, on https://our.umbraco.org/documentation/Using-Umbraco/Config-files/umbracoSettings/ they say the following:
On https://groups.google.com/forum/#!msg/umbraco-dev/Spw1bDYhuEo/LOYZ2zYnkMUJ however it reads:
So we'll try your suggestion on our test server and will let you know the results.
Kind regards, Maurice
My understanding of the XmlCacheEnabled setting is that it disabled any caching, and goes directly the database.
We have XmlCacheEnabled = false in development, as the developers share the same database. This avoids re-publishing of nodes that other developers have edited, to update the umbraco.config xml cache.
Best regards Emil
It makes sense turn off XmlCache if you will make great performance fixes in your code, and if you have great server with perfect connection between app and sql server.
Thanks, Alex
We've checked the XmlCache settings on our test server and it helped reducing the server response time as well as memory usage. Instead of 2 GB the web server process consumed just 300-500 MB while running the exact same test procedure. So thanks a lot for that suggestion, Alex! =)
We've discovered another issue with the home page, regardless of the XmlCache setting being enabled or disabled: When calling the extension method IPublishedContent.Descendants(String), the call takes about 1 second with IPublishedContent being the root node of the website. The same call takes only 100ms when IPublishedContent is any of the root's sub-nodes. We've replaced that call, so that's no problem anymore.
Regarding the hangs on app pool start-up: It might be related to an exception that is silently thrown in an ISimpleDataService, but we are not sure about that yet. We'll have to update the production server and have a look at that issue again.
Hi Maurice,
I'm glad that our advice helped you, also can you avoid IPublishedContent.Descendants(String) method? It's really heavy.
Thanks
is working on a reply...