Troubleshooting Scenario - High CPU usage on PaaS Roles with the same load after a running for a few hours


 

I had this interesting issue reported where the instance count would increase from 10 to 50 over the course of the month. This used to happen with the exact similar load and number of users. This was really perplexing for the customer’s Azure application developers and hence they reported the issue to Microsoft Azure Support.

At the very first analysis we found they used to manually increase the instance count as the existing instances used to hit CPU around 90%  and forming a plateau there, and hence becoming more or less unresponsive. So it was relatively simple to isolate the cause of the increase in instance count. The crucial thing was to find the cause of the high CPU. 

High CPU on the instance is generally caused by the application code. So we took memory dump on one of the instance when it gets into high CPU situation.  The way we analyze is like the one I did for a situation detailed in this blog http://blogs.msdn.com/b/cie/archive/2013/11/28/windows-azure-worker-role-showing-high-cpu.aspx

Process to collect dumps  

  a) RDP to the instance running the Cloud Service.  
  b) From task manager check which process is taking most CPU and is staying there without coming down.
  c) Right click and collect a Full Crash Dump and repeat this every 1 minute for say 5 minutes. So we will have 5 dump files.
  d) Once you have the files you can analyze it or create a ticket with Microsoft for an engineer to help analyze.

In this case it was W3WP process so we collected process dumps on it. In the first 2 memory dumps I didn’t find any high CPU.

Dump Analysis  

I am not delving into the details on how I did it as it merits a separate discussion. In all the dumps I see the CPU moving between 81% to 100%. Most of the calls that are stuck are as following

