Трейс производительности WCF инфраструктуры

Достаточно часто, задают вопросы относительно оверхеда магии WCF и увы под рукой ничего нет, кроме как вычитания общего времени исполнения запроса на клиенте и сервисе. Конечно решение неплохое, но оно хорошо работает, когда есть эти самые логи и когда запросов в целом то немного.
В обозримом будущем, предстоит на работе защищать несколько своих решений и пришло в голову следующее очень просто решение, на базе пары интерфейсов:

• IDispatchMessageInspector
• IClientMessageInspector

Общая суть идеи состоит в добавлении нескольких заголовков в посылаемые сообщения и обычный трейс разницы времени исполнения, между текущим и переданным временем.
Общая схема вызовов клиентских и серверных инспекторов показана ниже: 

BeforeSendRequest-[extend request message 1]-> 
AfterReceiveRequest-[trace]->
BeforeSendReply-[extend reply message 2]->
AfterReceiveReply-[trace]

Всего решение подразумевает добавление двух заголовков:
 

start : DateTime
request_correlation : GUID

При пересылке сообщения с запросом [1], клиентский инспектор добавляет текущее время и идентификатор корреляции. Передаваемое время используется на вызываемой стороне, для замера времени пересылки сообщения от клиента сервису, а идентификатор необходим наоборот уже самому клиенту, для определения времени пересылки ответного сообщения на переданный запрос.
 

        
#region IClientMessageInspector Members

public void AfterReceiveReply(ref Message reply, object correlationState)
{
   TraceTime(reply, (OperationCorrelationState)correlationState);
}

public object BeforeSendRequest(ref Message request, System.ServiceModel.IClientChannel channel)
{
   var correlation = OperationCorrelationState.Create(request.Headers.Action);
   AddTraceHeaders(request, correlation);
   return correlation;
}

#endregion

private static void AddTraceHeaders(Message message, OperationCorrelationState correlation)
{
   message.Headers.Add(MessageHeader.CreateHeader(RequestCorrelationHeaderName, Namespace, correlation.Identity, false));
   message.Headers.Add(MessageHeader.CreateHeader(StartTimeHeaderName, Namespace, DateTime.UtcNow, false));
}

private static void TraceTime(Message message, OperationCorrelationState correlation)
{
   var startTime = message.Headers.GetHeader<DateTime>(StartTimeHeaderName, Namespace);

   var ts = DateTime.UtcNow - startTime;

   Console.WriteLine("{0}[{1}] : {2}ms", correlation.Name.Split('/').Last(), correlation.Identity, ts.Milliseconds);
   return;
   }
}

public class OperationCorrelationState
{
   public Guid Identity { get; set; }
   public string Name { get; set; }

   public static OperationCorrelationState Create(string name)
   {
      return new OperationCorrelationState
      {
            Identity = Guid.NewGuid(),
            Name = name
      };
   }
}

 
Первый замер времени выполняется на сервисе, сразу после приема входного сообщения[1]

             
public object AfterReceiveRequest(ref System.ServiceModel.Channels.Message request, System.ServiceModel.IClientChannel channel, System.ServiceModel.InstanceContext instanceContext)
{
   var correlation = new OperationCorrelationState
   {
      Name = request.Headers.Action,
      Identity = Guid.Parse(request.Headers.GetHeader<string>(RequestCorrelationHeaderName, Namespace))
   };
            
   TraceTime(request, correlation);
   return correlation;
}

public void BeforeSendReply(ref System.ServiceModel.Channels.Message reply, object correlationState)
{
   AddTraceHeaders(reply, (OperationCorrelationState)correlationState);
}

private static void TraceTime(Message message, OperationCorrelationState correlation)
{
   var startTime = message.Headers.GetHeader<DateTime>(StartTimeHeaderName, Namespace);

   var ts = DateTime.UtcNow - startTime;

   Console.WriteLine("{0}[{1}] : {2}ms", correlation.Name.Split('/').Last(), correlation.Identity, ts.Milliseconds);
   return;
}

