真实世界：使用WCF扩展记录服务调用时间

WCF 可扩展性

WCF 提供了许多扩展点供开发人员自定义运行时行为。 WCF 在 Channel Layer 之上还提供了一个高级运行时，主要是针对应用程序开发人员。在 WCF 文档中，它常被称为服务模型层（Service Model Layer）。该高级运行时主要由一个称作 Dispatcher（在 ServiceHost 的 Context 中）的组件和一个称作 Proxy（在客户端的 Context 中）的组件组成。

（图片引自 MSDN Magazine : Extending WCF with Custom Behaviors）

每个扩展点都使用接口定义来扩展。

Stage	Interceptor Interface	Description
Parameter Inspection	IParameterInspector	Called before and after invocation to inspect and modify parameter values.
Message Formatting	IDispatchMessageFormatter IClientFormatter	Called to perform serialization and deserialization.
Message Inspection	IDispatchMessageInspector IClientMessageInspector	Called before send or after receive to inspect and replace message contents.
Operation Selection	IDispatchOperationSelector IClientOperationSelector	Called to select the operation to invoke for the given message.
Operation Invoker	IOperationInvoker	Called to invoke the operation.

Behavior 是一种特殊类型的类，它在 ServiceHost/ChannelFactory 初始化过程中扩展运行时行为。WCF 有四种类型的行为：服务行为、终结点行为、契约行为和操作行为。

Scope	Interface	Potential Impact
		Service	Endpoint	Contract	Operation
Service	IServiceBehavior	✗	✗	✗	✗
Endpoint	IEndpointBehavior		✗	✗	✗
Contract	IContractBehavior			✗	✗
Operation	IOperationBehavior				✗

每种行为类型也是通过不同的接口定义来扩展，它们都共用一组相同的方法。一个例外是，IServiceBehavior 没有 ApplyClientBehavior 方法，因为服务行为不能用于客户端。

Method	Description
Validate	Called just before the runtime is built—allows you to perform custom validation on the service description.
AddBindingParameters	Called in the first step of building the runtime, before the underlying channel is constructed, allows you to add parameters to influence the underlying channel stack.
ApplyClientBehavior	Allows behavior to inject proxy (client) extensions. Note that this method is not present on IServiceBehavior.
ApplyDispatchBehavior	Allows behavior to inject dispatcher extensions.

WCF扩展点

（图片引自 lovecindywang = lovecherry 博客）

案例：使用WCF扩展记录服务调用时间

服务定义：

  [ServiceContract]
  public interface ICalculatorService
  {
    [OperationContract]
    int Add(int a, int b);
  }

服务实现：

  public class CalculatorService : ICalculatorService
  {
    public int Add(int a, int b)
    {
      return a + b;
    }
  }

配置文件：

  <system.serviceModel>
    <services>
      <service name="WcfExtensibilityTestServiceConsole.CalculatorService">
        <endpoint address="" binding="netTcpBinding" bindingConfiguration="" 
                  contract="WcfExtensibilityTestServiceConsole.ICalculatorService" 
                  name="myCalculatorServiceEndpoint"/>
        <endpoint address="mex" binding="mexTcpBinding" contract="IMetadataExchange"/>
        <host>
          <baseAddresses>
            <add baseAddress="net.tcp://localhost:12345/CalculatorService"/>
          </baseAddresses>
        </host>
      </service>
    </services>
    <behaviors>
      <serviceBehaviors>
        <behavior>
          <serviceMetadata/>
          <serviceDebug includeExceptionDetailInFaults="true"/>
        </behavior>
      </serviceBehaviors>
    </behaviors>
  </system.serviceModel>

问题描述

现在需要记录每次服务调用执行所需的时间，比如可以将测量的方法执行时间传递给 PerformanceCounter 用于性能计数，或者直接写入到日志中等。

方式一：直接在方法内测量

  public class CalculatorService : ICalculatorService
  {
    public int Add(int a, int b)
    {
      Stopwatch watch = Stopwatch.StartNew();

      int result = a + b;
      Thread.Sleep(TimeSpan.FromMilliseconds(123)); // waste time here

      Debug.WriteLine(string.Format("Method [{0}] execution cost [{1}] milliseconds.",
        "Add", watch.ElapsedMilliseconds));

      return result;
    }
  }

这种方法浅显易懂，但如果服务所提供的功能过多，会导致大量冗余代码。

