If broken it is, fix it you should

Using the powers of the debugger to solve the problems of the world - and a bag of chips    by Tess Ferrandez, ASP.NET Escalation Engineer (Microsoft)

.NET Hang: My application hangs after I called my WCF service a couple of times

.NET Hang: My application hangs after I called my WCF service a couple of times

  • Comments 18

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 callstack

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 donig 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

 http://blogs.msdn.com/wenlong/archive/2008/04/21/wcf-request-throttling-and-server-scalability.aspx

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…>

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

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 threadparameter 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

  • My latest in a series of the weekly, or more often, summary of interesting links I come across related to Visual Studio. The Web Developer Tools Team posted a link to a Hotfix for Visual Studio 2005 crash when saving pages with linked stylesheets . The

  • We banged our heads on this once also.  The key is to use the using statement so it always closes.

    using (GameListingServiceClient gc = new GameListingServiceClient())

           {

             gc.AddGame(new Game() { Name = txtName.Text, Publisher = txtPublisher.Text });

     grdGames.DataSource = gc.GetAllGames();

             grdGames.DataBind();

           }

  • .NET Asynchronous Fire and Forget With Lambdas There is never a collection of Value Objects Reading all

  • .NETAsynchronousFireandForgetWithLambdasThereisneveracollectionofValueObjects...

  • In my last post I wrote about a WCF hang I caused because of a newbie mistake.&#160; I also wrote that

  • Hi Tess,

    I just wanted to add a reply to the "use the using statement to close the client proxy" reply above.

    Sadly, the implementation of IDisposable in ClientBase<T> (and DuplexClientBase<T>) does not cover the case where the inner channel is in a Faulted state. In this case the channel needs to be Abort()'ed - and not Close()'ed.

    The easy fix to this (since the generated client proxy is marked as partial) is to reimplement the Dispose() in an additional class file, and check if .State == CommunicationState.Faulted (then .Abort();) or .Opened (then .Close());

    Only by checking this, you can use the using-statement safely with generated WCF client proxies.

    Best regards,

    Lars Wilhelmsen

  • I just debugged into the same issue this past week.  The problem we found was that the ExecuteSynchronous() code does not handle ThreadAbortException properly.  The issue is that if a TAE happens, the second WCF thread doing the processing never "completes" the request, which means it never sets the event to cause the (first) request thread to be given back to the TP -- you can check that this is indeed the case by looking at the ExecuteSynchronous() code with reflector.  Over time these TAE's were causing our app to run out of threads.

    ThreadAbortExceptions happen when you call HttpResponse.End() or HttpResponse.Redirect(), which is what we were doing.  Switching to HttpResponse.Close() (which doesn't throw a TAE), and bubbling out a different exception allowed us to fix the bug.

  • Hi Tess,

    You mention "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. "

    Can you please explain what you mean by "requests will just sit there and wait"? Do you mean that mean that if the client is not closed, the request continues to hold onto a thread on the WCF service on the server?  And the call stack for such requests also looks like the WCF threads which wait in the ExecuteSynchronous method?

    I have a situation in a WCF service where I see a lot of threads that are waiting in the ExecuteSynchronous method but I only see 1 thread that's doing any real work talking to the DB.

  • I figured out our problem. The WCF service was executing just one request at a time. After digging into the throttling configs and reading a few other articles, I found this

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

    We were not setting the Concurrency attribute on the service, so it defaults to Single which means only 1 request executes at a time. I set to Multiple and now the service works great!

  • great article!

    Just wanted to let you know that the 'debugging tools for windows' link is broken

  • Tess, great article!

    Is there a Performance Counter that can be used to monitor how many requests are in this kind of "pending" status?

    Also, is there a setting on the WCF server end that prevents the clients from leaving the connections open for too long?

    Thanks,

    Paolo

  • Great article Tess! Saved me A LOT of time of research.

    /Daniel

  • Great article.  I had the exact same problem but was certain that I was closing all my client connections.  After double checking, there was one that wasn't.   Thanks!

  • Wow! Nice article. It helps me to solve two days problem :) Thank you!

  • Nice analysis. I'll remember this when deciding whether to call Microsoft Support.

Page 1 of 2 (18 items) 12
Leave a Comment
  • Please add 2 and 7 and type the answer here:
  • Post