Важно обратить внимание, что после приема запроса (метод AfterReceiveRequest), сервисный инспектор извлекает из заголовков сообщения клиентский идентификатор и формирует на его основе новый, передавая его дальше методу BeforeSendReply, который его в свою очередь добавит в заголовок вместе с текущим временем.
Таким образом, на клиенте и на сервере можно наблюдать время передачи сообщений и даже делать корреляцию между ними

Конечно, здесь не учитывается время затрачиваемое на сериализацию/десериализацию, но можно достаточно наглядно оценить именно эффективность выбранного транспорта.

Полный код решения приведен ниже

using System;
using System.Linq;
using System.ServiceModel.Channels;
using System.ServiceModel.Description;
using System.ServiceModel.Dispatcher;

namespace Sandbox.ServiceModel
{
    public class PerformanceTraceMessageInspector : IDispatchMessageInspector, IClientMessageInspector
    {
        const string StartTimeHeaderName = "start";
        const string RequestCorrelationHeaderName = "request_correlation";
        const string Namespace = "http://tempuri.org/sandbox";

        #region IDispatchMessageInspector Members

        public object AfterReceiveRequest(ref System.ServiceModel.Channels.Message request, System.ServiceModel.IClientChannel channel, System.ServiceModel.InstanceContext instanceContext)
        {
            var correlation = new OperationCorrelationState
            {
                Name = request.Headers.Action,
                Identity = Guid.Parse(request.Headers.GetHeader<string>(RequestCorrelationHeaderName, Namespace))
            };
            
            TraceTime(request, correlation);
            return correlation;
        }

        public void BeforeSendReply(ref System.ServiceModel.Channels.Message reply, object correlationState)
        {
            AddTraceHeaders(reply, (OperationCorrelationState)correlationState);
        }

        private static void TraceTime(Message message, OperationCorrelationState correlation)
        {
            var startTime = message.Headers.GetHeader<DateTime>(StartTimeHeaderName, Namespace);

            var ts = DateTime.UtcNow - startTime;

            Console.WriteLine("{0}[{1}] : {2}ms", correlation.Name.Split('/').Last(), correlation.Identity, ts.Milliseconds);
            return;
        }

        #endregion

        #region IClientMessageInspector Members

        public void AfterReceiveReply(ref Message reply, object correlationState)
        {
            TraceTime(reply, (OperationCorrelationState)correlationState);
        }

        public object BeforeSendRequest(ref Message request, System.ServiceModel.IClientChannel channel)
        {
            var correlation = OperationCorrelationState.Create(request.Headers.Action);
            AddTraceHeaders(request, correlation);
            return correlation;
        }

        #endregion

        private static void AddTraceHeaders(Message message, OperationCorrelationState correlation)
        {
            message.Headers.Add(MessageHeader.CreateHeader(RequestCorrelationHeaderName, Namespace, correlation.Identity, false));
            message.Headers.Add(MessageHeader.CreateHeader(StartTimeHeaderName, Namespace, DateTime.UtcNow, false));
        }
    }

    public class OperationCorrelationState
    {
        public Guid Identity { get; set; }
        public string Name { get; set; }

        public static OperationCorrelationState Create(string name)
        {
            return new OperationCorrelationState
            {
                Identity = Guid.NewGuid(),
                Name = name
            };
        }
    }

    public class PerformanceTraceMessageBehavior : Attribute, IContractBehavior
    {
        #region IContractBehavior Members

        public void AddBindingParameters(ContractDescription contractDescription, ServiceEndpoint endpoint, BindingParameterCollection bindingParameters)
        {
        }

        public void ApplyClientBehavior(ContractDescription contractDescription, ServiceEndpoint endpoint, ClientRuntime clientRuntime)
        {
            clientRuntime.MessageInspectors.Add(new PerformanceTraceMessageInspector());
        }

        public void ApplyDispatchBehavior(ContractDescription contractDescription, ServiceEndpoint endpoint, DispatchRuntime dispatchRuntime)
        {
            dispatchRuntime.MessageInspectors.Add(new PerformanceTraceMessageInspector());
        }

        public void Validate(ContractDescription contractDescription, ServiceEndpoint endpoint)
        {
        }

        #endregion
    }
}