方式二：形成测量类简化代码

  public class Measure : IDisposable
  {
    private Stopwatch _watch = null;

    protected Measure(string methodName)
    {
      MethodName = methodName;
      _watch = new Stopwatch();
    }

    public string MethodName { get; private set; }

    public void Start()
    {
      _watch.Start();
    }

    public void Stop()
    {
      _watch.Stop();

      Debug.WriteLine(string.Format("Measure method [{0}] execution cost [{1}] milliseconds.",
        MethodName, _watch.ElapsedMilliseconds));
    }

    public static Measure StartNew(string methodName)
    {
      Measure m = new Measure(methodName);
      m.Start();
      return m;
    }

    public void Dispose()
    {
      Stop();
      _watch = null;
    }
  }

  public class CalculatorService : ICalculatorService
  {
    public int Add(int a, int b)
    {
      using (var measure = Measure.StartNew("Add"))
      {
        Thread.Sleep(TimeSpan.FromMilliseconds(123)); // waste time here
        return a + b;
      }
    }
  }

此种方式简化了代码，但仍然需要在各自方法内实现，并需提供方法名作为参数。

使用 Message Inspection 来解决问题

我们定义类 IncomingMessageLoggerInspector 来实现 IDispatchMessageInspector 接口。

    #region IDispatchMessageInspector Members

    public object AfterReceiveRequest(
      ref Message request, 
      IClientChannel channel, 
      InstanceContext instanceContext)
    {
      var context = OperationContext.Current;
      if (context == null) return null;

      var operationName = ParseOperationName(context.IncomingMessageHeaders.Action);

      return MarkStartOfOperation(
        context.EndpointDispatcher.ContractName, operationName, 
        context.SessionId);
    }

    public void BeforeSendReply(ref Message reply, object correlationState)
    {
      var context = OperationContext.Current;
      if (context == null) return;

      var operationName = ParseOperationName(context.IncomingMessageHeaders.Action);

      MarkEndOfOperation(
        context.EndpointDispatcher.ContractName, operationName, 
        context.SessionId, correlationState);
    }

    #endregion

通过服务的当前上下文实例，我们可以获取到服务被调用的契约名称 ContractName，并且可以在 IncomingMessageHeaders 总解析出被调用的 OperationName。

我们在方法 MarkStartOfOperation 中启动 Stopwatch 开始测量执行时间，在方法执行完毕后服务模型会调用 BeforeSendReply 并将 Stopwatch 实例引用传递至 correlationState，此时我们可以在方法 MarkEndOfOperation 中解决时间测量，并打印日志。

    #region Private Methods

    private static string ParseOperationName(string action)
    {
      if (string.IsNullOrEmpty(action)) return action;

      string actionName = action;

      int index = action.LastIndexOf('/');
      if (index >= 0)
      {
        actionName = action.Substring(index + 1);
      }

      return actionName;
    }

    private static object MarkStartOfOperation(
      string inspectorType, string operationName, string sessionId)
    {
      var message = string.Format(CultureInfo.InvariantCulture,
        "Operation [{0}] was called at [{1}] on [{2}] in thread [{3}].",
        operationName, inspectorType,
        DateTime.Now.ToString(@"yyyy-MM-dd HH:mm:ss.ffffff", CultureInfo.InvariantCulture),
        Thread.CurrentThread.ManagedThreadId);

      Debug.WriteLine(message);

      return Stopwatch.StartNew();
    }

    private static void MarkEndOfOperation(
      string inspectorType, string operationName, 
      string sessionId, object correlationState)
    {
      var watch = (Stopwatch)correlationState;
      watch.Stop();

      var message = string.Format(CultureInfo.InvariantCulture,
        "Operation [{0}] returned after [{1}] milliseconds at [{2}] on [{3}] in thread [{4}].",
        operationName, watch.ElapsedMilliseconds, inspectorType,
        DateTime.Now.ToString(@"yyyy-MM-dd HH:mm:ss.ffffff", CultureInfo.InvariantCulture),
        Thread.CurrentThread.ManagedThreadId);

      Debug.WriteLine(message);
    }

    #endregion

此时，我们需要定义 EndpointBehavior 来讲 Inspector 设置到 DispatchRuntime 中。

  public class IncomingMessageLoggerEndpointBehavior : IEndpointBehavior
  {
    #region IEndpointBehavior Members

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

    public void ApplyClientBehavior(
      ServiceEndpoint endpoint, 
      ClientRuntime clientRuntime)
    {
    }

    public void ApplyDispatchBehavior(
      ServiceEndpoint endpoint, 
      EndpointDispatcher endpointDispatcher)
    {
      if (endpointDispatcher != null)
      {
        endpointDispatcher.DispatchRuntime.MessageInspectors.Add(
          new IncomingMessageLoggerInspector());
      }
    }

    public void Validate(ServiceEndpoint endpoint)
    {
    }

    #endregion
  }

