0

We have simple ASP.NET web application(ASP.NET 2.0) on production with 2 web server and each web server has 64GB RAM and 32 cores. The production site sometimes suddenly spike the CPU to 90-100% on both servers(offcourse only w3wp.exe). Also, we found the pagefile.sys also become too big(once it was 70GB+). We took some dumps of w3wp.exe process and found some interesting results. For example, we found a thread taking 22 minutes just to execute,

Thread 2840
General Operation Info 
Type   Unknown Operation 
Dumps present   All dumps 
Elapsed Time   (unknown) 

Thread Info 
Entry point   mscorwks!Thread::intermediateThreadProc 
System ID   2840 (0xB18) 
Create time   21/01/2018 10:55:34 


All functions in this operation      (excludes boiler-plate functions)
System.Security.CodeAccessSecurityEngine.Assert(System.Security.CodeAccessPermission, System.Threading.StackCrawlMark ByRef) 
System.Security.CodeAccessPermission.Assert() 
System.Security.PermissionToken.FindToken(System.Type) 
System.Security.PermissionSet.RemovePermission(System.Type) 
System.Security.PermissionSet.CopyWithNoIdentityPermissions() 
System.Security.CodeAccessSecurityEngine.ReflectionTargetDemandHelper(Int32, System.Security.PermissionSet, System.Threading.CompressedStack) 

System.Security.CodeAccessSecurityEngine.Assert(System.Security.CodeAccessPermission, System.Threading.StackCrawlMark ByRef) 
System.Security.CodeAccessPermission.Assert() 
System.Security.PermissionToken.FindToken(System.Type) 
System.Security.PermissionSet.RemovePermission(System.Type) 
System.Security.PermissionSet.CopyWithNoIdentityPermissions() 
System.Security.CodeAccessSecurityEngine.ReflectionTargetDemandHelper(Int32, System.Security.PermissionSet, System.Threading.CompressedStack) 

User Time     00:22:42.359 
Kernel time   00:01:59.765

My question is that why CodeAccessSecurityEngine is taking 22 minutes to execute?

We have found at least 48 threads in the dumps that using CodeAccessSecurityEngine and taking lot of time. Some more examples,

Thread 8092
General Operation Info 
Type   Unknown Operation 
Dumps present   All dumps 
Elapsed Time   (unknown) 

Thread Info 
Entry point   mscorwks!Thread::intermediateThreadProc 
System ID   8092 (0x1F9C) 
Create time   21/01/2018 10:25:40 


System.String.InternalSubString(Int32, Int32, Boolean) 
System.RuntimeType.SplitName(System.String, System.String ByRef, System.String ByRef) 
System.RuntimeType.GetInterface(System.String, Boolean) 
System.Security.PermissionToken.FindToken(System.Type) 
System.Security.PermissionSet.RemovePermission(System.Type) 
System.Security.PermissionSet.CopyWithNoIdentityPermissions() 
System.Security.CodeAccessSecurityEngine.ReflectionTargetDemandHelper(Int32, System.Security.PermissionSet, System.Threading.CompressedStack) 

User Time   00:26:49.734 
Kernel time   00:02:38.296 

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

Thread 2360
General Operation Info 
Type   Unknown Operation 
Dumps present   All dumps 
Elapsed Time   (unknown) 

Thread Info 
Entry point   mscorwks!Thread::intermediateThreadProc 
System ID   2360 (0x938) 
Create time   21/01/2018 10:47:53 

