WCF - Random client timeout when making multiple calls

Question

I have a WPF client requesting data via WCF service hosted in IIS 7. The service method makes a call to a stored procedure (SQL 2012) using EF to retrieve some data.

There's a lot of data to load so the client makes several calls to the service method in an effort to "break up" the data loading and avoid large payloads and timeouts.

We use the generated service proxies that extend from System.ServiceModel.ClientBase<T>.

We're also using a custom http binding with binary encoding (from here) - actual implementation shown here:

<customBinding>
   <binding name="CustomBinding_IPointDataAccess" closeTimeout="00:01:00"
      openTimeout="00:01:00" receiveTimeout="00:10:00" sendTimeout="00:01:00">
      <binaryMessageEncoding maxReadPoolSize="64" maxWritePoolSize="16" maxSessionSize="2048">
      <readerQuotas maxDepth="2147483647" maxStringContentLength="2147483647" maxArrayLength="2147483647" maxBytesPerRead="2147483647" maxNameTableCharCount="16384" />
      </binaryMessageEncoding>
      <httpTransport manualAddressing="false" maxBufferPoolSize="524288"
         maxReceivedMessageSize="2147483647" allowCookies="false" authenticationScheme="Anonymous" bypassProxyOnLocal="false" decompressionEnabled="true" hostNameComparisonMode="StrongWildcard" keepAliveEnabled="true" maxBufferSize="2147483647" proxyAuthenticationScheme="Anonymous" realm="" transferMode="Buffered" unsafeConnectionNtlmAuthentication="false" useDefaultWebProxy="true" />
   </binding>

Also, dynamic compression is turned on in IIS. I can view the requests in Fiddler, and the size of the message's body is fine (~50KB) and 99% of the requests return in a second or two. Perfect!

However, with almost every iteration, there is one call in the bunch that takes minutes to complete, and I don't know why... My sendTimeOut on the client was at 1 minute and naturally that one call would fail. I extended it to 10 minutes, and the call seems to complete in a little more than 2 minutes - although sometimes it would take even longer. The problem appears very random - it could be the first call, it could be the 30th call. But it's very reproducible.

I placed some logging around the the stored procedure call in the WCF service method and it executes and gets data back in under a second. So, I don't think it's a database issue.

Using Fiddler, the problematic call generates output similar to the following:

ACTUAL PERFORMANCE
--------------
ClientConnected:     14:02:42.959
ClientBeginRequest:  14:03:01.224
GotRequestHeaders:   14:03:01.224
ClientDoneRequest:   14:03:01.574
Determine Gateway:   0ms
DNS Lookup:      0ms
TCP/IP Connect:  46ms
HTTPS Handshake:     0ms
ServerConnected:     14:05:16.021
FiddlerBeginRequest: 14:05:16.021
ServerGotRequest:    14:05:16.021
ServerBeginResponse: 14:03:04.784
GotResponseHeaders:  14:05:16.561
ServerDoneResponse:  14:05:16.611
ClientBeginResponse: 14:05:16.611
ClientDoneResponse:  14:05:16.611

Notice the significant time between ServerBeginResponse and GotResponseHeaders. This seems strikingly similar to the issue seen here.

I enabled WCF Service Tracing, and at a quick glance, there are no errors or warnings, but I can't really make much sense out of what I'm looking at beyond the basics.

How can I nail down what and where the problem lies? Is it serialization? Is it a network issue? Can the server not keep up with the client sending so many requests?

I've tried adjusting the WCF Throttling in the config file by adding the appropriate serviceBehaviors, but this did not make a difference.

I should mention that I am doing this over a VPN connection, but other things like file transfers, remote desktop connections work just fine. It seems pretty reliable.

I can provide more details if necessary.

Edit (6.10.2013): Not sure if this is related or just a fluke, but a couple times, I've noticed that on the problematic call, the Body size is significantly less than the others. This is not the case each time, but it may provide some clues. Here is a screen capture from Fiddler to show you how consistent the Body size should be with each call. The selected entry (#21) is much smaller than the others in size, but takes over 2 minutes to complete.

Oddly enough, this time I received an exception. The exception does not happen every time.

System.ServiceModel.CommunicationException: The server did not provide a meaningful reply; this might be caused by a contract mismatch, a premature session shutdown or an internal server error.

Server stack trace: 
   at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
   at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs)
   at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
   at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)

Exception rethrown at [0]: 
   at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
   at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)

Answer 1

As I suggested in the comments, please try setting transfermode to streamed to rule out the possibility that this is an issue related to memory pressure (since stream mode should cause wcf to utilize less memory).

When I saw this issue suspected this might be the problem because it only seems to happen to you when making many service calls in rapid succession. In my experience this is often one of two problems: either the proxies aren't being properly closed from the client, or the server is running GC's due to memory pressure.

When the transfermode is buffered, WCF loads the entire dataset for the message response into memory before sending it back to the client. Streamed simply sends the data back without buffering. It tends to be much faster for large data sets, slightly slower for small data sets, and always utilizes less memory(on both the server and client).

Answer 2

To find out what causes your timeouts you should trace what is going on in WCF. Adding the following to your config files will generate a trace file on your client and server:

<system.diagnostics>
   <sources>
       <source name="UserTraceSource" switchValue="Warning, ActivityTracing" >
          <listeners>
              <add name="xml"
                 type="System.Diagnostics.XmlWriterTraceListener"
                 initializeData="C:\logs\UserTraces.svclog" />
          </listeners>
       </source>
   </sources>
   <trace autoflush="true" /> 
</system.diagnostics>

Normally the file will tell you exactly what is going on and what fails. Make sure you have the C:\logs dir and the user has write permissions on the directory.

Configure wcf tracing