1

I recently deployed mvc-forum to Azure as a .net web application (app service) and while everything was working smoothly localy, I am seeing very long response times with Azure.

The first thing I checked were the remote dependencies (thinking it might be a SQL issue). I scowered around there, but the slow requests have a cumulative dependency duration of about 100 ms at worst.

I proceeded to enable "failed request tracing" and set my web.config to write a log if a request takes longer than five seconds. I did have some luck there, but I am having trouble gleaning anything from it. While the summary states that the overall time taken for a given request was 5141ms, I am not seeing that delay in the trace anywhere.

Time Taken 5141 msec 
1. GENERAL_REQUEST_START SiteId="xxxx", AppPoolId="xxxx", ConnId="1610619243", RawConnId="0", RequestURL="xxxx", RequestVerb="GET" 22:37:50.337 
2. PRE_BEGIN_REQUEST_START ModuleName="FailedRequestsTracingModule" 22:37:50.337 
3. PRE_BEGIN_REQUEST_END ModuleName="FailedRequestsTracingModule", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
4. PRE_BEGIN_REQUEST_START ModuleName="RequestMonitorModule" 22:37:50.337 
5. PRE_BEGIN_REQUEST_END ModuleName="RequestMonitorModule", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
6. PRE_BEGIN_REQUEST_START ModuleName="IsapiFilterModule" 22:37:50.337 
7. FILTER_PREPROC_HEADERS_START  22:37:50.337 
8. FILTER_START FilterName="D:\Windows\Microsoft.NET\Framework\v4.0.30319\aspnet_filter.dll" 22:37:50.337 
9. GENERAL_SET_REQUEST_HEADER HeaderName="AspFilterSessionId", HeaderValue="", Replace="true" 22:37:50.337 
10. FILTER_SET_REQ_HEADER HeaderName="AspFilterSessionId:", HeaderValue="" 22:37:50.337 
11. FILTER_END NotificationStatus="SF_STATUS_REQ_NEXT_NOTIFICATION" 22:37:50.337 
12. FILTER_PREPROC_HEADERS_END  22:37:50.337 
13. PRE_BEGIN_REQUEST_END ModuleName="IsapiFilterModule", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
14. PRE_BEGIN_REQUEST_START ModuleName="RewriteModule" 22:37:50.337 
15. PRE_BEGIN_REQUEST_END ModuleName="RewriteModule", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
16. PRE_BEGIN_REQUEST_START ModuleName="ARRHelper" 22:37:50.337 
17. PRE_BEGIN_REQUEST_END ModuleName="ARRHelper", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
18. PRE_BEGIN_REQUEST_START ModuleName="DynamicIpRestrictionModule" 22:37:50.337 
19. PRE_BEGIN_REQUEST_END ModuleName="DynamicIpRestrictionModule", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
20. PRE_BEGIN_REQUEST_START ModuleName="DWASModule" 22:37:50.337 
21. GENERAL_SET_REQUEST_HEADER HeaderName="HOST", HeaderValue="xxxx", Replace="true" 22:37:50.337 
22. PRE_BEGIN_REQUEST_END ModuleName="DWASModule", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
23. PRE_BEGIN_REQUEST_START ModuleName="AzureSlaModule" 22:37:50.337 
24. PRE_BEGIN_REQUEST_END ModuleName="AzureSlaModule", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
25. GENERAL_ENDPOINT_INFORMATION RemoteAddress="72.206.106.203", RemotePort="62440", LocalAddress="100.116.250.43", LocalPort="80" 22:37:50.337 
26. GENERAL_REQUEST_HEADERS Headers="Cache-Control: max-age=0
Connection: Keep-Alive
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Encoding: gzip, deflate, sdch
Accept-Language: en-US,en;q=0.8
Cookie: ARRAffinity=b0163f6574741482f6f634ea00c0eb3fd178c69a75355c0f8e40747e210f72eb; __RequestVerificationToken=rlmcAL1_URxrL0wf7GcwtG75NjbL12Zof-Jwaq0hT9COn0D7ZIBLprHAeap8EGWHApgg09cHBd46EakZyTZLye7zgjyZMp6y1ZKFAt-053E1; ASP.NET_SessionId=htp1pdiwkohswqzytmw1sim2; MvcForumAuth=166A62DDFC1383320AF6DF54DDF912195EF39B9D5BAFABDDF919B5D8DBD8E2A8D66C5B8B541CEFA870C48D1F8C8A7A4DF1602391F0529D281BAA7929D79613B11F56CB3C3B1F49E33D6400033E738F7915B8B028F5C9CF09D6447A06A85CBC627324A8DA2FA0ED9136B4F8C52C9AA8EA64BE1B373E7BB9285EB91C2FB59C50ACF8851E548596F348CC77F008140ED41772382AF386758AA1DE9259B87BE46214
Host: xxxx
Max-Forwards: 10
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/50.0.2661.102 Safari/537.36
Upgrade-Insecure-Requests: 1
X-LiveUpgrade: 1
X-ARR-LOG-ID: bab81c7b-19a2-4675-a105-9812223607f8
MWH-SecurityToken: xxxx
DISGUISED-HOST: xxxx
X-SITE-DEPLOYMENT-ID: xxxx
X-Original-URL: xxxx
X-Forwarded-For: xxxx
" 22:37:50.337 
27. URL_CACHE_ACCESS_START RequestURL="xxxx" 22:37:50.337 
28. URL_CACHE_ACCESS_END PhysicalPath="", URLInfoFromCache="false", URLInfoAddedToCache="true", ErrorCode="The operation completed successfully.
 (0x0)" 22:37:50.337 
