I realize this is an older Umbraco installation (4.0.4.2) and that a short answer is "just upgrade" but this installation has been highly customized by more than 6 outside contractors over a period of two years. Upgrading is a long process and is in progress. I'm actually almost done upgrading and launching a new production server with a newer version. However, there are many other things to do in my job role and I am just a one man team in my position. That being said, I still feel obligated to do my due dilligence in trying to get an answer to this problem (described below) as my company uses the behaviour I will describe as an excuse to ditch the whole CMS (which will just make even more work for me). 

Umbraco intermittently hangs for up to 40 minutes at a time. Recycling the application pool does not help. I am not an IIS expert and so it has been difficult for me to diagnose the problem. I only got as far as setting up performance counters to monitor "Current Anonymous Users" under "Web Service" Performance Monitor. During this hanging condition, the Current Anonymous Users would always climb up into the hundreds or thousands and never drop down (often to zero) like it normally does. 

I spent months combing through the logs trying to figure out if maybe it was related to bad content (embedded scripts, or remote calls) or heavy traffic/load, I always found something to fix and improve, but it never fixed the root problem. Every few weeks or so, the site would hang for up to 40 minutes. This website is mission critical according to the departments that use it (i.e. news reporters). 

Finally I contacted Microsoft Support. They had me take memory dumps and submit log files during these hang times. So, I submitted this information and after their analysis they suggested asking the development team the following: 

 

* Let’s check with development team of umbraco.macro.renderMacro and see why it’s not releasing the lock properly.

 

They are referring to this method:

public System.Web.UI.Control renderMacro(System.Collections.Hashtable attributes, System.Collections.Hashtable pageElements, int pageId)

 

Here are their other comments:

 

-- The following threads in w3wp.exe__UCPRAppPool__PID__2900__Date__05_07_2013__Time_03_38_42PM__150__Manual Dump.dmp are waiting to enter a .NET Lock which thread 47 is currently holding

 

-- 50.57% of threads blocked

 -- Checking thread 47

 

...

 

-- So this thread is holding a lock and rest of the threads are waiting for lock. This is just a portion of issue. Issue is multifold. There are 2647 requests are in queue. This is a four process box and I think request load is too high. Checking the Garbage Collection:

 

 

-- Notice the Gen 2 finailizable objects in Gen 2 . This is not good and it will hit performance. Please check the http://msdn.microsoft.com/en-us/library/ms973837.aspx for more info. 

 

So, it would be great if somone on the development team could AT LEAST acknowledge this post. It represents the culmination of a lot of searching and anaylsis (and the 250 bucks to Microsoft to perform there analysis).

Here is thir analysis in its entirety. I'm trying to research the other references they have made. They asked specifically however, to submit a question to the Umbraco Dev team regarding the umbraco.macro.renderMacro why it’s not releasing the lock properly.

Thanks. 

.....

 

 

Hi Jacob,

 

-- Checking the dumps:

w3wp.exe__UCPRAppPool__PID__2900__Date__05_07_2013__Time_03_36_58PM__478__Manual Dump

w3wp.exe__UCPRAppPool__PID__2900__Date__05_07_2013__Time_03_38_20PM__197__Manual Dump

w3wp.exe__UCPRAppPool__PID__2900__Date__05_07_2013__Time_03_38_42PM__150__Manual Dump

w3wp.exe__UCPRAppPool__PID__2900__Date__05_07_2013__Time_03_40_07PM__697__Manual Dump

w3wp.exe__UCPRAppPool__PID__2900__Date__05_07_2013__Time_03_36_58PM__ProcessList.txt

 

-- There are a few long running requests:

 

0x42a365c4     7200 Sec        no       269 Sec      61        200   GET /articles/2013/05/07/missing-yosemite-hiker-found-dead

0x42b1cc08     7200 Sec        no       254 Sec      75        200   GET /articles/2013/05/07/missing-yosemite-hiker-found-dead