然后，我们在 ServiceHost 实例化后，未Open前，将 IncomingMessageLoggerEndpointBehavior 添加至 Endpoint 的 Behaviors 中。

  class Program
  {
    static void Main(string[] args)
    {
      ServiceHost host = new ServiceHost(typeof(CalculatorService));

      foreach (var endpoint in host.Description.Endpoints)
      {
        endpoint.Behaviors.Add(new IncomingMessageLoggerEndpointBehavior());
      }

      host.Opened += new EventHandler(delegate(object obj, EventArgs e)
      {
        Debug.WriteLine(typeof(CalculatorService).Name + " 服务已经启动！");
      });

      host.Open();

      Console.ReadKey();
    }
  }

使用 WcfTestClient.exe 调用服务，执行 2 + 3 查看结果，

在 Debug 输出中可以看到，

使用配置文件定制

使用配置文件定制扩展的优点就是可以按需添加和删除扩展，而无需改动代码。比如当发现系统有性能问题时，添加该扩展来查看具体哪个方法执行速度慢。

需要定义类来实现 BehaviorExtensionElement 抽象类。

  public class IncomingMessageLoggerEndpointBehaviorExtension : BehaviorExtensionElement
  {
    public override Type BehaviorType
    {
      get { return typeof(IncomingMessageLoggerEndpointBehavior); }
    }

    protected override object CreateBehavior()
    {
      return new IncomingMessageLoggerEndpointBehavior();
    }
  }

在配置文件中添加扩展项，

    <extensions>
      <behaviorExtensions>
        <add name="incomingMessageLogger" 
             type="WcfExtensibilityTestServiceConsole.Extensions.IncomingMessageLoggerEndpointBehaviorExtension, WcfExtensibilityTestServiceConsole"/>
      </behaviorExtensions>
    </extensions>

在终结点行为中添加该扩展定义，

    <behaviors>
      <serviceBehaviors>
        <behavior>
          <serviceMetadata/>
          <serviceDebug includeExceptionDetailInFaults="true"/>
        </behavior>
      </serviceBehaviors>
      <endpointBehaviors>
        <behavior>
          <incomingMessageLogger/>
        </behavior>
      </endpointBehaviors>
    </behaviors>

使用 ServiceBehavior 扩展

同理，如果服务实现了多个 Endpoint，则想在所有 Endpoint 上添加该扩展，除了可以逐个添加或者使用 behaviorConfiguration 来配置。

另一个方法是可以借助 IServiceBehavior 的扩展实现。

  public class IncomingMessageLoggerServiceBehavior : IServiceBehavior
  {
    #region IServiceBehavior Members

    public void AddBindingParameters(
      ServiceDescription serviceDescription, 
      ServiceHostBase serviceHostBase, 
      Collection<ServiceEndpoint> endpoints, 
      BindingParameterCollection bindingParameters)
    {
    }

    public void ApplyDispatchBehavior(
      ServiceDescription serviceDescription, 
      ServiceHostBase serviceHostBase)
    {
      if (serviceHostBase != null)
      {
        foreach (ChannelDispatcher channelDispatcher in serviceHostBase.ChannelDispatchers)
        {
          foreach (EndpointDispatcher endpointDispatcher in channelDispatcher.Endpoints)
          {
            endpointDispatcher.DispatchRuntime.MessageInspectors.Add(
              new IncomingMessageLoggerInspector());
          }
        }
      }
    }

    public void Validate(
      ServiceDescription serviceDescription, 
      ServiceHostBase serviceHostBase)
    {
    }

    #endregion
  }

原理相同，仅是遍历通道分配器中所有的终结点，逐一添加 Inspector。

同理，如果需要在配置文件中使用，也需要实现一个 BehaviorExtensionElement 类。

  public class IncomingMessageLoggerServiceBehaviorExtension : BehaviorExtensionElement
  {
    public override Type BehaviorType
    {
      get { return typeof(IncomingMessageLoggerServiceBehavior); }
    }

    protected override object CreateBehavior()
    {
      return new IncomingMessageLoggerServiceBehavior();
    }
  }

此时的配置文件描述如下：

    <behaviors>
      <serviceBehaviors>
        <behavior>
          <serviceMetadata/>
          <serviceDebug includeExceptionDetailInFaults="true"/>
          <incomingMessageLogger/>
        </behavior>
      </serviceBehaviors>
    </behaviors>
    <extensions>
      <behaviorExtensions>
        <add name="incomingMessageLogger" 
             type="WcfExtensibilityTestServiceConsole.Extensions.IncomingMessageLoggerServiceBehaviorExtension, WcfExtensibilityTestServiceConsole"/>
      </behaviorExtensions>
    </extensions>

参考资料

• Extending WCF with Custom Behaviors
• WCF Extensibility – Message Inspectors
• WCF扩展
• Introduction to Extensibility
• Carlos Figueira MSDN blog