System.Collections.Generic.List`1[[System.__Canon, mscorlib]].set_Capacity(Int32) 
System.Collections.Generic.List`1[[System.__Canon, mscorlib]].EnsureCapacity(Int32) 
System.Collections.Generic.List`1[[System.__Canon, mscorlib]].Add(System.__Canon) 
System.RuntimeType.GetMethodCandidates(System.String, System.Reflection.BindingFlags, System.Reflection.CallingConventions, System.Type[], Boolean) 
System.RuntimeType.GetMethodImpl(System.String, System.Reflection.BindingFlags, System.Reflection.Binder, System.Reflection.CallingConventions, System.Type[], System.Reflection.ParameterModifier[]) 
System.Security.PermissionToken.FindToken(System.Type) 
System.Security.PermissionSet.RemovePermission(System.Type) 
System.Security.PermissionSet.CopyWithNoIdentityPermissions() 
System.Security.CodeAccessSecurityEngine.ReflectionTargetDemandHelper(Int32, System.Security.PermissionSet, System.Threading.CompressedStack) 

User Time   00:25:37.671 
Kernel time   00:02:29.953 

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

Thread 7008
General Operation Info 
Type   Unknown Operation 
Dumps present   All dumps 
Elapsed Time   (unknown) 

Thread Info 
Entry point   mscorwks!Thread::intermediateThreadProc 
System ID   7008 (0x1B60) 
Create time   21/01/2018 10:54:20 

System.Reflection.MethodBase.CheckArguments(System.Object[], System.Reflection.Binder, System.Reflection.BindingFlags, System.Globalization.CultureInfo, System.Signature) 
System.Reflection.RuntimeConstructorInfo.Invoke(System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo) 
System.RuntimeType.CreateInstanceImpl(System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo, System.Object[]) 
System.Security.PermissionSet.AddPermission(System.Security.IPermission) 
System.Security.CodeAccessSecurityEngine.ReflectionTargetDemandHelper(Int32, System.Security.PermissionSet, System.Threading.CompressedStack) 


User Time   00:23:01.656 
Kernel time   00:02:04.625 
-------------------------------------------------------------------------------

Thread 5584
General Operation Info 
Type   Unknown Operation 
Dumps present   All dumps 
Elapsed Time   (unknown) 


Thread Info 
Entry point   mscorwks!Thread::intermediateThreadProc 
System ID   5584 (0x15D0) 
Create time   21/01/2018 10:53:13 


System.Security.CodeAccessSecurityEngine.ReflectionTargetDemandHelper(Int32, System.Security.PermissionSet, System.Threading.CompressedStack) 

User Time   00:23:40.421 
Kernel time   00:02:08.296

Dumps have taken and analysed using Debug Diagnostics as shown here https://docs.microsoft.com/en-us/iis/troubleshoot/performance-issues/troubleshooting-high-cpu-in-an-iis-7x-application-pool

Is CodeAccessSecurityEngine is really culprit or something else?

Imran Qadir Baksh - Baloch
  • 337
  • 3
  • 10
  • 17
  • fwiw - User/Kernel time is the sum of all runtime the thread has got since it was created, not the duration of the last time it ran. It could be one consecutive run of 22 minutes or a few seconds eacht time spanning out for a full day. – Lieven Keersmaekers Jan 22 '18 at 08:27
  • What does debugdiag analysis tell you? – Lieven Keersmaekers Jan 22 '18 at 08:27
  • debugdiag showing me the report that include the above data. So, how do we can find which method taking too much time to execute? – Imran Qadir Baksh - Baloch Jan 22 '18 at 11:38
  • If you followed the instructions from your link, there's a good chance that the given stacks are what's causing your spikes but you might get a better result using wpa. A dump is just a snapshot from a single point in time. Using wpa can get you a more holistic view. – Lieven Keersmaekers Jan 22 '18 at 12:47
  • You can use [UI for ETW](https://randomascii.wordpress.com/2015/04/14/uiforetw-windows-performance-made-easier/) from Buce Dawson to get going pretty fast – Lieven Keersmaekers Jan 22 '18 at 12:49
  • oh great let me check that – Imran Qadir Baksh - Baloch Jan 22 '18 at 13:59
  • DebugDiag won't tell much on high CPU scenarios. Open a support case via http://support.microsoft.com and let Microsoft support team analyze the dumps manually please. – Lex Li Apr 16 '18 at 20:55

0 Answers0