0x42d180b8     7200 Sec        no        68 Sec     XXX        200   GET /images/listenlive_button.png

0x42d1f034     7200 Sec        no        67 Sec      25        200   GET /articles/2013/05/07/missing-yosemite-hiker-found-dead

0x42d3bee4     7200 Sec        no        67 Sec      35        200   GET /articles/2013/05/07/missing-yosemite-hiker-found-dead

0x42d661d8     7200 Sec        no        62 Sec      32        200   GET /articles/2013/05/07/missing-yosemite-hiker-found-dead

0x42da0ca0     7200 Sec        no        62 Sec      21        200   GET /articles/2013/05/07/missing-yosemite-hiker-found-dead

0x42e8522c     7200 Sec        no        57 Sec      56        200   GET /articles/2013/05/07/missing-yosemite-hiker-found-dead

 

--To be noted:

ASP.NET Request Queue Report

 

AppDomain External Queue Local Queue

/LM/W3SVC/109769922/Root 2647

 

-- It is a four process box and auto config is true

:063> !dtc

0x00000000 is not a RequestQueue object

autoConfig is true

 

Number of Processors: 4  (multiplied by number to get total value).

MaxWorkerThreads: 100 (400)

MaxIoThreads: 100 (400)

minFreeThreads: 88 (352)

minLocalRequestFreeThreads: 76 (304)

maxConnection: 12 (48)

 

-- The following threads in w3wp.exe__UCPRAppPool__PID__2900__Date__05_07_2013__Time_03_38_42PM__150__Manual Dump.dmp are waiting to enter a .NET Lock which thread 47 is currently holding

 

 

( 14 21 24 25 28 32 33 34 35 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 )

 

 

50.57% of threads blocked

 

-- Checking thread 47

 

ChildEBP RetAddr 

4662d7d4 65b89264 System_Xml_ni!System.Xml.DocumentXPathNavigator.get_NodeType()

4662d7d4 65b890bf System_Data_SqlXml_ni!System.Xml.Xsl.Runtime.XmlNavNeverFilter.MoveToNextAttributeContent(System.Xml.XPath.XPathNavigator)+0x10

4662d7e0 301b0b82 System_Data_SqlXml_ni!System.Xml.Xsl.Runtime.AttributeContentIterator.MoveNext()+0x2f

4662e774 3004b510 0x301b0b82

4662e8a4 3004b15e 0x3004b510

4662e8e0 302bf896 0x3004b15e

4662e8ec 65b58161 0x302bf896

4662e904 65b581f2 System_Data_SqlXml_ni!System.Xml.Xsl.XmlILCommand.Execute(System.Object, System.Xml.XmlResolver, System.Xml.Xsl.XsltArgumentList, System.Xml.Xsl.Runtime.XmlSequenceWriter)+0x59

4662e938 65b5846c System_Data_SqlXml_ni!System.Xml.Xsl.XmlILCommand.Execute(System.Object, System.Xml.XmlResolver, System.Xml.Xsl.XsltArgumentList, System.Xml.XmlWriter, Boolean)+0x7a

4662e958 65b5842b System_Data_SqlXml_ni!System.Xml.Xsl.XmlILCommand.Execute(System.Xml.XPath.IXPathNavigable, System.Xml.XmlResolver, System.Xml.Xsl.XsltArgumentList, System.Xml.XmlWriter)+0x30

4662e974 63b08941 System_Data_SqlXml_ni!System.Xml.Xsl.XmlILCommand.Execute(System.Xml.XPath.IXPathNavigable, System.Xml.XmlResolver, System.Xml.Xsl.XsltArgumentList, System.IO.TextWriter)+0x2f

4662e990 212db305 System_Xml_ni!System.Xml.Xsl.XslCompiledTransform.Transform(System.Xml.XPath.IXPathNavigable, System.Xml.Xsl.XsltArgumentList, System.IO.TextWriter)+0x35