29. GENERAL_GET_URL_METADATA PhysicalPath="", AccessPerms="513" 22:37:50.337 
30. HANDLER_CHANGED OldHandlerName="", NewHandlerName="ExtensionlessUrlHandler-Integrated-4.0", NewHandlerModules="ManagedPipelineHandler", NewHandlerScriptProcessor="", NewHandlerType="System.Web.Handlers.TransferRequestHandler" 22:37:50.337 
31. NOTIFY_MODULE_START ModuleName="ModSecurity IIS (32bits)", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
32. NOTIFY_MODULE_END ModuleName="ModSecurity IIS (32bits)", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
33. NOTIFY_MODULE_START ModuleName="WebSocketMonitoringModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
34. NOTIFY_MODULE_END ModuleName="WebSocketMonitoringModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
35. NOTIFY_MODULE_START ModuleName="DWASModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
36. GENERAL_SET_REQUEST_HEADER HeaderName="MWH-SecurityToken", HeaderValue="", Replace="true" 22:37:50.337 
37. GENERAL_SET_REQUEST_HEADER HeaderName="Sec-WebSocket-Extensions", HeaderValue="", Replace="true" 22:37:50.337 
38. NOTIFY_MODULE_END ModuleName="DWASModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
39. NOTIFY_MODULE_START ModuleName="HttpCacheModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
40. NOTIFY_MODULE_END ModuleName="HttpCacheModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
41. NOTIFY_MODULE_START ModuleName="RequestFilteringModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
42. NOTIFY_MODULE_END ModuleName="RequestFilteringModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
43. NOTIFY_MODULE_START ModuleName="FailedRequestsTracingModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
44. NOTIFY_MODULE_END ModuleName="FailedRequestsTracingModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
45. NOTIFY_MODULE_START ModuleName="ConfigurationValidationModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
46. NOTIFY_MODULE_END ModuleName="ConfigurationValidationModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
47. NOTIFY_MODULE_START ModuleName="RewriteModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
48. NOTIFY_MODULE_END ModuleName="RewriteModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
49. NOTIFY_MODULE_START ModuleName="IpRestrictionModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
50. NOTIFY_MODULE_END ModuleName="IpRestrictionModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
51. NOTIFY_MODULE_START ModuleName="ApplicationInitializationModule", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
52. NOTIFY_MODULE_END ModuleName="ApplicationInitializationModule", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
53. NOTIFY_MODULE_START ModuleName="__DynamicModule_Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule, Microsoft.AI.Web, Version=2.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35_002eae9c-5707-4811-9682-00b6b9c1f5b9", Notification="BEGIN_REQUEST", fIsPostNotification="false" 22:37:50.337 
54. AspNetStart Data1="GET", Data2="xxxx", Data3="" 22:37:50.337 
55. AspNetAppDomainEnter Data1="/LM/W3SVC/1464294192/ROOT-1-131083426700994043" 22:37:50.337 
56. NOTIFY_MODULE_START ModuleName="IsapiFilterModule", Notification="MAP_PATH", fIsPostNotification="false" 22:37:50.337 
57. NOTIFY_MODULE_END ModuleName="IsapiFilterModule", Notification="MAP_PATH", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
58. AspNetStartHandler Data1="ASP.global_asax", Data2="Start" 22:37:50.337 
59. AspNetPipelineEnter Data1="Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule" 22:37:50.337 
60. AspNetPipelineLeave Data1="Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule" 22:37:50.337 
61. NOTIFY_MODULE_END ModuleName="__DynamicModule_Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule, Microsoft.AI.Web, Version=2.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35_002eae9c-5707-4811-9682-00b6b9c1f5b9", Notification="BEGIN_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
62. NOTIFY_MODULE_START ModuleName="IsapiFilterModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="false" 22:37:50.337 
63. NOTIFY_MODULE_END ModuleName="IsapiFilterModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
64. NOTIFY_MODULE_START ModuleName="WindowsAuthentication", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="false" 22:37:50.337 
65. AspNetPipelineEnter Data1="System.Web.Security.WindowsAuthenticationModule" 22:37:50.337 
66. AspNetPipelineLeave Data1="System.Web.Security.WindowsAuthenticationModule" 22:37:50.337 
67. NOTIFY_MODULE_END ModuleName="WindowsAuthentication", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
68. NOTIFY_MODULE_START ModuleName="FormsAuthentication", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="false" 22:37:50.337 
69. AspNetPipelineEnter Data1="System.Web.Security.FormsAuthenticationModule" 22:37:50.337 
70. USER_SET AuthType="Forms", UserName="si1entStill", SupportsIsInRole="true" 22:37:50.337 
71. AspNetPipelineLeave Data1="System.Web.Security.FormsAuthenticationModule" 22:37:50.337 
72. NOTIFY_MODULE_END ModuleName="FormsAuthentication", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
73. NOTIFY_MODULE_START ModuleName="ScriptModule-4.0", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="false" 22:37:50.337 
74. AspNetPipelineEnter Data1="System.Web.Handlers.ScriptModule" 22:37:50.337 
75. AspNetPipelineLeave Data1="System.Web.Handlers.ScriptModule" 22:37:50.337 
76. NOTIFY_MODULE_END ModuleName="ScriptModule-4.0", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
77. NOTIFY_MODULE_START ModuleName="DWASModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="false" 22:37:50.337 
78. NOTIFY_MODULE_END ModuleName="DWASModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
79. NOTIFY_MODULE_START ModuleName="AnonymousAuthenticationModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="false" 22:37:50.337 
80. NOTIFY_MODULE_END ModuleName="AnonymousAuthenticationModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
81. NOTIFY_MODULE_START ModuleName="IsapiFilterModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="true" 22:37:50.337 
82. FILTER_AUTH_COMPLETE_START  22:37:50.337 
83. FILTER_AUTH_COMPLETE_END  22:37:50.337 
84. NOTIFY_MODULE_END ModuleName="IsapiFilterModule", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
85. NOTIFY_MODULE_START ModuleName="DefaultAuthentication", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="true" 22:37:50.337 
86. AspNetPipelineEnter Data1="System.Web.Security.DefaultAuthenticationModule" 22:37:50.337 
87. AspNetPipelineLeave Data1="System.Web.Security.DefaultAuthenticationModule" 22:37:50.337 
88. NOTIFY_MODULE_END ModuleName="DefaultAuthentication", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
89. NOTIFY_MODULE_START ModuleName="RoleManager", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="true" 22:37:50.337 
90. AspNetPipelineEnter Data1="System.Web.Security.RoleManagerModule" 22:37:50.337 
91. AspNetPipelineLeave Data1="System.Web.Security.RoleManagerModule" 22:37:50.337 
92. NOTIFY_MODULE_END ModuleName="RoleManager", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
93. NOTIFY_MODULE_START ModuleName="ServiceModel-4.0", Notification="AUTHENTICATE_REQUEST", fIsPostNotification="true" 22:37:50.337 
94. AspNetPipelineEnter Data1="System.ServiceModel.Activation.ServiceHttpModule" 22:37:50.337 
95. AspNetPipelineLeave Data1="System.ServiceModel.Activation.ServiceHttpModule" 22:37:50.337 
96. NOTIFY_MODULE_END ModuleName="ServiceModel-4.0", Notification="AUTHENTICATE_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
97. NOTIFY_MODULE_START ModuleName="UrlAuthorization", Notification="AUTHORIZE_REQUEST", fIsPostNotification="false" 22:37:50.337 
98. AspNetPipelineEnter Data1="System.Web.Security.UrlAuthorizationModule" 22:37:50.337 
99. AspNetPipelineLeave Data1="System.Web.Security.UrlAuthorizationModule" 22:37:50.337 
100. NOTIFY_MODULE_END ModuleName="UrlAuthorization", Notification="AUTHORIZE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
101. NOTIFY_MODULE_START ModuleName="FileAuthorization", Notification="AUTHORIZE_REQUEST", fIsPostNotification="false" 22:37:50.337 
102. AspNetPipelineEnter Data1="System.Web.Security.FileAuthorizationModule" 22:37:50.337 
103. AspNetPipelineLeave Data1="System.Web.Security.FileAuthorizationModule" 22:37:50.337 
104. NOTIFY_MODULE_END ModuleName="FileAuthorization", Notification="AUTHORIZE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
105. NOTIFY_MODULE_START ModuleName="DWASModule", Notification="AUTHORIZE_REQUEST", fIsPostNotification="false" 22:37:50.337 
106. NOTIFY_MODULE_END ModuleName="DWASModule", Notification="AUTHORIZE_REQUEST", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
107. NOTIFY_MODULE_START ModuleName="ImageProcessorModule", Notification="AUTHORIZE_REQUEST", fIsPostNotification="true" 22:37:50.337 
108. AspNetPipelineEnter Data1="System.Web.EventHandlerTaskAsyncHelper+<>c__DisplayClass0_0" 22:37:50.337 
109. AspNetPipelineLeave Data1="System.Web.EventHandlerTaskAsyncHelper+<>c__DisplayClass0_0" 22:37:50.337 
110. NOTIFY_MODULE_END ModuleName="ImageProcessorModule", Notification="AUTHORIZE_REQUEST", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
111. NOTIFY_MODULE_START ModuleName="HttpCacheModule", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotification="false" 22:37:50.337 
112. OUTPUT_CACHE_LOOKUP_START  22:37:50.337 
113. OUTPUT_CACHE_LOOKUP_END Result="NOT_FOUND" 22:37:50.337 
114. NOTIFY_MODULE_END ModuleName="HttpCacheModule", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
115. NOTIFY_MODULE_START ModuleName="OutputCache", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotification="false" 22:37:50.337 
116. AspNetPipelineEnter Data1="System.Web.Caching.OutputCacheModule" 22:37:50.337 
117. AspNetPipelineLeave Data1="System.Web.Caching.OutputCacheModule" 22:37:50.337 
118. NOTIFY_MODULE_END ModuleName="OutputCache", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
119. NOTIFY_MODULE_START ModuleName="UrlRoutingModule-4.0", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotification="true" 22:37:50.337 
120. AspNetPipelineEnter Data1="System.Web.Routing.UrlRoutingModule" 22:37:50.337 
121. AspNetPipelineLeave Data1="System.Web.Routing.UrlRoutingModule" 22:37:50.337 
122. NOTIFY_MODULE_END ModuleName="UrlRoutingModule-4.0", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.337 
123. NOTIFY_MODULE_START ModuleName="__DynamicModule_System.Web.WebPages.WebPageHttpModule, System.Web.WebPages, Version=3.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35_ac4a637a-cee0-4dc9-b506-afc8cca75fd3", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotification="true" 22:37:50.337 
124. AspNetPipelineEnter Data1="System.Web.WebPages.WebPageHttpModule" 22:37:50.337 
125. AspNetPipelineLeave Data1="System.Web.WebPages.WebPageHttpModule" 22:37:50.353 
126. NOTIFY_MODULE_END ModuleName="__DynamicModule_System.Web.WebPages.WebPageHttpModule, System.Web.WebPages, Version=3.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35_ac4a637a-cee0-4dc9-b506-afc8cca75fd3", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
127. NOTIFY_MODULE_START ModuleName="__DynamicModule_System.Web.Optimization.BundleModule, System.Web.Optimization, Version=1.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35_94f34eb0-645e-4f50-84e0-96f33c221470", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotification="true" 22:37:50.353 
128. AspNetPipelineEnter Data1="System.Web.Optimization.BundleModule" 22:37:50.353 
129. AspNetPipelineLeave Data1="System.Web.Optimization.BundleModule" 22:37:50.353 
130. NOTIFY_MODULE_END ModuleName="__DynamicModule_System.Web.Optimization.BundleModule, System.Web.Optimization, Version=1.1.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35_94f34eb0-645e-4f50-84e0-96f33c221470", Notification="RESOLVE_REQUEST_CACHE", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
131. NOTIFY_MODULE_START ModuleName="ApplicationRequestRouting", Notification="MAP_REQUEST_HANDLER", fIsPostNotification="false" 22:37:50.353 
132. NOTIFY_MODULE_END ModuleName="ApplicationRequestRouting", Notification="MAP_REQUEST_HANDLER", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
133. NOTIFY_MODULE_START ModuleName="StaticCompressionModule", Notification="MAP_REQUEST_HANDLER", fIsPostNotification="false" 22:37:50.353 
134. NOTIFY_MODULE_END ModuleName="StaticCompressionModule", Notification="MAP_REQUEST_HANDLER", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
135. NOTIFY_MODULE_START ModuleName="HttpRedirectionModule", Notification="MAP_REQUEST_HANDLER", fIsPostNotification="false" 22:37:50.353 
136. NOTIFY_MODULE_END ModuleName="HttpRedirectionModule", Notification="MAP_REQUEST_HANDLER", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
137. NOTIFY_MODULE_START ModuleName="DWASModule", Notification="MAP_REQUEST_HANDLER", fIsPostNotification="false" 22:37:50.353 
138. NOTIFY_MODULE_END ModuleName="DWASModule", Notification="MAP_REQUEST_HANDLER", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
139. NOTIFY_MODULE_START ModuleName="ManagedPipelineHandler", Notification="MAP_REQUEST_HANDLER", fIsPostNotification="false" 22:37:50.353 
140. AspNetMapHandlerEnter  22:37:50.353 
141. HANDLER_CHANGED OldHandlerName="ExtensionlessUrlHandler-Integrated-4.0", NewHandlerName="System.Web.Mvc.MvcHandler", NewHandlerModules="ManagedPipelineHandler", NewHandlerScriptProcessor="", NewHandlerType="System.Web.Mvc.MvcHandler, System.Web.Mvc, Version=5.2.3.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35" 22:37:50.353 
142. AspNetMapHandlerLeave  22:37:50.353 
143. NOTIFY_MODULE_END ModuleName="ManagedPipelineHandler", Notification="MAP_REQUEST_HANDLER", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
144. NOTIFY_MODULE_START ModuleName="DWASModule", Notification="MAP_REQUEST_HANDLER", fIsPostNotification="true" 22:37:50.353 
145. NOTIFY_MODULE_END ModuleName="DWASModule", Notification="MAP_REQUEST_HANDLER", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
146. NOTIFY_MODULE_START ModuleName="Session", Notification="REQUEST_ACQUIRE_STATE", fIsPostNotification="false" 22:37:50.353 
147. AspNetPipelineEnter Data1="System.Web.SessionState.SessionStateModule" 22:37:50.353 
148. AspNetSessionDataBegin  22:37:50.353 
149. AspNetSessionDataEnd  22:37:50.353 
150. AspNetPipelineLeave Data1="System.Web.SessionState.SessionStateModule" 22:37:50.353 
151. NOTIFY_MODULE_END ModuleName="Session", Notification="REQUEST_ACQUIRE_STATE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
152. NOTIFY_MODULE_START ModuleName="Profile", Notification="REQUEST_ACQUIRE_STATE", fIsPostNotification="false" 22:37:50.353 
153. AspNetPipelineEnter Data1="System.Web.Profile.ProfileModule" 22:37:50.353 
154. AspNetPipelineLeave Data1="System.Web.Profile.ProfileModule" 22:37:50.353 
155. NOTIFY_MODULE_END ModuleName="Profile", Notification="REQUEST_ACQUIRE_STATE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.353 
156. NOTIFY_MODULE_START ModuleName="global.asax", Notification="REQUEST_ACQUIRE_STATE", fIsPostNotification="false" 22:37:50.353 
157. AspNetPipelineEnter Data1="MVCForum.Website.MvcApplication" 22:37:50.353 
158. AspNetPipelineLeave Data1="MVCForum.Website.MvcApplication" 22:37:50.603 
159. NOTIFY_MODULE_END ModuleName="global.asax", Notification="REQUEST_ACQUIRE_STATE", fIsPostNotificationEvent="false", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.603 
160. NOTIFY_MODULE_START ModuleName="ScriptModule-4.0", Notification="REQUEST_ACQUIRE_STATE", fIsPostNotification="true" 22:37:50.603 
161. AspNetPipelineEnter Data1="System.Web.Handlers.ScriptModule" 22:37:50.603 
162. AspNetPipelineLeave Data1="System.Web.Handlers.ScriptModule" 22:37:50.603 
163. NOTIFY_MODULE_END ModuleName="ScriptModule-4.0", Notification="REQUEST_ACQUIRE_STATE", fIsPostNotificationEvent="true", NotificationStatus="NOTIFICATION_CONTINUE" 22:37:50.603 
164. NOTIFY_MODULE_START ModuleName="ManagedPipelineHandler", Notification="EXECUTE_REQUEST_HANDLER", fIsPostNotification="false" 22:37:50.603 
165. AspNetPipelineEnter Data1="System.Web.ImplicitAsyncPreloadModule" 22:37:50.603 
166. AspNetPipelineLeave Data1="System.Web.ImplicitAsyncPreloadModule" 22:37:50.603 
167. AspNetHttpHandlerEnter  22:37:50.603 

I am kind of at a loss on what could be causing the slowness at this point. Any and all suggestions would be very welcome. I am also more than happy to grab any logs for further info if need be. Thanks for reading!

  • Is this happening on every request, or does it happen on your first request, then the next few requests after that in a short time window are ok speed wise? – Sam Cogan May 22 '16 at 16:24
  • Same issue. I mostly have this issue after some requests, just randomly. Did you find the solution ? – qasimzee May 23 '16 at 3:18
  • @qasimzee the reason I asked is that if the app has been dormant for some time, the default settings will shut down the app pool to save resources, when it starts up again the app pool needs to be loaded and the app compiled, which increases time. You can avoid this by setting the "always on" setting on the app to true, this means the app pool will not shut down. This is only available on standard and premium apps. – Sam Cogan May 23 '16 at 10:01
  • no, its not just the first request - it is a subset of requests, but a rather large group of them. Some are still fast. – Noel Minchow May 24 '16 at 1:10

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.