Simple WCF calls take a lot of time

Question

I am creating a WCF server-client application. However, in my first test, a simple call (the method basically just return true;) takes a lot of time (~5 seconds)

I tried to trace it, and here's a screenshot of the call trace

As you can see between line 2 and 3 ther's a lapse of 5 seconds (although to be honest I don't know what line 2 and 3 means)

At the client's (caller's) configuration, the binding is like this (mostly generated by Visual Studio

    <wsHttpBinding>
        <binding name="WSHttpBinding_IAgent" closeTimeout="00:01:00"
          openTimeout="00:01:00" receiveTimeout="00:10:00" sendTimeout="00:01:00"
          bypassProxyOnLocal="false" transactionFlow="false" hostNameComparisonMode="StrongWildcard"
          maxBufferPoolSize="524288" maxReceivedMessageSize="65536" messageEncoding="Text"
          textEncoding="utf-8" useDefaultWebProxy="true" allowCookies="false">
          <readerQuotas maxDepth="32" maxStringContentLength="8192" maxArrayLength="16384"
            maxBytesPerRead="4096" maxNameTableCharCount="16384" />
          <reliableSession ordered="true" inactivityTimeout="00:10:00"
            enabled="false" />
          <security mode="None">
          </security>
        </binding>
      </wsHttpBinding>

and at the server

<wsHttpBinding>
    <binding name="WSHttpBinding_IAgent" closeTimeout="00:01:00"
      openTimeout="00:01:00" receiveTimeout="00:05:00" sendTimeout="00:05:00"
      bypassProxyOnLocal="false" transactionFlow="false" hostNameComparisonMode="StrongWildcard"
      maxBufferPoolSize="16777216" maxReceivedMessageSize="16777216"
      messageEncoding="Text" textEncoding="utf-8" useDefaultWebProxy="true"
      allowCookies="false">
      <readerQuotas maxDepth="32" maxStringContentLength="16777216"
        maxArrayLength="16384" maxBytesPerRead="16384" maxNameTableCharCount="16384" />
      <reliableSession ordered="true" inactivityTimeout="00:10:00"
        enabled="false" />
      <security mode="None"/>
    </binding>

And the way I call it something like this

var client = new AgentClient(binding, BuildEndpointAddress(hostName, port));
for(int i =0; i<10; i++)
    client.IsAlive(); //this call is very slow despite just returning true;
    // subsequent calls are also slow so probably not because of wake-up time

Note for this test, both server and client are in the same computer so it couldn't be a network issue. Any idea what's causing the slowness or how I can find more information to troubleshoot this?

Withy

Is it faster on subsequent calls? Could be compiling or "waking up" on the first call. – Discourage

no I tried looping the call client.IsAlive() several times, and subsequent calls show no difference from the first one. – Withy

@dbaseman To be precise, the duration does vary, but it seems to be because of randomness than systematic. For example, in my first test the duration of consecutive calls (same method) was 4 seconds, 4, 6, 2, 4, 3, 8, and when I retry it was: 9, 3, 2, 4, 5, 5, 3 – Withy

Did you try this test NOT using the same computer? Here's a link to an article that talk about a 5 second delay when running on localhost: support.microsoft.com/kb/2020447 Unfortunately, it mentions a large amount of data (> 64KB) in the scenario. – Heliotype

@RichardMorgan I just tried it now, and using different computer doesn't improve it either. Neither did changing the hostname to IP address – Withy

If you need to look at the network traffic fiddler2 is great: fiddler2.com/fiddler2 – Sanorasans

Answer 1

Application lifetime is not specified in your post and I will assume that you start the client app and call WCF service at first time without warming it up.

Timing will make sense in that case.

.NET does lots of hidden work to initialize ChannelFactory and Server if it was not warmed up despite using of lightweight binding and message.

That is nature of WCF and should not cause much issues because after warming up communications are really fast.

Try to call your service two times in a row in one app session measuring time for both calls. If both calls take comparable time my assumption is wrong.

In case you would like to see my question and compare environment -

Why is the first WCF client call slow?

Suffice

Answer 2

To find more information you may want to leverage Event Tracing for Windows (ETW) with the Perfmonitor tool from the BCL team's codeplex site. One of the many features of this tool is that it can sample the instruction pointer every millisecond and give you the managed call stack for each sample. This may give you an indication of what the code is doing during those lapses of time.

ps. Here's another link to articles that use this tool: http://naveensrinivasan.com/category/net/etw-net/

Weihs

Answer 3

Try configuring WCF trace logging - details here: http://msdn.microsoft.com/en-us/library/ms733025.aspx

I've had all sorts of hair-pulling-out issues with WCF, but that kind of performance issue on the same box is not something I've ever seen before. As others have said, the most likely cause would be the "warming up" of the server, but if you are calling it several times then this should not be an issue. Have you tried calling the code multiple times from within your client app?

Newmodel