.NET Hang: My application hangs after I called my WCF service a couple of times
I know it is a little late, but Happy New Year to all of you. My holiday break was great, and I wish I would have had some more time to blog, but instead I got an XBOX 360 and a Guitar Hero World Tour game so the blog had to take the back seat for a while…
My whole family and even my mom are now hooked on GH so the evenings at my house have turned into family jam sessions :)
Apart from playing GH and hanging out with family and friends, I spent most of my break writing Silverlight apps and games for the new debugging labs. While doing so I also played around a bit with some WCF services and ran into an issue, because of bad programming on my end, that I thought I’d share in case any of you happen to run into it.
I will share a step-by-step of how I created a simple WCF service and consumed it from an ASP.NET app in my next post, but first I wanted to show you how to debug the particular hang I was running into.
Problem description
After a while, any page that calls the WCF service will hang until I restart IIS. Eventually the page will time out with the following exception.
Server Error in '/GameSite' Application.
The operation has timed out
Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code.
Exception Details: System.Net.WebException: The operation has timed out
Source Error:
Line 140: public void AddGame(Game g)
Line 141: {
Line 142: base.Channel.AddGame(g);
Line 143: }
Line 144:}
Source File: c:\Inetpub\wwwroot\GameSite\App_Code\GameListingService.cs Line: 142
Stack Trace:
[WebException: The operation has timed out]
System.Net.HttpWebRequest.GetResponse() +5313085
System.ServiceModel.Channels.HttpChannelRequest.WaitForReply(TimeSpan timeout) +54
[TimeoutException: The HTTP request to 'http://prather.europe.corp.microsoft.com/GameListingService/GameListingService.svc' has exceeded the allotted timeout of 00:01:00. The time allotted to this operation may have been a portion of a longer timeout.]
System.ServiceModel.Channels.HttpChannelUtilities.ProcessGetResponseWebException(WebException webException, HttpWebRequest request, HttpAbortReason abortReason) +4119697
System.ServiceModel.Channels.HttpChannelRequest.WaitForReply(TimeSpan timeout) +213
System.ServiceModel.Channels.RequestChannel.Request(Message message, TimeSpan timeout) +355
[TimeoutException: The request channel timed out while waiting for a reply after 00:01:00. Increase the timeout value passed to the call to Request or increase the SendTimeout value on the Binding. The time allotted to this operation may have been a portion of a longer timeout.]
System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg) +7594687
System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type) +275
IGameListingService.AddGame(Game g) +0
GameListingServiceClient.AddGame(Game g) in c:\Inetpub\wwwroot\GameSite\App_Code\GameListingService.cs:142
_Default.Button1_Click(Object sender, EventArgs e) in c:\Inetpub\wwwroot\GameSite\Default.aspx.cs:20
System.Web.UI.WebControls.Button.OnClick(EventArgs e) +111
System.Web.UI.WebControls.Button.RaisePostBackEvent(String eventArgument) +110
System.Web.UI.WebControls.Button.System.Web.UI.IPostBackEventHandler.RaisePostBackEvent(String eventArgument) +10
System.Web.UI.Page.RaisePostBackEvent(IPostBackEventHandler sourceControl, String eventArgument) +13
System.Web.UI.Page.RaisePostBackEvent(NameValueCollection postData) +36
System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint) +1565
Version Information: Microsoft .NET Framework Version:2.0.50727.3053; ASP.NET Version:2.0.50727.3053
Debugging
The first step was to take a hang dump of the w3wp.exe process hosting the asp.net application and the w3wp.exe process hosting the wcf service (using the debugging tools for windows)
adplus –hang –pn w3wp.exe
Before doing so, I stressed the application with tinyget to get a lot of requests pouring through
tinyget –srv:localhost –uri:/GameSite/Default.aspx –loop:30 –threads:15
I opened up the dump for the default application pool in windbg.exe and loaded sos (.loadby sos mscorwks) and ran ~* e !clrstack to see the .net stacks for all the threads.
15 threads are sitting there in Socket.Receive, waiting to get data from the WCF service call IGameListingService.AddGame(Game), so it appears that we are waiting for the WCF service to return some data.
OS Thread Id: 0x15c8 (37)
ESP EIP
11c7e29c 7d61c828 [NDirectMethodFrameStandalone: 11c7e29c] System.Net.UnsafeNclNativeMethods+OSSOCK.recv(IntPtr, Byte*, Int32, System.Net.Sockets.SocketFlags)
11c7e2b4 7a57f804 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags, System.Net.Sockets.SocketError ByRef)
11c7e2ec 7a57f700 System.Net.Sockets.Socket.Receive(Byte[], Int32, Int32, System.Net.Sockets.SocketFlags)
11c7e30c 7a589714 System.Net.Sockets.NetworkStream.Read(Byte[], Int32, Int32)
11c7e33c 7a58967b System.Net.PooledStream.Read(Byte[], Int32, Int32)
11c7e358 7a58936a System.Net.Connection.SyncRead(System.Net.HttpWebRequest, Boolean, Boolean)
11c7e3ac 7a58baf5 System.Net.ConnectStream.ProcessWriteCallDone(System.Net.ConnectionReturnResult)
11c7e3dc 7a58ba51 System.Net.HttpWebRequest.WriteCallDone(System.Net.ConnectStream, System.Net.ConnectionReturnResult)
11c7e3f4 7a58b9bb System.Net.ConnectStream.CallDone(System.Net.ConnectionReturnResult)
11c7e404 7a58b685 System.Net.ConnectStream.ResubmitWrite(System.Net.ConnectStream, Boolean)
11c7e460 7a58b27f System.Net.HttpWebRequest.EndWriteHeaders_Part2()
11c7e490 7a5890a9 System.Net.HttpWebRequest.EndWriteHeaders(Boolean)
11c7e4bc 7a588f16 System.Net.HttpWebRequest.WriteHeadersCallback(System.Net.WebExceptionStatus, System.Net.ConnectStream, Boolean)
11c7e4d0 7a588ad1 System.Net.ConnectStream.WriteHeaders(Boolean)
11c7e524 7a586e42 System.Net.HttpWebRequest.EndSubmitRequest()
11c7e550 7a58822e System.Net.HttpWebRequest.CheckDeferredCallDone(System.Net.ConnectStream)
11c7e564 7a588107 System.Net.HttpWebRequest.GetResponse()
11c7e5a4 0f463d97 System.ServiceModel.Channels.HttpChannelFactory+HttpRequestChannel+HttpChannelRequest.WaitForReply(System.TimeSpan)
11c7e5e4 0f462f24 System.ServiceModel.Channels.RequestChannel.Request(System.ServiceModel.Channels.Message, System.TimeSpan)
11c7e658 0f45aa6e System.ServiceModel.Channels.ClientReliableChannelBinder`1+RequestClientReliableChannelBinder`1[[System.__Canon, mscorlib],[System.__Canon, mscorlib]].OnRequest(System.__Canon, System.ServiceModel.Channels.Message, System.TimeSpan, System.ServiceModel.Channels.MaskingMode)
11c7e678 0f459844 System.ServiceModel.Channels.ClientReliableChannelBinder`1[[System.__Canon, mscorlib]].Request(System.ServiceModel.Channels.Message, System.TimeSpan, System.ServiceModel.Channels.MaskingMode)
11c7e6f0 0f459766 System.ServiceModel.Channels.ClientReliableChannelBinder`1[[System.__Canon, mscorlib]].Request(System.ServiceModel.Channels.Message, System.TimeSpan)
11c7e700 0f43ff2f System.ServiceModel.Security.SecuritySessionClientSettings`1+SecurityRequestSessionChannel[[System.__Canon, mscorlib]].Request(System.ServiceModel.Channels.Message, System.TimeSpan)
11c7e750 0f462da7 System.ServiceModel.Dispatcher.RequestChannelBinder.Request(System.ServiceModel.Channels.Message, System.TimeSpan)
11c7e764 0f475cb2 System.ServiceModel.Channels.ServiceChannel.Call(System.String, Boolean, System.ServiceModel.Dispatcher.ProxyOperationRuntime, System.Object[], System.Object[], System.TimeSpan)
11c7e894 0f475af3 System.ServiceModel.Channels.ServiceChannel.Call(System.String, Boolean, System.ServiceModel.Dispatcher.ProxyOperationRuntime, System.Object[], System.Object[])
11c7e8b4 0f475a03 System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(System.Runtime.Remoting.Messaging.IMethodCallMessage, System.ServiceModel.Dispatcher.ProxyOperationRuntime)
11c7e8d8 0f4778e5 System.ServiceModel.Channels.ServiceChannelProxy.Invoke(System.Runtime.Remoting.Messaging.IMessage)
11c7e91c 792c128d System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(System.Runtime.Remoting.Proxies.MessageData ByRef, Int32)
11c7ebbc 79e71e04 [TPMethodFrame: 11c7ebbc] IGameListingService.AddGame(Game)
11c7ebcc 106c0c2a GameListingServiceClient.AddGame(Game)
11c7ebe0 106c09ad _Default.Page_Load(System.Object, System.EventArgs)
11c7ec58 66f2a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
11c7ec68 660b2344 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
11c7ec7c 660ab864 System.Web.UI.Control.OnLoad(System.EventArgs)
11c7ec90 660ab8a3 System.Web.UI.Control.LoadRecursive()
11c7eca8 660a7954 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
11c7ee00 660a7584 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
11c7ee38 660a74b1 System.Web.UI.Page.ProcessRequest()
11c7ee70 660a7446 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
11c7ee7c 660a7422 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
11c7ee90 106c01fe ASP.default_aspx.ProcessRequest(System.Web.HttpContext)
11c7eea0 660ad8f6 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
11c7eed4 6608132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
11c7ef14 6608c3a3 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
11c7ef64 660808ac System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
11c7ef80 66083e1c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
11c7efb4 66083ac3 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
11c7efc4 66082c5c System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
11c7f1d8 79f68c4e [ContextTransitionFrame: 11c7f1d8]
11c7f20c 79f68c4e [GCFrame: 11c7f20c]
11c7f368 79f68c4e [ComMethodFrame: 11c7f368]
With that in mind I opened up the dump from the application pool hosting the WCF service to see what it was doing, and why we were waiting to return data, and there I could see 15 threads in the following call stack
0:037> !clrstack
OS Thread Id: 0x1980 (37)
ESP EIP
11b3ed00 7d61d051 [HelperMethodFrame_1OBJ: 11b3ed00] System.Threading.WaitHandle.WaitOneNative(Microsoft.Win32.SafeHandles.SafeWaitHandle, UInt32, Boolean, Boolean)
11b3edac 792b687f System.Threading.WaitHandle.WaitOne(Int64, Boolean)
11b3edc8 792b6835 System.Threading.WaitHandle.WaitOne(Int32, Boolean)
11b3eddc 792b67fd System.Threading.WaitHandle.WaitOne()
11b3ede4 0f17bd10 System.ServiceModel.Activation.HostedHttpRequestAsyncResult.ExecuteSynchronous(System.Web.HttpApplication, Boolean)
11b3ee14 0f17b657 System.ServiceModel.Activation.HttpModule.ProcessRequest(System.Object, System.EventArgs)
11b3ee3c 6608cde5 System.Web.HttpApplication+SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
11b3ee54 6608132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
11b3ee94 6608c3a3 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
11b3eee4 660808ac System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
11b3ef00 66083e1c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
11b3ef34 66083ac3 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
11b3ef44 66082c5c System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
11b3f158 79f68c4e [ContextTransitionFrame: 11b3f158]
11b3f18c 79f68c4e [GCFrame: 11b3f18c]
11b3f2e8 79f68c4e [ComMethodFrame: 11b3f2e8]
These threads are not really doing any socket operations as I would have expected, or for that matter executing any code inside my wcf service either.
Instead it is sitting in System.ServiceModel.Activation.HostedHttpRequestAsyncResult.ExecuteSynchronous. I didn’t know what this was so I started searching for this call on the internet and found a blog post from Wen Long about WCF Request Throttling
As it turns out, the WCF service has a throttling mechanism that only allows x number of concurrent instances of the WCF service at the same time and if it has reached that limit it will wait for those instances to be closed/disposed to continue serving the next request. This is a configurable number and by default it is 10 <serviceThrottling maxConcurrentSessions…>
The problem is that even with this I would have expected to see 10 requests actually processing and the others backing up here, but then I remembered something.
In the code for my WCF call I had forgotten to close the GameListingServiceClient after using it, so it was left in an idle but open state, and thus any requests after my 10th call will just sit there and wait.
GameListingServiceClient gc = new GameListingServiceClient();
gc.AddGame(new Game() { Name = txtName.Text, Publisher = txtPublisher.Text });
grdGames.DataSource = gc.GetAllGames();
grdGames.DataBind();
Final thoughts
If it would have been the case that the WCF process was actually processing my requests, I would have instead looked at what it was doing to see what was taking so long and perhaps also changed the throttling behavior. In this particular case, changing the behavior to allow say 50 instances would have only meant that it would have taken a little longer before it would eventually hang.
I have seen some comments in forums etc. that people have seen that forcing a GC in the ASP.NET process made the issue go away. The reason for this is because if they forced a GC, the instance would be disposed and closed as part of finalization. Even if this fixes the problem, this is not the correct action though.
Btw. the reason that I have 15 active requests here is of course because my tinyget thread parameter was 15, which means that I send off 15 concurrent requests. Once the first 10 have finished executing (leaving the channel still open) it could push through 10 more, but with 15 threads on tinyget, it can have a maximum of 15 requests waiting at a time before it sends new ones.
Have a good one, Tess