4662ea78 212dafbe umbraco!umbraco.macro.GetXsltTransformResult(System.Xml.XmlDocument, System.Xml.Xsl.XslCompiledTransform, System.Collections.Generic.Dictionary`2)+0x31d

4662ea94 212d7e1e umbraco!umbraco.macro.GetXsltTransformResult(System.Xml.XmlDocument, System.Xml.Xsl.XslCompiledTransform)+0x2e

4662ec5c 212d6b5a umbraco!umbraco.macro.loadMacroXSLT(umbraco.macro, System.Collections.Hashtable, System.Collections.Hashtable)+0x6a6

4662ef3c 212d2a95 umbraco!umbraco.macro.renderMacro(System.Collections.Hashtable, System.Collections.Hashtable, Int32)+0xc42

4662f064 660af258 umbraco!umbraco.presentation.templateControls.Macro.CreateChildControls()+0x43d

4662f090 212d2332 System_Web_ni!System.Web.UI.Control.EnsureChildControls()+0x58

4662f0a0 660add5e umbraco!umbraco.presentation.templateControls.Macro.OnInit(System.EventArgs)+0x32

4662f0c0 660adce3 System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0x14e

4662f0e0 660adce3 System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0xd3

4662f100 660adce3 System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0xd3

4662f120 660adce3 System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0xd3

4662f140 660adce3 System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0xd3

4662f160 660adce3 System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0xd3

4662f180 660adce3 System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0xd3

4662f1a0 660adce3 System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0xd3

4662f1c0 660aa1bb System_Web_ni!System.Web.UI.Control.InitRecursive(System.Web.UI.Control)+0xd3

4662f314 660a9ee4 System_Web_ni!System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)+0x17b

4662f34c 660a9e11 System_Web_ni!System.Web.UI.Page.ProcessRequest(Boolean, Boolean)+0x84

4662f388 660a9da6 System_Web_ni!System.Web.UI.Page.ProcessRequest()+0x51

4662f394 660a9d82 System_Web_ni!System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)+0x16

4662f3a8 2024ab45 System_Web_ni!System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)+0x32

4662f3e0 660b0256 App_Web_mi1zmjh8!ASP.default_aspx.ProcessRequest(System.Web.HttpContext)+0x5

4662f3e0 6608332c System_Web_ni!System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()+0xb6

4662f41c 6608eb83 System_Web_ni!System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)+0x4c

4662f470 660828ac System_Web_ni!System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)+0x133

4662f484 66085e1c System_Web_ni!System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)+0x7c

4662f4c0 6668bc23 System_Web_ni!System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)+0x17c

4662f4d8 792ca09f System_Web_ni!System.Web.RequestQueue.WorkItemCallback(System.Object)+0x93

4662f4f0 792f58d1 mscorlib_ni!System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)+0x2f

4662f4f0 79e71b4c mscorlib_ni!System.Threading.ExecutionContext.runTryCode(System.Object)+0x51

4662f500 79e8908a mscorwks!CallDescrWorker+0x33

4662f580 79e965b9 mscorwks!CallDescrWorkerWithHandler+0xa3

4662f6b8 79e965ec mscorwks!MethodDesc::CallDescr+0x19c

4662f6d4 79e9660a mscorwks!MethodDesc::CallTargetWorker+0x1f

4662f6ec 79f1ae3f mscorwks!MethodDescCallSite::Call+0x1a

4662f8b8 79f1af96 mscorwks!ExecuteCodeWithGuaranteedCleanupHelper+0x9f

4662f968 792f57c7 mscorwks!ReflectionInvocation::ExecuteCodeWithGuaranteedCleanup+0x10f

4662f984 792e0415 mscorlib_ni!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x67

4662f99c 792ca603 mscorlib_ni!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)+0x45

4662f9b4 792ca499 mscorlib_ni!System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback)+0x53

4662f9cc 79e71b4c mscorlib_ni!System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)+0x59

4662f9dc 79e8908a mscorwks!CallDescrWorker+0x33

4662fa5c 79e8988b mscorwks!CallDescrWorkerWithHandler+0xa3

4662fa7c 79e898cc mscorwks!DispatchCallBody+0x1e

4662fae0 79e89939 mscorwks!DispatchCallDebuggerWrapper+0x3d

4662fb14 79fba7dd mscorwks!DispatchCallNoEH+0x51

4662fb70 79ec1457 mscorwks!QueueUserWorkItemManagedCallback+0x59

4662fb84 79ec13f3 mscorwks!ManagedThreadBase_DispatchInner+0x4f

4662fc18 79ec1313 mscorwks!ManagedThreadBase_DispatchMiddle+0xb1

4662fc54 79ec1b5e mscorwks!ManagedThreadBase_DispatchOuter+0x6d

4662fc64 79ec2aed mscorwks!ManagedThreadBase_DispatchInCorrectAD+0x14

4662fd14 79ec1b7f mscorwks!Thread::DoADCallBack+0xda

4662fd30 79ec13f3 mscorwks!ManagedThreadBase_DispatchInner+0x35

4662fdc4 79ec1313 mscorwks!ManagedThreadBase_DispatchMiddle+0xb1

4662fe00 79ec14a5 mscorwks!ManagedThreadBase_DispatchOuter+0x6d

4662fe28 79ec22c0 mscorwks!ManagedThreadBase_FullTransitionWithAD+0x25

4662fe40 79fba472 mscorwks!ManagedThreadBase::ThreadPool+0x13

4662fea8 79ec1f5a mscorwks!ManagedPerAppDomainTPCount::DispatchWorkItem+0xe9

4662febc 79ec20ce mscorwks!ThreadpoolMgr::ExecuteWorkRequest+0xaf

4662ff14 79fcb469 mscorwks!ThreadpoolMgr::WorkerThreadStart+0x20b

4662ffb8 77e6481f mscorwks!Thread::intermediateThreadProc+0x49

4662ffec 00000000 kernel32!BaseThreadStart+0x34

 

-- Checking umbraco!umbraco.macro.renderMacro

 

public System.Web.UI.Control renderMacro(System.Collections.Hashtable attributes, System.Collections.Hashtable pageElements, int pageId)

  {

    System.Web.HttpContext.Current.Trace.Write("renderMacro", string.Format("Rendering started (macro: {0}, type: {1}, cacheRate: {2})", this.Name, this.MacroType, this.RefreshRate));

    umbraco.BusinessLogic.StateHelper.SetContextValue(this.macrosAddedKey, (umbraco.BusinessLogic.StateHelper.GetContextValue(this.macrosAddedKey) + 1));

    System.Web.UI.Control control1 = null;

    umbraco.MacroCacheContent content1 = null;

    object object1 = null;

    string string1 = this.getCacheGuid(attributes, pageElements, pageId);

    string string2 = string.Concat("macroHtml_", string1);

    bool boolean1 = (this.RefreshRate <= 0);

    if (!boolean1)

    {

      content1 = (this.macroCache[string2] as umbraco.MacroCacheContent);

      boolean1 = (content1 == null);

      if (!boolean1)

      {

        control1 = content1.Content;

        control1.ID = content1.ID;

        string string3 = (System.Web.UI.LiteralControl)content1.Content.Controls[0].Text;

        System.Web.HttpContext.Current.Trace.Write("renderMacro", string.Concat("Content loaded from cache ('", string1, "')..."));

      }

    }

    boolean1 = (control1 != null);

    if (!boolean1)

    {

      boolean1 = !umbraco.macro.MacroRenderDict.ContainsKey(string2);

      if (boolean1) goto lab1;

      object object2;

      if (!boolean1)

      {

        object1 = umbraco.macro.MacroRenderDict[string2];

      }

      else

      {

      lab1:

        System.Threading.Monitor.Enter((object2 = umbraco.macro._lockMacroRenderDict));

        try

        {

          boolean1 = umbraco.macro.MacroRenderDict.ContainsKey(string2);

          if (!boolean1)

          {

            object1 = new object();

            umbraco.macro.MacroRenderDict.Add(string2, object1);

          }

        }

        finally

        {

          System.Threading.Monitor.Exit(object2);

        }

      }

      System.DateTime time1 = System.DateTime.Now;

      System.Threading.Monitor.Enter((object2 = object1));

      try

      {

        System.DateTime time2 = System.DateTime.Now;

        content1 = (this.macroCache[string2] as umbraco.MacroCacheContent);

        boolean1 = (content1 == null);

        if (boolean1) goto lab2;

        if (!boolean1)

        {

          control1 = content1.Content;

          control1.ID = content1.ID;

          System.Web.HttpContext.Current.Trace.Write("renderMacro", string.Format(string.Concat("Content loaded from cache ('", string1, "') after waiting {0} ms"), (time2 - time1).TotalMilliseconds));

        }

        else

        {

        lab2:

          switch ((this.MacroType - 1))

          {

            case 0: goto lab3;

            case 1: goto lab4;

            case 2: goto lab5;

            case 3: goto lab6;

            case 4: goto lab7;

          }

          goto lab6;

          try

          {

          lab5:

            System.Web.HttpContext.Current.Trace.Write("umbracoMacro", string.Concat("Usercontrol added (", this.scriptType, ")"));

            control1 = this.loadUserControl(this.ScriptType, attributes, pageElements);

            goto lab8;

          }

          catch(System.Exception ex)

          {

            System.Web.HttpContext.Current.Trace.Warn("umbracoMacro", string.Concat("Error loading userControl (", this.scriptType, ")"), ex);

            control1 = new System.Web.UI.LiteralControl(string.Concat("Error loading userControl '", this.scriptType, "'"));

            goto lab8;

          }

          string[] stringArray1;

          try

          {

          lab4:

            System.Web.HttpContext.Current.Trace.Write("umbracoMacro", string.Concat("Custom control added (", this.scriptType, ")"));

            System.Web.HttpContext.Current.Trace.Write("umbracoMacro", string.Concat("ScriptAssembly (", this.scriptAssembly, ")"));

            control1 = this.loadControl(this.scriptAssembly, this.ScriptType, attributes, pageElements);

            goto lab8;

          }

          catch(System.Exception ex)

          {

            System.Web.HttpContext.Current.Trace.Warn("umbracoMacro", string.Concat((stringArray1 = new string[5] { "Error loading customControl (Assembly: ", this.scriptAssembly, ", Type: '", this.scriptType, "'" })), ex);

            stringArray1 = new string[5] { "Error loading customControl (Assembly: ", this.scriptAssembly, ", Type: '", this.scriptType, "'" };

            control1 = new System.Web.UI.LiteralControl(string.Concat(stringArray1));

            goto lab8;

          }

        lab3:

          control1 = this.loadMacroXSLT(this, attributes, pageElements);

          goto lab8;

          try

          {

          lab7:

            System.Web.HttpContext.Current.Trace.Write("umbracoMacro", string.Concat("Python script added (", this.scriptType, ")"));

            control1 = this.loadMacroPython(this, attributes, pageElements);

            goto lab8;

          }

          catch(System.Exception ex)

          {

            System.Web.HttpContext.Current.Trace.Warn("umbracoMacro", string.Concat((stringArray1 = new string[5] { "Error loading python script (file: ", this.PythonFile, ", Type: '", this.scriptType, "'" })), ex);

            stringArray1 = new string[5] { "Error loading python script (file: ", this.PythonFile, ", Type: '", this.scriptType, "'" };

            control1 = new System.Web.UI.LiteralControl(string.Concat(stringArray1));

            goto lab8;

          }

        lab6:

          boolean1 = !umbraco.GlobalSettings.get_DebugMode();

          if (!boolean1)

          {

            stringArray1 = new string[7] { "<Macro: ", this.Name, " (", this.ScriptAssembly, ",", this.ScriptType, ")>" };

            control1 = new System.Web.UI.LiteralControl(string.Concat(stringArray1));

          }

        lab8:

        }

        boolean1 = (this.RefreshRate <= 0);

        if (!boolean1)

        {

          boolean1 = (this.CacheByPersonalization && (!this.CacheByPersonalization || (umbraco.cms.businesslogic.member.Member.GetCurrentMember() == null)));

          if (!boolean1)

          {

            boolean1 = (control1 == null);

            if (!boolean1)

            {

              this.macroCache.Insert(string.Concat("macroHtml_", string1), new umbraco.MacroCacheContent(control1, control1.ID), null, System.DateTime.Now.AddSeconds((double)this.RefreshRate), System.TimeSpan.Zero, System.Web.Caching.CacheItemPriority.Low, null);

            }

          }

        }

      }

      finally

      {

        System.Threading.Monitor.Exit(object2);

      }

    }

    return control1;

  }

 

 

-- So this thread is holding a lock and rest of the threads are waiting for lock. This is just a portion of issue. Issue is multifold. There are 2647 requests are in queue. This is a four process box and I think request load is too high. Checking the Garbage Collection:

 

0:063> !FinalizeQueue

SyncBlocks to be cleaned up: 0

MTA Interfaces to be released: 0

STA Interfaces to be released: 0

----------------------------------

------------------------------

Heap 0

generation 0 has 547 finalizable objects (406aa3a0->406aac2c)

generation 1 has 221 finalizable objects (406aa02c->406aa3a0)

generation 2 has 28635 finalizable objects (4068e0c0->406aa02c)

Ready for finalization 0 objects (406aac2c->406aac2c)

------------------------------

Heap 1

generation 0 has 209 finalizable objects (403489c8->40348d0c)

generation 1 has 358 finalizable objects (40348430->403489c8)

generation 2 has 22676 finalizable objects (403321e0->40348430)

Ready for finalization 0 objects (40348d0c->40348d0c)

------------------------------

Heap 2

generation 0 has 296 finalizable objects (40616680->40616b20)

generation 1 has 428 finalizable objects (40615fd0->40616680)

generation 2 has 24164 finalizable objects (405fe640->40615fd0)

Ready for finalization 0 objects (40616b20->40616b20)

------------------------------

Heap 3

generation 0 has 381 finalizable objects (406f8fe8->406f95dc)

generation 1 has 280 finalizable objects (406f8b88->406f8fe8)

generation 2 has 24242 finalizable objects (406e10c0->406f8b88)

Ready for finalization 0 objects (406f95dc->406f95dc)

 

-- Notice the Gen 2 finailizable objects in Gen 2 . This is not good and it will hit performance. Please check the http://msdn.microsoft.com/en-us/library/ms973837.aspx for more info

 

Plan:

-----------------------------

* Let’s check with development team of umbraco.macro.renderMacro and see why it’s not releasing the lock properly.

There are some good guidelines for locks in general at:

http://msdn.microsoft.com/en-us/library/c5kehkcz.aspx

And

http://www.guidanceshare.com/wiki/.NET_2.0_Performance_Guidelines_-_Locking_and_Synchronization

* You can modify the autoconfig setting as per your requirement, however the same configuration has worked absolutely fine for many servers that I have worked on. I would say adding more CPU will help. GEN 2 objects are also alarming. We can check with the development team about it.

 

To summarize, this looks like a resource shortage at the time the server is forced to handle too many requests so adding resource (CPU) might help.

 

Let me know should you need to discuss anything.