SP               IP               Function                                                                                                                                                                                                                                                        Source
00000011a7ff9008 0000000000000000 HelperMethodFrame                                                                                                                                                                                                                                               
00000011a7ff9150 00007ff90caf1177 Microsoft.Data.OData.DuplicatePropertyNamesChecker.CheckForDuplicatePropertyNames(Microsoft.Data.OData.ODataProperty)                                                                                                                                           
00000011a7ff91b0 00007ff90caee6d8 Microsoft.Data.OData.Atom.ODataAtomPropertyAndValueDeserializer.ReadPropertiesImplementation(Microsoft.Data.Edm.IEdmStructuredType, System.Collections.Generic.List`1<Microsoft.Data.OData.ODataProperty>, Microsoft.Data.OData.DuplicatePropertyNamesChecker,  
00000011a7ff9240 00007ff90caede16 Microsoft.Data.OData.Atom.ODataAtomEntryAndFeedDeserializer.ReadAtomContentElement(Microsoft.Data.OData.Atom.IODataAtomReaderEntryState)                                                                                                                        
00000011a7ff92c0 00007ff90caec553 Microsoft.Data.OData.Atom.ODataAtomEntryAndFeedDeserializer.ReadAtomElementInEntry(Microsoft.Data.OData.Atom.IODataAtomReaderEntryState)                                                                                                                        
00000011a7ff9300 00007ff90caec2a2 Microsoft.Data.OData.Atom.ODataAtomEntryAndFeedDeserializer.ReadEntryContent(Microsoft.Data.OData.Atom.IODataAtomReaderEntryState)                                                                                                                              
00000011a7ff9370 00007ff90cae9665 Microsoft.Data.OData.Atom.ODataAtomReader.ReadEntryStart()                                                                                                                                                                                                      
00000011a7ff93e0 00007ff90caf2ef6 Microsoft.Data.OData.Atom.ODataAtomReader.ReadAtEntryEndImplementation()                                                                                                                                                                                        
00000011a7ff9430 00007ff90cae88df Microsoft.Data.OData.ODataReaderCore.ReadImplementation()                                                                                                                                                                                                       
00000011a7ff9480 00007ff90cae8727 Microsoft.Data.OData.ODataReaderCore.InterceptException[[System.Boolean, mscorlib]](System.Func`1<Boolean>)                                                                                                                                                     
00000011a7ff94f0 00007ff90cca40a6 Microsoft.WindowsAzure.Storage.Table.Protocol.TableOperationHttpResponseParsers.TableQueryPostProcessGeneric[[System.__Canon, mscorlib]](System.IO.Stream, System.Func`6<System.String,System.String,System.DateTimeOffset,System.Collections.Generic.IDictiona 
00000011a7ff9580 00007ff90cca3df1 Microsoft.WindowsAzure.Storage.Table.TableQuery`1+<>c__DisplayClassf`2[[System.__Canon, mscorlib],[System.__Canon, mscorlib],[System.__Canon, mscorlib]].<QueryImpl>b__e(Microsoft.WindowsAzure.Storage.Core.Executor.RESTCommand`1<Microsoft.WindowsAzure.Stor 
00000011a7ff95e0 00007ff90caddc69 Microsoft.WindowsAzure.Storage.Core.Executor.Executor.ProcessEndOfRequest[[System.__Canon, mscorlib]](Microsoft.WindowsAzure.Storage.Core.Executor.ExecutionState`1<System.__Canon>)                                                                            
00000011a7ff9630 00007ff90cad99e5 Microsoft.WindowsAzure.Storage.Core.Executor.Executor.ExecuteSync[[System.__Canon, mscorlib]](Microsoft.WindowsAzure.Storage.Core.Executor.StorageCommandBase`1<System.__Canon>, Microsoft.WindowsAzure.Storage.RetryPolicies.IRetryPolicy, Microsoft.WindowsAz 
00000011a7ff9970 00007ff90cca30ae Microsoft.WindowsAzure.Storage.Table.TableQuery`1+<>c__DisplayClass7[[System.__Canon, mscorlib]].<ExecuteInternal>b__6(Microsoft.WindowsAzure.Storage.IContinuationToken)                                                                                       
00000011a7ff99d0 00007ff90cca2fd8 Microsoft.WindowsAzure.Storage.Core.Util.CommonUtility+<LazyEnumerable>d__0`1[[System.__Canon, mscorlib]].MoveNext()                                                                                                                                            
00000011a7ff9a40 00007ff90cca22f8 MoviePlayer.TableStorage.GetListRangeEntity[[System.__Canon, mscorlib]](System.Collections.Generic.List`1<MoviePlayer.QueryTableStorage>, System.String)                                                                                                        
00000011a7ff9b70 00007ff90cca0612 MoviePlayer.NoSQLData.GetListCategoryTS(MoviePlayer.Video, System.String)                                                                                                                                                                          
00000011a7ffa020 00007ff90cca3ab8 MoviePlayer.NoSQLData.GetCategoryLatest(MoviePlayer.Video, System.String)                                                                                                                                                                            
00000011a7ffa090 00007ff90cafda64 RepSyndWebApplication.Player.Default.Page_Load(System.Object, System.EventArgs)                                                                                                                                                                             
00000011a7ffa640 00007ff962abc0b7 System.Web.UI.Control.LoadRecursive()                                                                                                                                                                                                                           
00000011a7ffa690 00007ff962adcc4a System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)                                                                                                                                                                                                         
00000011a7ffa750 00007ff962adbec9 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)                                                                                                                                                                                                             
00000011a7ffa7c0 00007ff962adbd27 System.Web.UI.Page.ProcessRequest()                                                                                                                                                                                                                             
00000011a7ffa860 00007ff962ada453 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)                                                                                                                                                                                                       
00000011a7ffa8b0 00007ff962ae4b61 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()                                                                                                                                                         
00000011a7ffa990 00007ff962aabee5 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)                                                                                                                                                                                           
00000011a7ffaa30 00007ff962ac954a System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)                                                                                                                                                                                    
00000011a7ffab80 00007ff962aac0f3 System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)                                                                                                                                                        
00000011a7ffabd0 00007ff962aa613e System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)                                                                                                                                          
00000011a7ffac70 00007ff962aaefb1 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)                                                                                                                                                              
00000011a7ffae80 00007ff962aae9e2 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)                                                                                                                                                                    
00000011a7ffaed0 00007ff9632028d1 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)                                                                                                                                                                                     
00000011a7ffb6e8 0000000000000000 InlinedCallFrame                                                                                                                                                                                                                                                
00000011a7ffb6e8 0000000000000000 InlinedCallFrame                                                                                                                                                                                                                                                
00000011a7ffb6c0 00007ff962b5838b DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)                                                                                                                                                                    
00000011a7ffb790 00007ff962aaf19f System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)                                                                                                                                                              
00000011a7ffb9a0 00007ff962aae9e2 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)                                                                                                                                                                    
00000011a7ffb9f0 00007ff9632028d1 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)                                                                                                                                                                                     
00000011a7ffda48 0000000000000000 InlinedCallFrame                                                                                                                                                                                                                                                
00000011a7ffda48 0000000000000000 InlinedCallFrame                                                                                                                                                                                                                                                
00000011a7ffda20 00007ff962b5838b DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)                                                                                                                                                                    
00000011a7ffdaf0 00007ff962aaf19f System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)                                                                                                                                                              
00000011a7ffdd00 00007ff962aae9e2 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)                                                                                                                                                                    
00000011a7ffdd50 00007ff9632028d1 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)                                                                                                                                                                                     
00000011a7ffec98 0000000000000000 InlinedCallFrame                                                                                                                                                                                                                                                
00000011a7ffec98 0000000000000000 InlinedCallFrame                                                                                                                                                                                                                                                
00000011a7ffec70 00007ff962b5838b DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)                                                                                                                                                                    
00000011a7ffed40 00007ff962aaf19f System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)                                                                                                                                                              
00000011a7ffef50 00007ff962aae9e2 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)                                                                                                                                                                    
00000011a7ffefa0 00007ff9632028d1 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)                                                                                                                                                                                     
00000011a7fff1a8 0000000000000000 ContextTransitionFrame

The common function in all the call stacks  is

MoviePlayer.TableStorage.GetListRangeEntity[[System.__Canon, mscorlib]](System.Collections.Generic.List`1<MoviePlayer.QueryTableStorage>, System.String)

It is executing the following code

public System.Collections.Generic.List<T> GetListRangeEntity<T>(System.Collections.Generic.List<MoviePlayer.QueryTableStorage> queue, string query)
{
  string string1 = "";
  if (!string.IsNullOrWhiteSpace(query)) goto lab1;
  if (string.IsNullOrWhiteSpace(query))
  {
    if (que != null)
    {
      System.Collections.Generic.List<MoviePlayer.QueryTableStorage>.Enumerator enumerator1 = queue.GetEnumerator();
      try
      {
        while (enumerator1.MoveNext())
        {
          MoviePlayer.QueryTableStorage storage1 = enumerator1.Current;
          switch (storage1.TypeTS)
          {
            case 0: goto lab2;
            case 1: goto lab3;
            case 2: goto lab4;
            case 3: goto lab5;
            case 4: goto lab6;
            case 5: goto lab7;
            case 6: goto lab8;
            case 7: goto lab9;
          }
          goto lab10;
        lab2:
          string1 = string.Concat(string1, Microsoft.WindowsAzure.Storage.Table.TableQuery.GenerateFilterCondition(storage1.KeyTS, storage1.OperationTS, storage1.ValueTS.ToString()));
          goto lab10;
        lab3:
          
   <SNIPPED>

The collection passed is as below.

0000000f58a9f1f0 System.Collections.Generic.List`1[[MoviePlayer.CategoryList, MoviePlayerDistList]]

The collection is as follows and contains 726 objects

MT                           Field           Offset        Type                 VT     Attr           Value                          Name

00007ff96af01250     4000cd1       8              System.Object[]   0      instance     0000000f58b9a7c8      _items

00007ff96af037c8     4000cd2       18             System.Int32       1      instance                           726      _size

00007ff96af037c8     4000cd3       1c             System.Int32       1      instance                           726      _version

00007ff96af011b8    4000cd4       10             System.Object     0      instance     0000000000000000    _syncRoot

Looking at the size of this object.

sizeof(0000000f58b40940) = 137048 (0x21758) bytes (MoviePlayer.CategoryList) 

This object MoviePlayer.CategoryList size is greater than 85,000 bytes. Any object greater than 85,000 bytes will not get allocated in the normal SOH heap but will go to the LOH (Large Object Heap). Details around LOH and GC can be found in the articles

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

http://msdn.microsoft.com/en-us/magazine/cc534993.aspx

If I look at the process uptime 1:45:31.000 = 6331 seconds in the first dump. If I look at the number of time GC has run it’s very high for Gen 2. It’s almost like Gen 2 collection is attempted in every two seconds.

.NET CLR Memory

Counter                               Value

===============     ==============

Bytes in All Heaps              84,495,440

GCHandles                        1,514

GEN 0 Collections              55,143

GEN 1 Collections              13,746

GEN 2 Collections             3,463

# Induced GCs                   0

# of Pinned Objects           2

Sync Blocks in use              121

Finalization Survivors          0

Total Commited Bytes        502,095,872

Total Reserved Bytes          18,253,578,240

GEN 0 Heap Size                26,423,840

GEN 1 Heap Size                2,989,384

GEN 2 Heap Size                52,896,880

LOH Size                            2,185,336

% Time in GC                     7.90%

So the Action Plan for this issue was to reduce the size of the object for MoviePlayer.CategoryList. Since most outside developer support engineer roles are not familiar with post mortem analysis the following could be used to find the size of the object using .Net or Visual Studio

http://stackoverflow.com/questions/324053/find-out-the-size-of-a-net-object

 After implementing the suggestions the CPU grows in linear fashion with load and not exponential. The CPU stopped hitting >90% and staying there, so there was no need to spawn additional instances of the role to server users.

Hope this article helps in understanding one of the fundamental causes of frequent GC leading to high CPU. It’s not just Azure but could happen on premises application as well.

Regards,

Angshuman Nayak

Cloud Integration Engineer


Comments (0)

Skip to main content