Open marafiq opened 6 months ago
Tagging subscribers to this area: @tommcdon See info in area-owners.md if you want to be subscribed.
11056 ?
@jkotas It seems very related. As on CPU stacks window, this is what I see Subsequently as previously noted multiple threads doing the rundown.
Name Inc % Inc Exc % Exc Fold When First Last
+ Thread (13212) CPU=11459ms 49.0 13,875 0.0 0 0 41o1996o_o____o_.._._..o____o_._ 503.287 129,364.361
|+ ntdll!_RtlUserThreadStart 38.5 10,899 0.0 0 0 ___1886o_o____o_.._._..o____o_._ 16,510.889 129,364.361
||+ ntdll!__RtlUserThreadStart 38.5 10,899 0.0 0 0 ___1886o_o____o_.._._..o____o_._ 16,510.889 129,364.361
|| + kernel32!BaseThreadInitThunk 38.5 10,899 0.0 0 0 ___1886o_o____o_.._._..o____o_._ 16,510.889 129,364.361
|| + ntdll!TppWorkerThread 38.5 10,899 0.0 0 0 ___1886o_o____o_.._._..o____o_._ 16,510.889 129,364.361
|| + ntdll!TppWaitCompletion 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| |+ ntdll!TppExecuteWaitCallback 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + ntdll!EtwpNotificationThread 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + ntdll!EtwDeliverDataBlock 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + ntdll!EtwpProcessNotification 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + ntdll!EtwpUpdateEnableInfoAndCallback 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + ntdll!EtwpEventApiCallback 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + clr!McGenControlCallbackV2 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + clr!EtwCallback 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + clr!ETW::EnumerationLog::StartRundown 38.4 10,852 0.0 0 0 ___1886_________________________ 16,510.889 28,857.130
|| | + clr!ETW::EnumerationLog::EnumerationHelper 38.3 10,846 0.0 0 0 ___1886_________________________ 16,510.889 28,856.122
|| | |+ clr!ETW::EnumerationLog::IterateAppDomain 29.6 8,367 0.0 0 0 ___1674_________________________ 16,510.889 28,458.092
|| | ||+ clr!ETW::EnumerationLog::IterateDomain 29.6 8,367 0.0 0 0 ___1674_________________________ 16,510.889 28,458.092
|| | || + clr!ETW::MethodLog::SendEventsForJitMethods 28.9 8,179 0.0 0 0 ___1574_________________________ 16,510.889 28,458.092
|| | || |+ clr!ETW::MethodLog::SendEventsForJitMethodsHelper 28.8 8,155 0.0 9 0 ___1574_________________________ 16,510.889 28,458.092
|| | || ||+ clr!ETW::MethodLog::SendMethodILToNativeMapEvent 16.3 4,599 0.0 14 0 ___0342_________________________ 16,510.889 28,458.092
|| | || |||+ clr!Debugger::GetILToNativeMappingIntoArrays 13.3 3,774 0.2 70 0 ___0232_________________________ 16,510.889 28,457.084
|| | || ||||+ clr!Debugger::GetJitInfoWorker 12.7 3,602 0.2 49 0 ___0232_________________________ 16,510.889 28,457.084
|| | || |||||+ clr!Debugger::GetOrCreateMethodInfo 12.4 3,497 0.0 2 0 ___0231_________________________ 16,510.889 28,457.084
|| | || ||||||+ clr!DebuggerMethodInfoTable::GetMethodInfo 12.3 3,469 0.0 0 0 ___0231_________________________ 16,510.889 28,457.084
|| | || |||||||+ clr!CHashTable::Find 11.7 3,306 1.2 330 0 ___0221_________________________ 16,510.889 28,457.084
|| | || ||||||||+ clr!DebuggerMethodInfoTable::Cmp 10.5 2,972 10.4 2,931 0 ___0221_________________________ 16,510.889 28,457.084
|| | || |||||||||+ ntoskrnl!KiDpcInterrupt 0.1 18 0.0 3 0 ___o.oo_________________________ 16,577.900 27,556.997
|| | || |||||||||+ ntoskrnl!KiVmbusInterruptDispatch 0.0 12 0.0 0 0 ___.o.._________________________ 16,652.906 27,757.019
|| | || |||||||||+ ntoskrnl!KiApcInterrupt 0.0 7 0.0 3 0 ___...._________________________ 16,655.906 26,007.840
|| | || |||||||||+ ntoskrnl!KiInterruptDispatchNoLockNoEtw 0.0 3 0.0 0 0 ___._.__________________________ 16,689.910 23,940.632
|| | || |||||||||+ ntoskrnl!KiSystemServiceUser 0.0 1 0.0 0 0 ____.___________________________ 18,549.157 18,550.157
|| | || ||||||||+ ntoskrnl!KiDpcInterrupt 0.0 3 0.0 1 0 ____..__________________________ 21,330.374 23,159.555
|| | || ||||||||+ ntoskrnl!KiVmbusInterruptDispatch 0.0 1 0.0 0 0 ___.____________________________ 16,764.924 16,765.924
|| | || |||||||+ ntdll!LdrpValidateUserCallTargetBitMapCheck 0.3 94 0.3 94 0 ___oooo_________________________ 16,593.896 28,296.066
|| | || |||||||+ ntdll!LdrpValidateUserCallTarget 0.2 50 0.2 50 0 ___oooo_________________________ 16,687.906 28,413.079
|| | || |||||||+ clr!DebuggerMethodInfoTable::Cmp 0.1 19 0.1 19 0 ___.oo._________________________ 16,848.923 27,311.968
|| | || ||||||+ clr!CrstBase::Leave 0.0 10 0.0 5 0 ___.o_._________________________ 16,553.893 28,221.060
|| | || ||||||+ clr!Debugger::AcquireDebuggerDataLock 0.0 9 0.0 0 0 ____o.._________________________ 17,570.994 27,054.940
|| | || ||||||+ clr!Debugger::ReleaseDebuggerDataLock 0.0 3 0.0 3 0 _____.__________________________ 22,172.455 25,074.743
|| | || ||||||+ clr!CrstBase::Enter 0.0 2 0.0 2 0 _____.__________________________ 25,235.761 25,561.792
|| | || ||||||+ ntdll!RtlLeaveCriticalSection 0.0 1 0.0 1 0 _____.__________________________ 25,628.800 25,629.800
|| | || ||||||+ clr!GetThread 0.0 1 0.0 1 0 ______._________________________ 27,034.938 27,035.938
|| | || |||||+ clr!DebuggerMethodInfo::FindOrCreateInitAndAddJitInfo 0.1 40 0.0 0 0 ___oooo_________________________ 16,699.909 28,271.065
|| | || |||||+ clr!Debugger::AcquireDebuggerDataLock 0.0 7 0.0 0 0 ____..._________________________ 17,593.996 27,147.952
|| | || |||||+ clr!CrstBase::Leave 0.0 4 0.0 0 0 ____._._________________________ 18,634.101 27,715.008
|| | || |||||+ clr!DebuggerMethodInfo::FindJitInfo 0.0 1 0.0 1 0 ___.____________________________ 16,532.891 16,533.891
|| | || |||||+ clr!Debugger::ReleaseDebuggerDataLock 0.0 1 0.0 1 0 ____.___________________________ 17,568.995 17,569.995
|| | || |||||+ clr!DebuggerMethodInfoTable::GetMethodInfo 0.0 1 0.0 1 0 _____.__________________________ 23,062.544 23,063.544
|| | || |||||+ ntoskrnl!KiDpcInterrupt 0.0 1 0.0 0 0 _____.__________________________ 25,390.780 25,391.780
|| | || |||||+ clr!__EH_epilog3 0.0 1 0.0 1 0 ______._________________________ 28,212.059 28,213.059
|| | || ||||+ clr!ClrAllocInProcessHeap 0.3 71 0.0 4 0 ___.ooo_________________________ 16,762.914 28,265.064
|| | || ||||+ clr!DebuggerJitInfo::LazyInitBounds 0.1 20 0.1 20 0 ____ooo_________________________ 18,251.059 27,189.954
|| | || ||||+ clr!MethodTable::GetModule 0.0 2 0.0 2 0 ____.___________________________ 20,687.308 21,367.373
|| | || ||||+ ntdll!LdrpValidateUserCallTargetBitMapCheck 0.0 1 0.0 1 0 ___.____________________________ 16,797.917 16,798.917
|| | || ||||+ clr!MethodDesc::HasClassOrMethodInstantiation 0.0 1 0.0 1 0 ___.____________________________ 17,123.950 17,124.950
|| | || ||||+ clr!MethodDesc::GetMemberDef_NoLogging 0.0 1 0.0 1 0 ____.___________________________ 20,936.333 20,937.333
|| | || ||||+ clr!MethodDesc::GetModule_NoLogging 0.0 1 0.0 1 0 _____.__________________________ 22,780.516 22,781.516
|| | || ||||+ clr!__EH_prolog3 0.0 1 0.0 1 0 _____.__________________________ 23,144.551 23,145.551
|| | || ||||+ clr!__EH_prolog3_catch 0.0 1 0.0 1 0 _____.__________________________ 24,193.656 24,194.656
|| | || ||||+ clr!MethodDesc::HasClassInstantiation 0.0 1 0.0 1 0 ______._________________________ 27,033.938 27,034.938
|| | || ||||+ ntdll!LdrpValidateUserCallTarget 0.0 1 0.0 1 0 ______._________________________ 27,036.938 27,037.938
|| | || ||||+ clr!Debugger::ReleaseDebuggerDataLock 0.0 1 0.0 1 0 ______._________________________ 27,636.001 27,637.001
|| | || |||+ clr!CoTemplate_xxchQR3QR3h 2.6 749 0.0 10 0 ___o000_________________________ 16,541.895 28,458.092
|| | || |||+ clr!operator delete 0.1 37 0.0 3 0 ___oooo_________________________ 16,852.923 27,601.998
|| | || |||+ clr!__EH_epilog3 0.0 4 0.0 4 0 ___.._._________________________ 16,656.901 28,058.043
|| | || |||+ clr!Debugger::GetJitInfoWorker 0.0 4 0.0 4 0 ____..._________________________ 18,212.056 27,912.027
|| | || |||+ clr!ClrAllocInProcessHeap 0.0 3 0.0 3 0 ____..__________________________ 17,602.998 23,809.618
|| | || |||+ clr!EtwCallout 0.0 3 0.0 3 0 ____..._________________________ 18,157.049 28,282.066
|| | || |||+ clr!__EH_prolog3 0.0 3 0.0 3 0 ____..__________________________ 18,250.062 25,545.792
|| | || |||+ clr!__EH_prolog3_catch 0.0 3 0.0 3 0 _____.._________________________ 25,066.742 28,409.079
|| | || |||+ ntdll!LdrpValidateUserCallTargetBitMapCheck 0.0 2 0.0 2 0 ____..__________________________ 19,188.156 23,923.630
|| | || |||+ ntdll!LdrpValidateUserCallTarget 0.0 1 0.0 1 0 ____.___________________________ 17,589.997 17,590.997
|| | || |||+ clr!_security_check_cookie 0.0 1 0.0 1 0 ____.___________________________ 19,607.198 19,608.198
|| | || |||+ clr!BaseWrapper,&DeleteArray,2>,0,&CompareDefault,2>::operator& 0.0 1 0.0 1 0 ____.___________________________ 21,016.339 21,017.339
|| | || ||+ clr!ETW::MethodLog::SendMethodEvent 11.3 3,188 0.1 36 0 ___0221_________________________ 16,521.888 28,456.082
|| | || ||+ clr!EEJitManager::CodeHeapIterator::Next 0.9 268 0.4 119 0 ___o000_________________________ 16,535.892 28,418.079
|| | || ||+ clr!__EH_prolog3_GS 0.0 12 0.0 12 0 ____oo._________________________ 19,248.162 27,524.989
|| | || ||+ clr!MethodTable::IsRestored 0.0 10 0.0 10 0 ___...._________________________ 16,991.936 27,512.987
|| | || ||+ ntdll!LdrpValidateUserCallTargetBitMapCheck 0.0 6 0.0 6 0 ____..__________________________ 17,387.976 25,646.801
|| | || ||+ clr!MethodDesc::GetMethodTable 0.0 6 0.0 6 0 ____..._________________________ 18,701.107 28,398.078
|| | || ||+ clr!MethodDesc::GetMethodTable_NoLogging 0.0 6 0.0 6 0 ____..._________________________ 19,160.153 26,255.863
|| | || ||+ clr!ReJitManager::FindReJitInfo 0.0 5 0.0 1 0 ___._.._________________________ 16,942.932 26,911.926
|| | || ||+ clr!ExecutionManager::GetScanFlags 0.0 4 0.0 4 0 ___...__________________________ 16,975.933 25,564.794
|| | || ||+ clr!MethodDesc::IsSharedByGenericMethodInstantiations 0.0 4 0.0 4 0 ____..._________________________ 18,132.050 28,216.060
|| | || ||+ clr!__EH_prolog3 0.0 4 0.0 4 0 ____..__________________________ 18,260.060 23,438.582
|| | || ||+ clr!BaseWrapper,&DeleteArray,2>,0,&CompareDefault,2>::operator& 0.0 3 0.0 2 0 ___.__._________________________ 16,824.918 27,291.966
|| | || ||+ clr!EECodeInfo::GetMethodRegionInfo 0.0 3 0.0 3 0 ___..___________________________ 16,827.919 18,906.127
|| | || ||+ clr!SString::ConvertToUnicode 0.0 3 0.0 3 0 ____..._________________________ 17,298.966 26,053.842
|| | || ||+ clr!MethodDesc::GetDomain 0.0 3 0.0 3 0 ____..__________________________ 18,058.042 22,671.506
|| | || ||+ clr!MethodDesc::GetMemberDef_NoLogging 0.0 3 0.0 3 0 ____..__________________________ 18,143.050 22,228.460
|| | || ||+ clr!operator delete 0.0 3 0.0 3 0 ____..._________________________ 18,340.068 27,271.963
|| | || ||+ clr!MethodDesc::IsRestored 0.0 3 0.0 3 0 _____.._________________________ 25,067.742 28,146.053
|| | || ||+ clr!GetThread 0.0 2 0.0 2 0 ____._._________________________ 21,056.342 27,962.032
|| | || ||+ clr!MethodDesc::IsTypicalMethodDefinition 0.0 1 0.0 1 0 ____.___________________________ 17,195.957 17,196.957
|| | || ||+ clr!MethodDesc::GetMethodInfo 0.0 1 0.0 1 0 ____.___________________________ 17,514.989 17,515.989
|| | || ||+ clr!MethodDesc::HasClassOrMethodInstantiation_NoLogging 0.0 1 0.0 1 0 ____.___________________________ 18,229.056 18,230.056
|| | || ||+ clr!__EH_epilog3_GS 0.0 1 0.0 1 0 ____.___________________________ 19,342.171 19,343.171
|| | || ||+ clr!MethodDesc::HasClassInstantiation 0.0 1 0.0 1 0 ____.___________________________ 21,040.341 21,041.341
|| | || ||+ clr!Debugger::GetILToNativeMappingIntoArrays 0.0 1 0.0 1 0 _____.__________________________ 21,574.394 21,575.394
|| | || ||+ clr!MethodDesc::IsGenericMethodDefinition 0.0 1 0.0 1 0 _____.__________________________ 21,814.418 21,815.418
|| | || ||+ ntoskrnl!KiVmbusInterruptDispatch 0.0 1 0.0 0 0 _____.__________________________ 25,002.745 25,003.745
|| | || ||+ clr!MethodDesc::HasClassOrMethodInstantiation 0.0 1 0.0 1 0 ______._________________________ 26,101.846 26,102.846
|| | || ||+ clr!MethodTable::GetModule 0.0 1 0.0 1 0 ______._________________________ 27,026.937 27,027.937
|| | || ||+ clr!MethodTable::IsSharedByGenericInstantiations 0.0 1 0.0 1 0 ______._________________________ 27,087.945 27,088.945
|| | || |+ clr!MethodDesc::GetMethodEntryPoint 0.0 8 0.0 3 0 ___...._________________________ 16,946.932 27,603.997
|| | || |+ clr!ReJitManager::FindReJitInfo 0.0 4 0.0 4 0 _____.._________________________ 21,657.403 28,018.037
|| | || |+ clr!__EH_prolog3 0.0 3 0.0 3 0 ____..._________________________ 17,524.990 28,440.082
|| | || |+ clr!EEJitManager::CodeHeapIterator::Next 0.0 3 0.0 3 0 ____..__________________________ 18,534.090 23,252.561
|| | || |+ clr!__EH_prolog3_GS 0.0 1 0.0 1 0 ___.____________________________ 17,040.939 17,041.939
|| | || |+ clr!??__EH_epilog3_GS 0.0 1 0.0 1 0 ____.___________________________ 18,501.086 18,502.086
|| | || |+ clr!MethodDesc::GetMethodTable_NoLogging 0.0 1 0.0 1 0 ____.___________________________ 19,581.195 19,582.195
|| | || |+ clr!MethodDesc::GetModule 0.0 1 0.0 1 0 _____.__________________________ 25,637.800 25,638.800
|| | || |+ clr!ETW::MethodLog::SendMethodEvent 0.0 1 0.0 1 0 ______._________________________ 26,072.845 26,073.845
|| | || |+ clr!ETW::MethodLog::SendMethodILToNativeMapEvent 0.0 1 0.0 1 0 ______._________________________ 26,958.930 26,959.930
|| | || + clr!ETW::EnumerationLog::IterateAssembly 0.7 185 0.0 0 0 ____00o_________________________ 18,074.042 26,894.926
|| | || + clr!AppDomain::AssemblyIterator::Next 0.0 2 0.0 0 0 _____.._________________________ 24,783.712 26,871.925
|| | || + clr!ETW::EnumerationLog::IterateModule 0.0 1 0.0 0 0 ____.___________________________ 20,614.299 20,615.299
|| | |+ clr!ETW::EnumerationLog::IterateDomain 8.8 2,479 0.0 0 0 ____211_________________________ 17,672.002 28,856.122
|| | + clr!ETW::EnumerationLog::SendThreadRundownEvent 0.0 5 0.0 0 0 ____..._________________________ 18,056.041 28,857.130
|| | + clr!ThreadStore::GetThreadList 0.0 1 0.0 0 0 ____.___________________________ 20,585.296 20,586.296
|| + ntdll!TppTimerpExecuteCallback 0.1 36 0.0 0 0 _______o_o____o_..___._o____o___ 30,825.329 122,770.341
|| + ntdll!NtWaitForWorkViaWorkerFactory 0.0 7 0.0 0 0 ______.._.______.__.__._________ 29,399.185 95,755.340
|| + ntdll!TppTimerQueueExpiration 0.0 3 0.0 1 0 ______________._.______.________ 63,750.336 102,745.350
|| + ntdll!TppIopExecuteCallback 0.0 1 0.0 0 0 ______________________________._ 129,363.361 129,364.361
|+ BROKEN 8.7 2,461 0.0 0 0 41ooooo_________________________ 503.287 28,702.109
|+ ntdll!LdrInitializeThunk 1.8 510 0.0 0 0 ___o000_________________________ 16,556.893 28,853.122
|+ ntdll!LdrpValidateUserCallTargetBitMapRet 0.0 3 0.0 3 0 ____.___________________________ 19,051.141 20,485.285
|+ ntdll!LdrpValidateUserCallTargetBitMapCheck 0.0 2 0.0 2 0 ____..__________________________ 21,231.361 23,006.539
+ Thread (13212) CPU=2856ms 10.0 2,837 0.0 0 0 __41____________________________ 10,031.248 13,781.614
+ Thread (13212) CPU=884ms 3.1 881 0.0 0 0 ___2____________________________ 14,521.697 15,804.816
+ Thread (13212) CPU=599ms 2.1 596 0.0 0 0 ___1____________________________ 13,781.616 14,521.697
+ Thread (13212) CPU=564ms 2.0 556 0.0 0 0 ___1____________________________ 15,804.817 16,506.888
Thank you all. I see it is assigned and tagged at milestone 9. Will it fix the NET Framework issue as well. I am assuming the issue is known at this point.
Is the only workaround is to disable the profiler? If there is any other workaround kindly let me know or something different I can do in the app that stands out in the trace. It's been source of continuous problems for us. Appreciate the help.
Hi @marafiq
Apologies for the confusion - the milestone that we added is for our tracking only. It just means that we are tracking the issue.
Looking at the CPU time for this trace is unlikely to help figure out the root cause since the application is not CPU bound. Would you be able to do a wall clock analysis as described here: https://learn.microsoft.com/en-us/shows/perfview-tutorial/tutorial-12-wall-clock-time-investigation-basics?
@davmason thanks. Let me try to do the analysis.
Analysis Using ASP.NET Thread Time With Tasks Stacks In the below screen shot, one request took ~ 71 seconds to complete. It is bundle request. Surprisingly the file size is only 799 B. All other requests seem to be doing okay in terms of response time. And there is no indication of ETW events/rundown in the stack trace of the thread which has the highest response time. The thread was blocked for ~ 71 seconds, pasting the trace below.
The next 3 most slow requests are waiting for query results thus not a concern for this trace.
Name Inc % Inc Inc Ct Exc % Exc Exc Ct Fold Fold Ct When First Last
+ Request ID 4000a067-0000-d000-b63f-84710c7967bb URL: GET('/Scripts/barcodelistener', 'v=ycTUTOVVo9ETq-VcoQm6jL0elaRSY4Znm7gGv3Sjx2E1') 100.0 71,580.813 13 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,882.522
+ Thread (936) CPU=1ms (Incoming Request Thread) 100.0 71,580.305 9 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,882.522
|+ ntdll!_RtlUserThreadStart 100.0 71,580.305 9 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,882.522
| + ntdll!__RtlUserThreadStart 100.0 71,580.305 9 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,882.522
| + kernel32!BaseThreadInitThunk 100.0 71,580.305 9 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,882.522
| + w3tp!THREAD_MANAGER::ThreadManagerThread 100.0 71,580.305 9 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,882.522
| + w3tp!THREAD_POOL_DATA::ThreadPoolThread 100.0 71,580.305 9 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,882.522
| + w3tp!THREAD_POOL_DATA::ThreadPoolThread 100.0 71,580.305 9 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,882.522
| + picohelper!? 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| |+ kernelbase!GetQueuedCompletionStatus 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntdll!NtRemoveIoCompletion 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntdll!LdrInitializeThunk 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntdll!LdrpInitializeInternal 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntdll!_LdrpInitialize 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + wow64!Wow64LdrpInitialize 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + wow64!RunCpuSimulation 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + wow64cpu!BTCpuSimulate 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + wow64cpu!RemoveIoCompletionFault 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + wow64cpu!CpupSyscallStub 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntoskrnl!KiSystemServiceCopyEnd 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntoskrnl!NtRemoveIoCompletion 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntoskrnl!IoRemoveIoCompletion 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntoskrnl!KeRemoveQueueEx 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntoskrnl!KiCommitThreadWait 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntoskrnl!KiSwapThread 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntoskrnl!KiSwapContext 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + ntoskrnl!SwapContext 100.0 71,579.742 2 0.0 0 0 0 0 ___99999999999999996____________ 13,302.218 84,881.958
| | + BLOCKED_TIME 100.0 71,579.227 1 100.0 71,579.227 1 0 0 ___99999999999999996____________ 13,302.218 84,881.444
| | + CPU_TIME 0.0 0.517 1 0.0 0.517 1 0 0 ___________________.____________ 84,881.440 84,881.958
| + w3dt!WP_CONTEXT::OnCompletion 0.0 0.565 7 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.522
| + w3dt!UL_RECEIVE_CONTEXT::DoWork 0.0 0.565 7 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.522
| + w3dt!UL_NATIVE_REQUEST::DoWork 0.0 0.565 7 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.522
| + iiscore!? 0.0 0.565 7 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.522
| + iisutil!LookupTokenAccountName 0.0 0.385 6 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.342
| |+ advapi32!LookupAccountSidW 0.0 0.385 6 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.342
| | + sechost!LookupAccountSidLocalW 0.0 0.385 6 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.342
| | + sechost!LookupAccountSidInternal 0.0 0.385 6 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.342
| | + sechost!LsaLookupClose 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | |+ rpcrt4!_NdrClientCall4 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + rpcrt4!_NdrClientCall2 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + rpcrt4!LRPC_CCALL::SendReceive 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + rpcrt4!LRPC_BASE_CCALL::DoSendReceive 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntdll!NtAlpcSendWaitReceivePort 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntdll!LdrInitializeThunk 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntdll!LdrpInitializeInternal 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntdll!_LdrpInitialize 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + wow64!Wow64LdrpInitialize 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + wow64!RunCpuSimulation 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + wow64cpu!BTCpuSimulate 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + wow64cpu!ServiceNoTurbo 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + wow64!Wow64SystemServiceEx 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + wow64!whNtAlpcSendWaitReceivePort 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntdll!NtAlpcSendWaitReceivePort 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!KiSystemServiceUser 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!PsSyscallProviderDispatch 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!PspSyscallProviderServiceDispatchGeneric 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + handlerc!? 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!NtAlpcSendWaitReceivePort 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!AlpcpProcessSynchronousRequest 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!AlpcpReceiveSynchronousReply 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!AlpcpSignalAndWait 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!KeWaitForSingleObject 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!KiCommitThreadWait 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!KiSwapThread 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!KiSwapContext 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + ntoskrnl!SwapContext 0.0 0.156 2 0.0 0 0 0 0 ___________________.____________ 84,882.186 84,882.342
| | | + CPU_TIME 0.0 0.121 1 0.0 0.121 1 0 0 ___________________.____________ 84,882.221 84,882.342
| | | + BLOCKED_TIME 0.0 0.035 1 0.0 0.035 1 0 0 ___________________.____________ 84,882.186 84,882.221
| | + sechost!LsaLookupOpenLocalPolicy 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | |+ rpcrt4!_NdrClientCall4 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + rpcrt4!_NdrClientCall2 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + rpcrt4!LRPC_CCALL::SendReceive 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + rpcrt4!LRPC_BASE_CCALL::DoSendReceive 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntdll!NtAlpcSendWaitReceivePort 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntdll!LdrInitializeThunk 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntdll!LdrpInitializeInternal 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntdll!_LdrpInitialize 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + wow64!Wow64LdrpInitialize 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + wow64!RunCpuSimulation 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + wow64cpu!BTCpuSimulate 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + wow64cpu!ServiceNoTurbo 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + wow64!Wow64SystemServiceEx 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + wow64!whNtAlpcSendWaitReceivePort 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntdll!NtAlpcSendWaitReceivePort 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!KiSystemServiceUser 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!PsSyscallProviderDispatch 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!PspSyscallProviderServiceDispatchGeneric 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + handlerc!? 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!NtAlpcSendWaitReceivePort 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!AlpcpProcessSynchronousRequest 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!AlpcpReceiveSynchronousReply 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!AlpcpSignalAndWait 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!KeWaitForSingleObject 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!KiCommitThreadWait 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!KiSwapThread 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!KiSwapContext 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + ntoskrnl!SwapContext 0.0 0.121 2 0.0 0 0 0 0 ___________________.____________ 84,881.958 84,882.079
| | | + BLOCKED_TIME 0.0 0.071 1 0.0 0.071 1 0 0 ___________________.____________ 84,881.958 84,882.028
| | | + CPU_TIME 0.0 0.051 1 0.0 0.051 1 0 0 ___________________.____________ 84,882.028 84,882.079
| | + sechost!LsaInternalClientLookupSids 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + rpcrt4!_NdrClientCall4 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + rpcrt4!_NdrClientCall2 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + rpcrt4!LRPC_CCALL::SendReceive 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + rpcrt4!LRPC_BASE_CCALL::DoSendReceive 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntdll!NtAlpcSendWaitReceivePort 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntdll!LdrInitializeThunk 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntdll!LdrpInitializeInternal 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntdll!_LdrpInitialize 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + wow64!Wow64LdrpInitialize 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + wow64!RunCpuSimulation 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + wow64cpu!BTCpuSimulate 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + wow64cpu!ServiceNoTurbo 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + wow64!Wow64SystemServiceEx 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + wow64!whNtAlpcSendWaitReceivePort 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntdll!NtAlpcSendWaitReceivePort 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!KiSystemServiceUser 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!PsSyscallProviderDispatch 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!PspSyscallProviderServiceDispatchGeneric 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + handlerc!? 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!NtAlpcSendWaitReceivePort 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!AlpcpProcessSynchronousRequest 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!AlpcpReceiveSynchronousReply 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!AlpcpSignalAndWait 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!KeWaitForSingleObject 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!KiCommitThreadWait 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!KiSwapThread 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!KiSwapContext 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + ntoskrnl!SwapContext 0.0 0.107 2 0.0 0 0 0 0 ___________________.____________ 84,882.079 84,882.186
| | + BLOCKED_TIME 0.0 0.057 1 0.0 0.057 1 0 0 ___________________.____________ 84,882.079 84,882.136
| | + CPU_TIME 0.0 0.050 1 0.0 0.050 1 0 0 ___________________.____________ 84,882.136 84,882.186
| + picohelper!? 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + kernelbase!CreateFileW 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + kernelbase!CreateFileInternal 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + picohelper!? 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntdll!NtCreateFile 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntdll!LdrInitializeThunk 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntdll!LdrpInitializeInternal 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntdll!_LdrpInitialize 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + wow64!Wow64LdrpInitialize 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + wow64!RunCpuSimulation 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + wow64cpu!BTCpuSimulate 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + wow64cpu!ServiceNoTurbo 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + wow64!Wow64SystemServiceEx 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + wow64!whNtCreateFile 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntdll!NtCreateFile 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!KiSystemServiceUser 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!PsSyscallProviderDispatch 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!PspSyscallProviderServiceDispatchGeneric 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + handlerc!? 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!KiServiceLinkage 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!KiSystemServiceCopyEnd 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!NtCreateFile 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!IopCreateFile 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!ObOpenObjectByNameEx 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!ObpLookupObjectName 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!IopParseDevice 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!IofCallDriver 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + fltmgr!FltpCreate 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + fltmgr!FltpPassThroughInternal 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + fltmgr!FltpPerformPreCallbacksWorker 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + ntoskrnl!ExAcquireRundownProtectionCacheAwareEx 0.0 0.180 1 0.0 0 0 0 0 ___________________.____________ 84,882.342 84,882.522
| + CPU_TIME 0.0 0.180 1 0.0 0.180 1 0 0 ___________________.____________ 84,882.342 84,882.522
+ Thread (22224) CPU=61ms (.NET ThreadPool Worker) 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ ntdll!_RtlUserThreadStart 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ ntdll!__RtlUserThreadStart 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ kernel32!BaseThreadInitThunk 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ clr!Thread::intermediateThreadProc 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ clr!ThreadpoolMgr::ExecuteWorkRequest 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ clr!UnManagedPerAppDomainTPCount::DispatchWorkItem 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ picohelper!? 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ webengine4!ProcessNotificationCallback 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ webengine4!W3_MGD_HANDLER::ProcessNotification 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ ?!? 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ clr!UM2MDoADCallBack 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ clr!Thread::DoADCallBack 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ clr!UM2MThunk_Wrapper 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ ?!? 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ system.web!PipelineRuntime.ProcessRequestNotification 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ system.web!PipelineRuntime.ProcessRequestNotificationHelper 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ system.web!PipelineRuntime.InitializeRequestContext 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ system.web!IIS7WorkerRequest.CreateWorkerRequest 0.0 0.508 4 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.818
+ system.web!IIS7WorkerRequest.ReadRequestBasics 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
|+ system.web!dynamicClass.IL_STUB_PInvoke(int,int32&,int32&,int&,int32&,int&,int32&,int&,int&) 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + webengine4!MgdGetRequestBasics 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + iiscore!? 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + nativerd!CONFIG_MAPPING_EXTENSION::MapPath 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + nativerd!CONFIG_SYSTEM::MapPath 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + nativerd!CONFIG_CACHE::MapPath 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + nativerd!CONFIG_PATH_MAPPER::MapPath 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + nativerd!CONFIG_PATH_MAPPER::MapPathFromParent 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + nativerd!CONFIG_VDIR::GetDirectory 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + nativerd!CONFIG_ELEMENT::GetStringProperty 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + nativerd!CONFIG_ELEMENT::GetInternalPropertyByName 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + ntoskrnl!KiVmbusInterruptDispatch 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + ntoskrnl!KiDpcInterruptBypass 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + ntoskrnl!KxDispatchInterrupt 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + ntoskrnl!SwapContext 0.0 0.280 2 0.0 0 0 0 0 ___.____________________________ 13,401.538 13,401.818
| + BLOCKED_TIME 0.0 0.162 1 0.0 0.162 1 0 0 ___.____________________________ 13,401.538 13,401.700
| + CPU_TIME 0.0 0.118 1 0.0 0.118 1 0 0 ___.____________________________ 13,401.700 13,401.818
+ system.web!System.Web.Hosting.IIS7WorkerRequest..ctor(int,bool) 0.0 0.228 2 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.538
+ clr!ThreadNative::FastGetDomain 0.0 0.228 2 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.538
+ ntoskrnl!KiVmbusInterruptDispatch 0.0 0.228 2 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.538
+ ntoskrnl!KiDpcInterruptBypass 0.0 0.228 2 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.538
+ ntoskrnl!KxDispatchInterrupt 0.0 0.228 2 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.538
+ ntoskrnl!SwapContext 0.0 0.228 2 0.0 0 0 0 0 ___.____________________________ 13,401.310 13,401.538
+ BLOCKED_TIME 0.0 0.143 1 0.0 0.143 1 0 0 ___.____________________________ 13,401.310 13,401.453
+ CPU_TIME 0.0 0.085 1 0.0 0.085 1 0 0 ___.____________________________ 13,401.453 13,401.538
I could not find any other reasons it was blocked, except that the thread 936 recorded - Compression Failure with Reason Code 14 occurred at 84,882.473 ms, that is when this request completed.
The thread 936 from Events received the CSwitch
Event Name Time MSec Process Name ActivityID ActivityInfo ContainerID DURATION__MSEC FormattedMessage HasBlockingStack HasStack NewProcessID NewProcessName NewThreadID Rest
Windows Kernel/Thread/CSwitch 84,881.440 w3wp (6008) Implied/TID=936/S=13301.417 False True 6,008 w3wp 936 ThreadID="936" ProcessorNumber="0" OldThreadID="22,124" OldProcessID="1,532" OldProcessName="DWASSVC" ProcessorNumber="0" NewThreadPriority="8" OldThreadPriority="10" NewThreadQuantum="0" OldThreadQuantum="0" OldThreadWaitReason="33" OldThreadWaitMode="Swappable" OldThreadState="Ready" OldThreadWaitIdealProcessor="1" NewThreadWaitTime="0" StartStopActivity="AspNetReq(4000a067-0000-d000-b63f-84710c7967bb,/Scripts/barcodelistener)/P=$"
Windows Kernel/Thread/CSwitch 84,882.028 w3wp (6008) Implied/TID=936/S=13301.417 False True 6,008 w3wp 936 ThreadID="936" ProcessorNumber="0" OldThreadID="10,252" OldProcessID="744" OldProcessName="lsass" ProcessorNumber="0" NewThreadPriority="9" OldThreadPriority="9" NewThreadQuantum="0" OldThreadQuantum="0" OldThreadWaitReason="15" OldThreadWaitMode="Swappable" OldThreadState="Wait" OldThreadWaitIdealProcessor="1" NewThreadWaitTime="0" StartStopActivity="AspNetReq(4000a067-0000-d000-b63f-84710c7967bb,/Scripts/barcodelistener)/P=$"
Windows Kernel/Thread/CSwitch 84,882.136 w3wp (6008) Implied/TID=936/S=13301.417 False True 6,008 w3wp 936 ThreadID="936" ProcessorNumber="0" OldThreadID="10,252" OldProcessID="744" OldProcessName="lsass" ProcessorNumber="0" NewThreadPriority="8" OldThreadPriority="9" NewThreadQuantum="0" OldThreadQuantum="0" OldThreadWaitReason="15" OldThreadWaitMode="Swappable" OldThreadState="Wait" OldThreadWaitIdealProcessor="1" NewThreadWaitTime="0" StartStopActivity="AspNetReq(4000a067-0000-d000-b63f-84710c7967bb,/Scripts/barcodelistener)/P=$"
Windows Kernel/Thread/CSwitch 84,882.221 w3wp (6008) Implied/TID=936/S=13301.417 False True 6,008 w3wp 936 ThreadID="936" ProcessorNumber="0" OldThreadID="10,252" OldProcessID="744" OldProcessName="lsass" ProcessorNumber="0" NewThreadPriority="9" OldThreadPriority="9" NewThreadQuantum="0" OldThreadQuantum="0" OldThreadWaitReason="15" OldThreadWaitMode="Swappable" OldThreadState="Wait" OldThreadWaitIdealProcessor="1" NewThreadWaitTime="0" StartStopActivity="AspNetReq(4000a067-0000-d000-b63f-84710c7967bb,/Scripts/barcodelistener)/P=$"
When I look at the CSwitch to Thread 936 time range, there are many calls to remove the IO seen for many threads. Including in case if it contains helpful trace.
Name Inc % Inc Inc Ct Exc % Exc Exc Ct Fold Fold Ct When First Last
+ Thread (21464) CPU=176ms (.NET IO ThreadPool Worker) 28.1 0.076 63 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
|+ module ntdll <<ntdll!_RtlUserThreadStart>> 28.1 0.076 63 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| + module kernel32 <<kernel32!BaseThreadInitThunk>> 28.1 0.076 63 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| + module clr <<clr!Thread::intermediateThreadProc>> 28.1 0.076 63 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| + module mscorlib.ni <<mscorlib.ni!_IOCompletionCallback.PerformIOCompletionCallback>> 27.7 0.074 62 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| |+ module System <<System!BaseOverlappedAsyncResult.CompletionPortCallback>> 27.7 0.074 62 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | + module mscorlib.ni <<mscorlib.ni!ExecutionContext.Run>> 27.7 0.074 62 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | + module System <<System!ContextAwareResult.CompleteCallback>> 27.7 0.074 62 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | + module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.TaskFactory`1+FromAsyncTrimPromise`1[System.Int32,System.__Canon].CompleteFromAsyncResult(System.IAsyncResult)>> 27.7 0.074 62 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | + module System <<System!System.Net.WebSockets.WebSocketConnectionStream+<ReadAsync>d__21.MoveNext()>> 26.3 0.071 59 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | |+ module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.Task`1[System.Int32].TrySetResult(Int32)>> 26.3 0.071 59 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | | + module System <<System!System.Net.WebSockets.WebSocketBase+WebSocketOperation+<Process>d__19.MoveNext()>> 26.3 0.071 59 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | | + module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.Task`1[System.__Canon].TrySetResult(System.__Canon)>> 26.3 0.071 59 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | | + module System <<System!System.Net.WebSockets.WebSocketBase+<ReceiveAsyncCore>d__45.MoveNext()>> 26.3 0.071 59 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | | + module mscorlib.ni <<mscorlib.ni!System.Threading.Tasks.Task`1[System.__Canon].TrySetResult(System.__Canon)>> 26.3 0.071 59 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | | + module microsoft.azure.signalr.common <<microsoft.azure.signalr.common!Microsoft.Azure.SignalR.Connections.Client.Internal.WebSocketsTransport+<StartReceiving>d__20.MoveNext()>> 20.1 0.054 45 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | | + module system.io.pipelines <<system.io.pipelines!System.IO.Pipelines.Pipe+DefaultPipeWriter.FlushAsync(value class System.Threading.CancellationToken)>> 6.2 0.017 14 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| | + module pipelines.sockets.unofficial <<pipelines.sockets.unofficial!Pipelines.Sockets.Unofficial.StreamConnection+AsyncStreamPipe+<CopyFromStreamToReadPipe>d__13.MoveNext()>> 1.3 0.004 3 0.0 0 0 0 0 9TTTTTTTTTTTTTTTTTTTTTTTTTTTTTTT 84,881.439 84,881.441
| + module picohelper <<picohelper!?>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module kernelbase <<kernelbase!GetQueuedCompletionStatus>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module ntdll <<ntdll!NtRemoveIoCompletion>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module wow64 <<wow64!Wow64LdrpInitialize>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module wow64cpu <<wow64cpu!BTCpuSimulate>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module ntoskrnl <<ntoskrnl!NtRemoveIoCompletion>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + BLOCKED_TIME 0.4 0.001 1 0.4 0.001 1 0 0 99999999999999999999999999999999 84,881.439 84,881.441
+ Thread (1608) CPU=189ms (.NET IO ThreadPool Worker) 11.2 0.030 25 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
|+ module ntdll <<ntdll!_RtlUserThreadStart>> 11.2 0.030 25 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| + module kernel32 <<kernel32!BaseThreadInitThunk>> 11.2 0.030 25 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| + module clr <<clr!Thread::intermediateThreadProc>> 11.2 0.030 25 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| + module mscorlib.ni <<mscorlib.ni!_IOCompletionCallback.PerformIOCompletionCallback>> 10.7 0.029 24 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
| + module picohelper <<picohelper!?>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module kernelbase <<kernelbase!GetQueuedCompletionStatus>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module ntdll <<ntdll!NtRemoveIoCompletion>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module wow64 <<wow64!Wow64LdrpInitialize>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module wow64cpu <<wow64cpu!BTCpuSimulate>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module ntoskrnl <<ntoskrnl!NtRemoveIoCompletion>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + BLOCKED_TIME 0.4 0.001 1 0.4 0.001 1 0 0 99999999999999999999999999999999 84,881.439 84,881.441
+ Thread (8928) CPU=215ms (.NET IO ThreadPool Worker) 10.3 0.028 23 0.0 0 0 0 0 9******************************* 84,881.439 84,881.441
+ Thread (12792) CPU=94ms (.NET ThreadPool Worker) 1.3 0.004 3 0.0 0 0 0 0 9TTTTTTTTTTTTTTTTTTTTTTTTTTTTTTT 84,881.439 84,881.441
+ Thread (10224) CPU=70ms (.NET ThreadPool Worker) 0.9 0.002 2 0.0 0 0 0 0 9JJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ 84,881.439 84,881.441
+ Thread (13296) CPU=134ms (.NET IO ThreadPool Worker) 0.9 0.002 2 0.0 0 0 0 0 9JJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ 84,881.439 84,881.441
+ Thread (7712) CPU=25ms 0.9 0.002 2 0.0 0 0 0 0 9JJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ 84,881.439 84,881.441
+ Thread (18632) CPU=128ms (.NET IO ThreadPool Worker) 0.9 0.002 2 0.0 0 0 0 0 9JJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ 84,881.439 84,881.441
|+ module ntdll <<ntdll!_RtlUserThreadStart>> 0.9 0.002 2 0.0 0 0 0 0 9JJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ 84,881.439 84,881.441
| + module kernel32 <<kernel32!BaseThreadInitThunk>> 0.9 0.002 2 0.0 0 0 0 0 9JJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ 84,881.439 84,881.441
| + module clr <<clr!Thread::intermediateThreadProc>> 0.9 0.002 2 0.0 0 0 0 0 9JJJJJJJJJJJJJJJJJJJJJJJJJJJJJJJ 84,881.439 84,881.441
| + module mscorlib.ni <<mscorlib.ni!_IOCompletionCallback.PerformIOCompletionCallback>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module picohelper <<picohelper!?>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module kernelbase <<kernelbase!GetQueuedCompletionStatus>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module ntdll <<ntdll!NtRemoveIoCompletion>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module wow64 <<wow64!Wow64LdrpInitialize>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module wow64cpu <<wow64cpu!BTCpuSimulate>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + module ntoskrnl <<ntoskrnl!NtRemoveIoCompletion>> 0.4 0.001 1 0.0 0 0 0 0 99999999999999999999999999999999 84,881.439 84,881.441
| + BLOCKED_TIME 0.4 0.001 1 0.4 0.001 1 0 0 99999999999999999999999999999999 84,881.439 84,881.441
When looking from the context of HTTP Requests, it seems ETW is not a factor here. Can you help me interpret why a bundle request took 71 - and help explaining the role of piochelper
as I see it in other traces as well?
I am not sure how I would find out who was blocking the request.
Sorry, I have few more questions. In multiple threads I see RareDisablePreemptiveGC
calls.
Under what conditions GC gets disabled or what the below call stack means when you find rare disable RareDisablePreemptiveGC call in call stack?
Below stack traces from a different profile trace taken today experiencing slowdown - but the same application
Partial Stack Traces of Possible GC Disable - Few threads have ETW thread before it got triggered.
Name Inc % Inc Inc Ct Exc % Exc Exc Ct Fold Fold Ct When First Last
||| | | | | ||| | | | || | | || | || | + mscorlib.ni!System.Runtime.CompilerServices.TaskAwaiter+<>c__DisplayClass11_0.<OutputWaitEtwEvents>b__0() 0.0 113.718 6 0.0 0 0 0 0 ____________0.__________________ 25,695.588 27,341.958
||| | | | | ||| | | | || | | || | || | |+ mscorlib.ni!TplEtwProvider.TaskWaitEnd 0.0 113.718 6 0.0 0 0 0 0 ____________0.__________________ 25,695.588 27,341.958
||| | | | | ||| | | | || | | || | || | | + mscorlib.ni!EventSource.WriteEvent 0.0 113.718 6 0.0 0 0 0 0 ____________0.__________________ 25,695.588 27,341.958
||| | | | | ||| | | | || | | || | || | | + mscorlib.ni!EventSource.WriteEventWithRelatedActivityIdCore 0.0 113.718 6 0.0 0 0 0 0 ____________0.__________________ 25,695.588 27,341.958
||| | | | | ||| | | | || | | || | || | | + mscorlib.ni!Microsoft.Win32.UnsafeNativeMethods+ManifestEtw.EventWriteTransferWrapper(Int64, System.Diagnostics.Tracing.EventDescriptor ByRef, System.Guid*, System.Guid*, Int32, EventData*) 0.0 113.718 6 0.0 0 0 0 0 ____________0.__________________ 25,695.588 27,341.958
||| | | | | ||| | | | || | | || | || | | + mscorlib.ni!DomainNeutralILStubClass.IL_STUB_PInvoke(Int64, System.Diagnostics.Tracing.EventDescriptor ByRef, System.Guid*, System.Guid*, Int32, EventData*) 0.0 113.718 6 0.0 0 0 0 0 ____________0.__________________ 25,695.588 27,341.958
||| | | | | ||| | | | || | | || | || | | + clr!JIT_RareDisableHelper 0.0 113.626 4 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,809.215
||| | | | | ||| | | | || | | || | || | | |+ clr!JIT_RareDisableHelperWorker 0.0 113.626 4 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,809.215
||| | | | | ||| | | | || | | || | || | | | + clr!??Thread::RareDisablePreemptiveGC 0.0 113.626 4 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,809.215
||| | | | | ||| | | | || | | || | || | | | + kernelbase!SwitchToThread 0.0 82.061 2 0.0 0 0 0 0 ____________0___________________ 25,727.153 25,809.215
||| | | | | ||| | | | || | | || | || | | | |+ ntdll!RtlDelayExecution 0.0 82.061 2 0.0 0 0 0 0 ____________0___________________ 25,727.153 25,809.215
||| | | | | ||| | | | || | | || | || | | | | + ntdll!NtDelayExecution 0.0 82.061 2 0.0 0 0 0 0 ____________0___________________ 25,727.153 25,809.215
||| | | | | ||| | | | || | | || | || | | | | + ntoskrnl!? 0.0 82.061 2 0.0 0 0 0 0 ____________0___________________ 25,727.153 25,809.215
||| | | | | ||| | | | || | | || | || | | | | + BLOCKED_TIME 0.0 82.017 1 0.0 82.017 1 0 0 ____________0___________________ 25,727.153 25,809.170
||| | | | | ||| | | | || | | || | || | | | | + CPU_TIME 0.0 0.045 1 0.0 0.045 1 0 0 ____________.___________________ 25,809.170 25,809.215
||| | | | | ||| | | | || | | || | || | | | + clr!SVR::GCHeap::WaitUntilGCComplete 0.0 31.565 2 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,727.153
||| | | | | ||| | | | || | | || | || | | | + clr!CLREventBase::WaitEx 0.0 31.565 2 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,727.153
||| | | | | ||| | | | || | | || | || | | | + clr!CLREventWaitHelper 0.0 31.565 2 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,727.153
||| | | | | ||| | | | || | | || | || | | | + clr!CLREventWaitHelper2 0.0 31.565 2 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,727.153
||| | | | | ||| | | | || | | || | || | | | + kernelbase!WaitForSingleObjectEx 0.0 31.565 2 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,727.153
||| | | | | ||| | | | || | | || | || | | | + ntdll!NtWaitForSingleObject 0.0 31.565 2 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,727.153
||| | | | | ||| | | | || | | || | || | | | + ntoskrnl!? 0.0 31.565 2 0.0 0 0 0 0 ____________0___________________ 25,695.588 25,727.153
||| | | | | ||| | | | || | | || | || | | | + BLOCKED_TIME 0.0 31.543 1 0.0 31.543 1 0 0 ____________0___________________ 25,695.588 25,727.132
||| | | | | ||| | | | || | | || | || | | | + CPU_TIME 0.0 0.022 1 0.0 0.022 1 0 0 ____________.___________________ 25,727.132 25,727.153
||| | | | | ||| | | | || | | || | || | | + ntdll!EtwEventWriteTransfer 0.0 0.091 2 0.0 0 0 0 0 _____________.__________________ 27,341.867 27,341.958
||| | | | | ||| | | | || | | || | || | | + ntdll!NtTraceEvent 0.0 0.091 2 0.0 0 0 0 0 _____________.__________________ 27,341.867 27,341.958
||| | | | | ||| | | | || | | || | || | | + ntoskrnl!? 0.0 0.091 2 0.0 0 0 0 0 _____________.__________________ 27,341.867 27,341.958
||| | | | | ||| | | | || | | || | || | | + handlerc!? 0.0 0.091 2 0.0 0 0 0 0 _____________.__________________ 27,341.867 27,341.958
||| | | | | ||| | | | || | | || | || | | + ntoskrnl!? 0.0 0.091 2 0.0 0 0 0 0 _____________.__________________ 27,341.867 27,341.958
||| | | | | ||| | | | || | | || | || | | + CPU_TIME 0.0 0.087 1 0.0 0.087 1 0 0 _____________.__________________ 27,341.871 27,341.958
||| | | | | ||| | | | || | | || | || | | + BLOCKED_TIME 0.0 0.005 1 0.0 0.005 1 0 0 _____________.__________________ 27,341.867 27,341.871
Name Inc % Inc Inc Ct Exc % Exc Exc Ct Fold Fold Ct When First Last
| | | | | ||| || | | ||| | | ||| |||||+ System.Web.Mvc!RouteCollectionExtensions.FilterRouteCollectionByArea 0.0 561.147 974 0.0 0 0 0 0 _______0110_____________________ 16,510.317 21,489.599
| | | | | ||| || | | ||| | | ||| ||||||+ System.Web.Mvc!AreaHelpers.GetAreaName 0.0 346.885 567 0.0 0 0 0 0 _______o00o_____________________ 16,510.317 21,488.816
| | | | | ||| || | | ||| | | ||| |||||||+ mscorlib.ni!System.Collections.Generic.Dictionary`2[System.__Canon,System.__Canon].FindEntry(System.__Canon) 0.0 204.738 237 0.0 0 0 0 0 _______o00o_____________________ 16,512.317 21,488.816
| | | | | ||| || | | ||| | | ||| ||||||||+ clr!RedirectedHandledJITCaseForGCThreadControl_Stub 0.0 103.458 5 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,987.600
| | | | | ||| || | | ||| | | ||| |||||||||+ clr!Thread::RedirectedHandledJITCase 0.0 103.458 5 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,987.600
| | | | | ||| || | | ||| | | ||| ||||||||| + clr!??Thread::RareDisablePreemptiveGC 0.0 103.458 5 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,987.600
| | | | | ||| || | | ||| | | ||| ||||||||| + clr!SVR::GCHeap::WaitUntilGCComplete 0.0 75.509 2 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,959.651
| | | | | ||| || | | ||| | | ||| ||||||||| |+ clr!CLREventBase::WaitEx 0.0 75.509 2 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,959.651
| | | | | ||| || | | ||| | | ||| ||||||||| | + clr!CLREventWaitHelper 0.0 75.509 2 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,959.651
| | | | | ||| || | | ||| | | ||| ||||||||| | + clr!CLREventWaitHelper2 0.0 75.509 2 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,959.651
| | | | | ||| || | | ||| | | ||| ||||||||| | + kernelbase!WaitForSingleObjectEx 0.0 75.509 2 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,959.651
| | | | | ||| || | | ||| | | ||| ||||||||| | + ntdll!NtWaitForSingleObject 0.0 75.509 2 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,959.651
| | | | | ||| || | | ||| | | ||| ||||||||| | + ntoskrnl!? 0.0 75.509 2 0.0 0 0 0 0 ________0_______________________ 16,884.142 16,959.651
| | | | | ||| || | | ||| | | ||| ||||||||| | + BLOCKED_TIME 0.0 75.463 1 0.0 75.463 1 0 0 ________0_______________________ 16,884.142 16,959.605
| | | | | ||| || | | ||| | | ||| ||||||||| | + CPU_TIME 0.0 0.046 1 0.0 0.046 1 0 0 ________._______________________ 16,959.605 16,959.651
| | | | | ||| || | | ||| | | ||| ||||||||| + kernelbase!SwitchToThread 0.0 27.949 3 0.0 0 0 0 0 ________0_______________________ 16,959.651 16,987.600
| | | | | ||| || | | ||| | | ||| ||||||||| + ntdll!RtlDelayExecution 0.0 27.949 3 0.0 0 0 0 0 ________0_______________________ 16,959.651 16,987.600
| | | | | ||| || | | ||| | | ||| ||||||||| + ntdll!NtDelayExecution 0.0 27.949 3 0.0 0 0 0 0 ________0_______________________ 16,959.651 16,987.600
| | | | | ||| || | | ||| | | ||| ||||||||| + ntoskrnl!? 0.0 27.949 3 0.0 0 0 0 0 ________0_______________________ 16,959.651 16,987.600
| | | | | ||| || | | ||| | | ||| ||||||||| + BLOCKED_TIME 0.0 27.664 1 0.0 27.664 1 0 0 ________0_______________________ 16,959.651 16,987.315
| | | | | ||| || | | ||| | | ||| ||||||||| + CPU_TIME 0.0 0.284 2 0.0 0.284 2 0 0 ________._______________________ 16,987.315 16,987.600
| | | | | ||| || | | ||| | | ||| ||||||||+ CPU_TIME 0.0 52.417 76 0.0 52.417 76 0 0 _______oo0o_____________________ 16,512.317 21,488.816
| | | | | ||| || | | ||| | | ||| ||||||||+ ntoskrnl!? 0.0 28.678 110 0.0 0 0 0 0 ________oo______________________ 16,875.408 20,875.755
| | | | | ||| || | | ||| | | ||| |||||||||+ BLOCKED_TIME 0.0 17.132 55 0.0 17.132 55 0 0 ________oo______________________ 16,875.408 20,874.862
| | | | | ||| || | | ||| | | ||| |||||||||+ CPU_TIME 0.0 11.546 55 0.0 11.546 55 0 0 ________oo______________________ 16,875.414 20,875.755
| | | | | ||| || | | ||| | | ||| ||||||||+ mscorlib.ni!OrdinalComparer.GetHashCode 0.0 20.185 46 0.0 0 0 0 0 _______.oo._____________________ 16,747.342 21,397.194
| | | | | ||| || | | ||| | | ||| |||||||| + mscorlib.ni!TextInfo.GetCaseInsensitiveHashCode 0.0 16.557 40 0.0 0 0 0 0 _______.oo._____________________ 16,747.342 21,397.194
| | | | | ||| || | | ||| | | ||| |||||||| + CPU_TIME 0.0 2.409 3 0.0 2.409 3 0 0 _________o______________________ 20,019.668 20,979.174
| | | | | ||| || | | ||| | | ||| |||||||| + mscorlib.ni!TextInfo.get_Invariant 0.0 1.220 3 0.0 0 0 0 0 _________.______________________ 20,058.438 20,350.704
| | | | | ||| || | | ||| | | ||| |||||||+ CPU_TIME 0.0 50.180 69 0.0 50.180 69 0 0 _______oo0._____________________ 16,510.317 21,483.816
| | | | | ||| || | | ||| | | ||| |||||||+ clr!JIT_IsInstanceOfInterface 0.0 49.471 117 0.0 0 0 0 0 _______.o0._____________________ 16,663.333 21,478.494
| | | | | ||| || | | ||| | | ||| |||||||+ ntoskrnl!? 0.0 42.496 144 0.0 0 0 0 0 _______o0o._____________________ 16,673.434 21,470.126
| | | | | ||| || | | ||| | | ||| ||||||+ system.web!RouteCollection.InsertItem 0.0 194.472 350 0.0 0 0 0 0 _______000o_____________________ 16,511.318 21,489.599
| | | | | ||| || | | ||| | | ||| ||||||+ mscorlib.ni!System.Collections.Generic.List`1+Enumerator[System.__Canon].MoveNext() 0.0 8.735 21 0.0 0 0 0 0 ________oo._____________________ 17,127.379 20,990.765
| | | | | ||| || | | ||| | | ||| ||||||+ mscorlib.ni!String.Equals 0.0 5.434 19 0.0 0 0 0 0 _______...._____________________ 16,704.414 21,396.755
| | | | | ||| || | | ||| | | ||| ||||||+ ntoskrnl!? 0.0 2.951 11 0.0 0 0 0 0 _________.._____________________ 19,292.225 21,424.810
| | | | | ||| || | | ||| | | ||| ||||||+ CPU_TIME 0.0 1.632 3 0.0 1.632 3 0 0 _______.._._____________________ 16,706.336 21,425.302
| | | | | ||| || | | ||| | | ||| ||||||+ mscorlib.ni!String.EqualsIgnoreCaseAsciiHelper 0.0 0.763 1 0.0 0 0 0 0 ________._______________________ 18,778.544 18,779.307
| | | | | ||| || | | ||| | | ||| ||||||+ mscorlib.ni!System.Collections.Generic.List`1[System.__Canon].System.Collections.Generic.IEnumerable.GetEnumerator() 0.0 0.276 2 0.0 0 0 0 0 __________._____________________ 21,418.532 21,418.808
| | | | | ||| || | | ||| | | ||| |||||+ system.web!System.Web.Routing.RouteValueDictionary..ctor(class System.Collections.Generic.IDictionary`2) 0.0 0.075 1 0.0 0 0 0 0 _________.______________________ 19,783.646 19,783.721
| | | | | ||| || | | ||| | | ||| ||||+ System.Web.WebPages!UrlUtil.GenerateClientUrl 0.0 1.694 4 0.0 0 0 0 0 ________..______________________ 17,000.750 19,274.670
| | | | | ||| || | | ||| | | ||| |||+ System.Web.Mvc!AjaxExtensions.GenerateLink 0.0 0.846 3 0.0 0 0 0 0 ________._______________________ 17,120.379 17,183.077
| | | | | ||| || | | ||| | | ||| ||+ system.web!RouteValueDictionary.AddValues 0.0 6.677 9 0.0 0 0 0 0 _______._o______________________ 16,704.337 19,959.072
Another partial stack trace under Blocked Time - Callers - This happens when I have JIT time crossing more than a second for a method.
Name Inc % Inc Inc Ct Exc % Exc Exc Ct Fold Fold Ct When First Last
||| |+ clr!SVR::GCHeap::GarbageCollectGeneration 0.1 1,491.664 3 0.0 0 0 0 0 _____________21994__799999999995 2,159.377 4,083.171
||| | + clr!SVR::gc_heap::trigger_gc_for_alloc 0.1 1,491.664 3 0.0 0 0 0 0 _____________21994__799999999995 2,159.377 4,083.171
||| | + clr!SVR::gc_heap::try_allocate_more_space 0.1 1,491.664 3 0.0 0 0 0 0 _____________21994__799999999995 2,159.377 4,083.171
||| | + clr!SVR::gc_heap::allocate_more_space 0.1 1,491.664 3 0.0 0 0 0 0 _____________21994__799999999995 2,159.377 4,083.171
||| | + clr!??SVR::GCHeap::Alloc 0.1 1,491.664 3 0.0 0 0 0 0 _____________21994__799999999995 2,159.377 4,083.171
||| | + clr!JIT_New 0.1 1,491.664 3 0.0 0 0 0 0 _____________21994__799999999995 2,159.377 4,083.171
||| | + system.web!CacheInternal.DoInsert 0.1 1,192.660 1 0.0 0 0 0 0 ____________________799999999995 2,890.512 4,083.171
||| | + mscorlib.ni!System.Collections.Generic.List`1[System.__Canon].System.Collections.Generic.IEnumerable.GetEnumerator() 0.0 299.005 2 0.0 0 0 0 0 _____________21994______________ 2,159.377 2,605.213
||| + clr!SVR::gc_heap::gc_thread_function 0.8 11,708.686 16 0.0 0 0 0 0 9************V*TTR**WTTTTTTTTTTP 769.564 4,128.766
||| |+ clr!SVR::gc_heap::gc_thread_stub 0.8 11,708.686 16 0.0 0 0 0 0 9************V*TTR**WTTTTTTTTTTP 769.564 4,128.766
||| | + clr!<lambda_f4a83ef2357e8af94a7c50f2736987d6>::<lambda_invoker_cdecl> 0.8 11,708.686 16 0.0 0 0 0 0 9************V*TTR**WTTTTTTTTTTP 769.564 4,128.766
||| | + kernel32!BaseThreadInitThunk 0.8 11,708.686 16 0.0 0 0 0 0 9************V*TTR**WTTTTTTTTTTP 769.564 4,128.766
||| | + ntdll!RtlUserThreadStart 0.8 11,708.686 16 0.0 0 0 0 0 9************V*TTR**WTTTTTTTTTTP 769.564 4,128.766
||| | + Thread (7736) CPU=1923ms 0.2 3,296.812 4 0.0 0 0 0 0 99999999999997999799999999999998 769.564 4,128.766
||| | + Thread (5192) CPU=2242ms 0.2 3,271.787 4 0.0 0 0 0 0 99999999999997999799999999999996 769.564 4,128.766
||| | + Thread (3580) CPU=2533ms 0.2 3,268.875 4 0.0 0 0 0 0 99999999999997999799999999999996 769.564 4,128.766
||| | + Thread (4128) CPU=2226ms (.NET Server GC Thread(0)) 0.1 1,871.212 4 0.0 0 0 0 0 999999999999978__5992__________4 769.564 4,128.766
||| + clr!SVR::GCHeap::WaitUntilGCComplete 0.2 3,146.547 25 0.0 0 0 0 0 _____________1__8C__799HJJJSTo*Y 2,171.206 4,079.555
||| |+ clr!??Thread::RareDisablePreemptiveGC 0.2 3,146.547 25 0.0 0 0 0 0 _____________1__8C__799HJJJSTo*Y 2,171.206 4,079.555
||| | + clr!??Thread::DoAppropriateWaitWorker 0.1 1,785.357 5 0.0 0 0 0 0 ________________84_____7999IJo*L 2,465.145 4,079.544
||| | |+ clr!Thread::DoAppropriateWait 0.1 1,785.357 5 0.0 0 0 0 0 ________________84_____7999IJo*L 2,465.145 4,079.544
||| | | + clr!WaitHandleNative::CorWaitMultipleNative 0.1 1,462.866 3 0.0 0 0 0 0 ________________84_____7999IJJJA 2,465.145 4,079.544
||| | | |+ mscorlib.ni!WaitHandle.WaitAny 0.1 1,462.866 3 0.0 0 0 0 0 ________________84_____7999IJJJA 2,465.145 4,079.544
||| | | | + mscorlib.ni!WaitHandle.WaitAny 0.1 1,462.866 3 0.0 0 0 0 0 ________________84_____7999IJJJA 2,465.145 4,079.544
||| | | | + Hangfire.Pro.Redis!RedisConnection.TrySubscriptionBasedFetch 0.1 864.419 1 0.0 0 0 0 0 _______________________799999995 3,215.124 4,079.544
||| | | | + Hangfire.Pro.Redis!RedisStorage.ConnectLoop 0.0 598.446 2 0.0 0 0 0 0 ________________84_________89995 2,465.145 4,079.541
||| | | + clr!WaitHandleNative::CorWaitOneNative 0.0 322.492 2 0.0 0 0 0 0 _____________________________oJA 3,918.274 4,079.539
||| | | + mscorlib.ni!WaitHandle.InternalWaitOne 0.0 322.492 2 0.0 0 0 0 0 _____________________________oJA 3,918.274 4,079.539
||| | | + mscorlib.ni!WaitHandle.WaitOne 0.0 322.492 2 0.0 0 0 0 0 _____________________________oJA 3,918.274 4,079.539
||| | | + mscorlib.ni!WaitHandle.WaitOne 0.0 322.492 2 0.0 0 0 0 0 _____________________________oJA 3,918.274 4,079.539
||| | | + Hangfire.Pro.Redis!CancellationTokenExtentions.Wait 0.0 161.265 1 0.0 0 0 0 0 _____________________________o95 3,918.274 4,079.539
||| | | + Hangfire.Core!CancellationTokenExtentions.Wait 0.0 161.227 1 0.0 0 0 0 0 _____________________________o95 3,918.297 4,079.524
||| | + clr!JIT_RareDisableHelperWorker 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | |+ clr!JIT_RareDisableHelper 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!PerfCounters.IncrementCounter 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!CacheSingle.UpdateCache 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!CacheInternal.DoInsert 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!AspNetCache.Add 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!Cache.Add 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + System.Web.WebPages!BuildManagerWrapper.ExistsInPrecompiledSite 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + System.Web.WebPages!VirtualPathFactoryManager.Exists 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + System.Web.WebPages!DefaultDisplayMode.GetDisplayInfo 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + System.Web.WebPages!DisplayModeProvider.GetDisplayInfoForVirtualPath 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + System.Web.WebPages!WebPageRoute.GetRouteLevelMatch 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + System.Web.WebPages!WebPageRoute.MatchRequest 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + System.Web.WebPages!WebPageRoute.DoPostResolveRequestCache 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!System.Web.HttpApplication+SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!System.Web.HttpApplication+<>c__DisplayClass285_0.<ExecuteStepImpl>b__0() 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!HttpApplication.ExecuteStepImpl 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!HttpApplication.ExecuteStep 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!System.Web.HttpApplication+PipelineStepManager.ResumeSteps(class System.Exception) 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!HttpApplication.BeginProcessRequestNotification 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!HttpRuntime.ProcessRequestNotificationPrivate 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!PipelineRuntime.ProcessRequestNotificationHelper 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!PipelineRuntime.ProcessRequestNotification 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!dynamicClass.IL_STUB_ReversePInvoke(int64,int64,int64,int32) 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!UMThunkStub 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + webengine4!W3_MGD_HANDLER::ProcessNotification 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + webengine4!W3_MGD_HANDLER::DoWork 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + webengine4!RequestDoWork 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + webengine4!CMgdEngHttpModule::OnResolveRequestCache 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + iiscore!? 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + webengine4!W3_MGD_HANDLER::IndicateCompletion 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + webengine4!MgdIndicateCompletion 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!dynamicClass.IL_STUB_PInvoke(int,value class System.Web.RequestNotificationStatus&) 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!PipelineRuntime.ProcessRequestNotificationHelper 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!PipelineRuntime.ProcessRequestNotification 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + system.web!dynamicClass.IL_STUB_ReversePInvoke(int64,int64,int64,int32) 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!UM2MThunk_WrapperHelper 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!UM2MThunk_Wrapper 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!Thread::DoADCallBack 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!UM2MDoADCallBack 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!UMThunkStub 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + webengine4!W3_MGD_HANDLER::ProcessNotification 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + webengine4!ProcessNotificationCallback 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!UnManagedPerAppDomainTPCount::DispatchWorkItem 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!ThreadpoolMgr::ExecuteWorkRequest 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!ThreadpoolMgr::WorkerThreadStart 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + clr!Thread::intermediateThreadProc 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + kernel32!BaseThreadInitThunk 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + ntdll!RtlUserThreadStart 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + Thread (9684) CPU=178ms (.NET ThreadPool Worker) 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + Not In Requests 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + Process64 w3wp (16160) Args: -ap "e" -v "v4.0" -a "\\.\pipe\iisipmc18cc5e0-6460-4204-9ab9-51ea11ccf50e" -h "D:\DWASFiles\Sites\ent\Config\applicationhost.config" -w "D:\DWASFiles\Sites\enusc\Config\rootweb.config" -m 0 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | | + ROOT 0.1 1,188.994 1 0.0 0 0 0 0 ____________________799999999995 2,890.561 4,079.555
||| | + clr!??invokeCompileMethod 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | |+ clr!CallCompileMethodWithSEHWrapper 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | | + clr!??UnsafeJitFunction 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | | + clr!MethodDesc::MakeJitWorker 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | | + clr!??MethodDesc::DoPrestub 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | | + clr!ReflectionInvocation::CompileMethod 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | | + mscorlib.ni!DomainNeutralILStubClass.IL_STUB_ReversePInvoke(IntPtr, System.StubHelpers.NativeVariant) 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | | + mscorlib.ni!DynamicMethod.CreateDelegate 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | | + System.Core!LambdaCompiler.Compile 0.0 133.616 16 0.0 0 0 0 0 _________________0_____________6 2,593.134 4,079.509
||| | | + system.data.linq!System.Data.Linq.SqlClient.Funcletizer+Localizer.MakeLocal(class System.Linq.Expressions.Expression) 0.0 108.654 13 0.0 0 0 0 0 _________________0_____________5 2,593.134 4,079.509
||| | | + EntityFramework!QueryParameterExpression.EvaluateParameter 0.0 17.341 2 0.0 0 0 0 0 _________________0_____________0 2,597.296 4,079.503
||| | | + EntityFramework!System.Data.Entity.Core.Objects.ELinq.Funcletizer+FuncletizingVisitor.CompileExpression(class System.Linq.Expressions.Expression) 0.0 7.621 1 0.0 0 0 0 0 _________________0______________ 2,597.670 2,605.291
||| | + clr!??CrstBase::Enter 0.0 27.248 2 0.0 0 0 0 0 _________________1_____________1 2,591.958 4,079.456
||| | + clr!??FinalizerThread::FinalizerThreadWorker 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + clr!ManagedThreadBase_DispatchInner 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + clr!ManagedThreadBase_DispatchMiddle 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + clr!??ManagedThreadBase_DispatchOuter 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + clr!FinalizerThread::FinalizerThreadStart 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + clr!Thread::intermediateThreadProc 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + kernel32!BaseThreadInitThunk 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + ntdll!RtlUserThreadStart 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + Thread (13340) CPU=168ms (.NET Finalizer Thread) 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + Not In Requests 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + Process64 w3wp (16160) Args: -ap "entc" -v "v4.0" -a "\\.\pipe\iisipmc18cc5e0-6460-4204-9ab9-51ea11ccf50e" -h "D:\DWASFiles\Sites\ent-c\Config\applicationhost.config" -w "D:\DWASFiles\Sites\enprd-usc\Config\rootweb.config" -m 0 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| | + ROOT 0.0 11.332 1 0.0 0 0 0 0 _____________1__________________ 2,171.206 2,182.538
||| + clr!??ThreadSuspend::SuspendRuntime 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| |+ clr!ThreadSuspend::SuspendEE 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + clr!SVR::gc_heap::gc_thread_function 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + clr!SVR::gc_heap::gc_thread_stub 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + clr!<lambda_f4a83ef2357e8af94a7c50f2736987d6>::<lambda_invoker_cdecl> 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + kernel32!BaseThreadInitThunk 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + ntdll!RtlUserThreadStart 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + Thread (4128) CPU=2226ms (.NET Server GC Thread(0)) 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + Not In Requests 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + Process64 w3wp (16160) Args: -ap "en-usc" -v "v4.0" -a "\\.\pipe\iisipmc18cc5e0-6460-4204-9ab9-51ea11ccf50e" -h "D:\DWASFile" -w "D:\DWASFiles\Sites\e-usc\Config\rootweb.config" -m 0 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| | + ROOT 0.1 1,417.750 95 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.474
||| + clr!FinalizerThread::WaitForFinalizerEvent 0.1 1,401.616 1 0.0 0 0 0 0 99999999999993__________________ 769.564 2,171.180
||| + clr!SVR::t_join::join 0.0 75.131 107 0.0 0 0 0 0 _____________o___1_____________1 2,159.629 4,079.372
In multiple threads I see RareDisablePreemptiveGC calls.
If you see a thread waiting in RareDisablePreemptiveGC, it means that there is GC running on some other thread and this thread is waiting for that GC to finish.
Thank you @jkotas One of the GC thread has the below stack trace. is it blocked? Callstack seems very similar to https://github.com/dotnet/runtime/issues/67559
Name Inc % Inc Inc Ct Exc % Exc Exc Ct Fold Fold Ct When First Last
+ Thread (4128) CPU=2226ms (.NET Server GC Thread(0)) 0.2 3,359.201 694 0.0 0 0 0 0 99999999999999A99A9999AA9A99A9A9 769.564 4,128.766
|+ ntdll!RtlUserThreadStart 0.2 3,359.201 694 0.0 0 0 0 0 99999999999999A99A9999AA9A99A9A9 769.564 4,128.766
| + kernel32!BaseThreadInitThunk 0.2 3,359.201 694 0.0 0 0 0 0 99999999999999A99A9999AA9A99A9A9 769.564 4,128.766
| + clr!<lambda_f4a83ef2357e8af94a7c50f2736987d6>::<lambda_invoker_cdecl> 0.2 3,359.201 694 0.0 0 0 0 0 99999999999999A99A9999AA9A99A9A9 769.564 4,128.766
| + clr!SVR::gc_heap::gc_thread_stub 0.2 3,359.201 694 0.0 0 0 0 0 99999999999999A99A9999AA9A99A9A9 769.564 4,128.766
| + clr!SVR::gc_heap::gc_thread_function 0.2 3,359.201 694 0.0 0 0 0 0 99999999999999A99A9999AA9A99A9A9 769.564 4,128.766
| + clr!CLREventBase::WaitEx 0.1 1,871.570 7 0.0 0 0 0 0 999999999999978__5992__________4 769.564 4,128.766
| |+ clr!CLREventWaitHelper 0.1 1,871.570 7 0.0 0 0 0 0 999999999999978__5992__________4 769.564 4,128.766
| | + clr!CLREventWaitHelper2 0.1 1,871.570 7 0.0 0 0 0 0 999999999999978__5992__________4 769.564 4,128.766
| | + kernelbase!WaitForSingleObjectEx 0.1 1,871.570 7 0.0 0 0 0 0 999999999999978__5992__________4 769.564 4,128.766
| | + ntdll!NtWaitForSingleObject 0.1 1,871.570 7 0.0 0 0 0 0 999999999999978__5992__________4 769.564 4,128.766
| | + ntoskrnl!? 0.1 1,871.570 7 0.0 0 0 0 0 999999999999978__5992__________4 769.564 4,128.766
| | + BLOCKED_TIME 0.1 1,871.212 4 0.1 1,871.212 4 0 0 999999999999978__5992__________4 769.564 4,128.766
| | + CPU_TIME 0.0 0.358 3 0.0 0.358 3 0 0 _____________o._____.___________ 2,159.380 2,890.568
| + clr!ThreadSuspend::SuspendEE 0.1 1,438.634 591 0.0 0 0 0 0 ______________1993__79AA9A99A9A3 2,329.428 4,065.707
| |+ clr!??ThreadSuspend::SuspendRuntime 0.1 1,438.634 591 0.0 0 0 0 0 ______________1993__79AA9A99A9A3 2,329.428 4,065.707
| | + clr!CLREventBase::WaitEx 0.1 1,421.426 191 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.707
| | |+ clr!CLREventWaitHelper 0.1 1,421.426 191 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.707
| | | + clr!CLREventWaitHelper2 0.1 1,421.426 191 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.707
| | | + kernelbase!WaitForSingleObjectEx 0.1 1,421.426 191 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.707
| | | + ntdll!NtWaitForSingleObject 0.1 1,421.426 191 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.707
| | | + ntoskrnl!? 0.1 1,421.426 191 0.0 0 0 0 0 ______________1993__799999999993 2,329.624 4,065.707
| | | + BLOCKED_TIME 0.1 1,417.750 95 0.1 1,417.750 95 0 0 ______________1993__799999999993 2,329.624 4,065.474
| | | + CPU_TIME 0.0 3.676 96 0.0 3.676 96 0 0 ______________.ooo__oooooooooooo 2,339.995 4,065.707
| | + clr!Thread::HandledJITCase 0.0 11.930 191 0.0 0 0 0 0 ______________oooo__oo0ooooooooo 2,329.477 4,058.940
| | |+ clr!Thread::GetSafelyRedirectableThreadContext 0.0 11.930 191 0.0 0 0 0 0 ______________oooo__oo0ooooooooo 2,329.477 4,058.940
| | | + clr!EEGetThreadContext 0.0 11.930 191 0.0 0 0 0 0 ______________oooo__oo0ooooooooo 2,329.477 4,058.940
| | | + kernelbase!GetThreadContext 0.0 11.930 191 0.0 0 0 0 0 ______________oooo__oo0ooooooooo 2,329.477 4,058.940
| | | + ntdll!NtGetContextThread 0.0 11.930 191 0.0 0 0 0 0 ______________oooo__oo0ooooooooo 2,329.477 4,058.940
| | | + ntoskrnl!? 0.0 11.930 191 0.0 0 0 0 0 ______________oooo__oo0ooooooooo 2,329.477 4,058.940
| | | + CPU_TIME 0.0 9.206 97 0.0 9.206 97 0 0 ______________oooo__oooooooooooo 2,329.500 4,058.940
| | | + BLOCKED_TIME 0.0 2.724 94 0.0 2.724 94 0 0 ______________.oo.__oo0..o.oooo. 2,329.477 4,058.842
| | + clr!Thread::SuspendThread 0.0 4.275 192 0.0 0 0 0 0 ______________.ooo__oooooooooooo 2,329.428 4,058.816
| | |+ kernelbase!GetThreadContext 0.0 4.255 191 0.0 0 0 0 0 ______________.ooo__oooooooooooo 2,329.428 4,058.816
| | ||+ ntdll!NtGetContextThread 0.0 4.255 191 0.0 0 0 0 0 ______________.ooo__oooooooooooo 2,329.428 4,058.816
| | || + ntoskrnl!? 0.0 4.255 191 0.0 0 0 0 0 ______________.ooo__oooooooooooo 2,329.428 4,058.816
| | || + CPU_TIME 0.0 2.449 97 0.0 2.449 97 0 0 ______________.oo.__ooooooooooo. 2,329.457 4,058.816
| | || + BLOCKED_TIME 0.0 1.806 94 0.0 1.806 94 0 0 ______________..o.__.ooooo.oooo. 2,329.428 4,058.792
| | |+ kernelbase!SuspendThread 0.0 0.020 1 0.0 0 0 0 0 __________________________._____ 3,590.022 3,590.042
| | | + ntdll!NtSuspendThread 0.0 0.020 1 0.0 0 0 0 0 __________________________._____ 3,590.022 3,590.042
| | | + ntoskrnl!? 0.0 0.020 1 0.0 0 0 0 0 __________________________._____ 3,590.022 3,590.042
| | | + CPU_TIME 0.0 0.020 1 0.0 0.020 1 0 0 __________________________._____ 3,590.022 3,590.042
| | + clr!Thread::ResumeThread 0.0 0.654 11 0.0 0 0 0 0 ________________._____o_o__o__._ 2,527.573 3,996.510
| | |+ kernelbase!ResumeThread 0.0 0.654 11 0.0 0 0 0 0 ________________._____o_o__o__._ 2,527.573 3,996.510
| | | + ntdll!NtResumeThread 0.0 0.654 11 0.0 0 0 0 0 ________________._____o_o__o__._ 2,527.573 3,996.510
| | | + ntoskrnl!? 0.0 0.654 11 0.0 0 0 0 0 ________________._____o_o__o__._ 2,527.573 3,996.510
| | | + CPU_TIME 0.0 0.566 6 0.0 0.566 6 0 0 ________________._____o_o__o__._ 2,527.586 3,996.510
| | | + BLOCKED_TIME 0.0 0.088 5 0.0 0.088 5 0 0 ________________._____._.__.__._ 2,527.573 3,996.418
| | + clr!ThreadStore::GetAllThreadList 0.0 0.350 6 0.0 0 0 0 0 _______________._.________._..._ 2,433.908 4,012.090
| + clr!SVR::gc_heap::garbage_collect 0.0 48.997 96 0.0 0 0 0 0 _____________2___1_____________1 2,159.629 4,079.473
| + clr!SVR::gc_heap::gc1 0.0 47.380 89 0.0 0 0 0 0 _____________2___1_____________1 2,159.880 4,079.473
| + clr!SVR::t_join::join 0.0 1.513 6 0.0 0 0 0 0 _____________o___o_____________o 2,159.629 4,066.072
| + clr!SVR::gc_heap::fix_allocation_contexts 0.0 0.105 1 0.0 0 0 0 0 _________________.______________ 2,592.923 2,593.028
Hi @marafiq! This repo (dotnet/runtime) is used to track issues with .NET 6+, though this issue is specific to .NET Framework. Based off of the original description it sounded like there might be a product issue however it seems the ETW trace is normal and nothing unusual from a diagnostics perspective stood out. Since this issue is now tracking answering questions on a specific performance analysis, we have decided to keep this issue open as other community members might benefit from the discussion and move it to the Future milestone. Since there are no .NET 6+ product issues listed here we are not planning on active working on this issue. If you are interested in paid Microsoft support, please see https://support.microsoft.com/contactus.
@tommcdon thanks. Keeping it open might help - yes, original trace ETW is not problem rather it was 'piohper' and some native calls, waiting for some clarifications there whenever folks find time.
Regard 2nd trace from same app, as per my understanding GC itself seems to be blocked - so we will know who is blocking it. But I m waiting for the answer before making assumption.
Description
Application experience slowdown up to 30 seconds. Most of the threads are waiting for
WaitForSingleObject
in the memory dump and similarly when a trace is taken 99% of threads are waiting underBlockedTime
.Configuration
ASP.NET Framework 4.8 running on Azure App Service Premium V3 The application uses the following: Azure SignalR SDK version - 1.21.4 SignalR Client SDK version - 2.4.1 Azure Insights Enabled - .NET Basic Level MVC 5.2.3 WebAPI
Help
I have been chasing this issue from few weeks now. I am unclear on the root cause, It would be great help if you can guide me to pin the root cause. My confusion is that I might be chasing the wrong optimization as I am failing to make sense of the blocked time quite clearly. As I suspect the ETW thread playing huge role in it than the application code.
Analysis
For the similar issue where JIT time was huge which I thought is the root cause. I did the following analysis https://github.com/microsoft/perfview/discussions/1997 and with expert help from PerfView Team Member, It was concluded that it is probably the Profile RunDown event causing the high JIT time.
Subsequently, we approached the Azure Support team, and the made different conclusion that it is somehow that GC is blocked for some reason but were not able to pin down the root cause as it falls outside of their day to day job. I am attaching the final conclusion made here that seems to indicate that there is some problem with the usage of
Dictionary
and most of thread traces show that is coming from Routing. Some of the suggestions to use the workstation mode might solve some slowdown but probably will not solve the root cause. Things we know:Issue related to ETW events - https://github.com/Azure/azure-signalr/issues/1837 Exception in Finalizer Thread- Dump shows that finalizer thread is not blocked - Though we have exception happening every then and now here https://github.com/Azure/azure-signalr/issues/1928
Latest Event of Slow Down
Whenever I take a trace the traces include ETW Trace events writing logs which our application explicitly does not write out.
- I can not make sense of it, what exactly it means?
When I look at the thread time stacks window
Only one thread is working under CPU_Time - thread 13212 - Below is part of stack trace of the thread.
One thing to note that there are multiple threads with same thread id 13212 in the same trace, below is 2nd thread with same id doing the rundown
Other instances of same thread