Why is the first WCF client call slow?

Question

I am trying to figure out why the first WCF call after client application start takes much more time comparing to second one.

What I did to test that:

1. Implemented simple self hosted WCF Server and console client.
2. Server IS warmed up - I run it and call method several times before running test.
3. Binding is basicHttpBinding to reduce network and security overhead.
4. Testing scenario - start console client app, making two identical WCF service calls in a row.

In my tests I see ~700 milliseconds for first call and ~3 milliseconds for second call.

Almost a second seems to be too much time for JIT compiler. I would accept if that time is used to initialize some complicated infrastructure like ObjectContext in Entity Framework but my code is very simple and proxy classes are already compiled.

I also tried netNamedPipeBinding binding. Result proves pattern - first call takes ~800 ms, second call takes ~8 ms.

Will appreciate if anybody can explain why the first service call takes so much time.

Tested in Win 7 64 bit.

My implementation is below.

Contract:

[ServiceContract]
public interface ICounter
{
        [OperationContract]
        int Add(int num);
}

Service Implementation:

public class CounterService: ICounter
{
        private int _value = 0;

        public int Add(int num)
        {
            _value += num;
            Console.WriteLine("Method Add called with argument {0}. Method  returned {1}", num, _value);
            return _value;
        }
}

Server Implementation:

class Program
{
    static void Main(string[] args)
    {
        Uri baseAddress = new Uri("http://localhost:8080/Service");

        // Create the ServiceHost.
        using (ServiceHost host = new ServiceHost(typeof(CounterService), baseAddress))
        {
            host.Open();

            Console.WriteLine("The service is ready at {0}", baseAddress);
            Console.WriteLine("Press <Enter> to stop the service.");
            Console.ReadLine();

            // Close the ServiceHost.
            host.Close();
        }
    }
}

Server Configuration:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <system.serviceModel>
    <services>
      <service name="Server.CounterService">
        <endpoint address="base" binding="basicHttpBinding" name="baseDefault"
          contract="Contract.ICounter" />
        <endpoint address="net.pipe://localhost/Service/netNamedPipe"
          binding="netNamedPipeBinding" name="netNamedPipeDefault" contract="Contract.ICounter" />
        <endpoint address="mex" binding="mexHttpBinding" contract="IMetadataExchange" />
      </service>
    </services>
    <behaviors>
      <serviceBehaviors>
        <behavior name="">
          <serviceMetadata httpGetEnabled="true" />
        </behavior>
      </serviceBehaviors>
    </behaviors>
  </system.serviceModel>
</configuration>

Client Implementation (CounterProxy is generated from service reference):

Stopwatch stopWatch = new Stopwatch();
stopWatch.Start();

using (var proxy = new CounterProxy.CounterClient(_endpointConfigurationName))
{
    output = proxy.Add(1);
}

stopWatch.Stop();
// Get the elapsed time as a TimeSpan value.
TimeSpan ts = stopWatch.Elapsed;

Function that contains that code called two times in a row.

Client Configuration:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  <system.serviceModel>
    <client>
      <endpoint address="http://localhost:8080/Service/base" binding="basicHttpBinding"
          contract="CounterProxy.ICounter"
          name="baseDefault" />
    </client>
  </system.serviceModel>
</configuration>

Answer 1

Usually the first call takes more time because in that call the Channel Factory is instantiated and prepared ready for the communication and that costs time. The created Channel Factory will be cached and reused in subsequent calls and so the time will be less.

http://social.msdn.microsoft.com/Forums/en/wcf/thread/43f89088-546b-46b0-adf8-214deb1741bd