Capturing WCF Request Execution Time
Published Nov 16 2018 06:41 AM 2,779 Views
Microsoft
First published on MSDN on Sep 18, 2012

Complete source code is here

WCF includes a large set of performance counters to help you gauge your application’s performance.  These counters can help you determine total number of WCF requests executed, request per seconds, number of faults etc. But one basic counter is missing : Request Execution Time

If you host your WCF Services in IIS, you can use ASP.NET Request Execution Time to capture the WCF operation execution time. Only limitation of using ASP.NET counter is, it will not tell us which WCF operation was taking long time to execute. You can use IIS logs to determine which *.SVC file was taking time to execute.

Fortunately, WCF is extensible. We can use Message Inspectors to capture WCF operation execution time. In this blog, I am going to show how to implement Message Inspectors and create a custom performance counter to capture WCF request execution time.

With the help of Message Inspectors, we can also capture a dump when any WCF request is taking more than the specified time.

Update: comparing TimeTaken with Call Duration

Call Duration is a default WCF performance counter available at all three levels (Service, Endpoint and Operation). The value is calculated based on this equation: ratio of the total elapsed time of the sample interval to the number of operations completed during that time.

Here is the perfmon logs with both TimeTaken and Call Duration.

Message Inspector

Message Inspectors triggers two events, one after the incoming message is received and another just before the outgoing message is pushed on to the wire. To create message inspector, we just have to implement IDispatchMessageInspector as shown :

class ServiceModelTimeTakenMessageInspector : IDispatchMessageInspector
{


public object AfterReceiveRequest(ref Message request,
IClientChannel channel,
InstanceContext instanceContext)
{
long ticks = DateTime.Now.Ticks;
return ticks;
}

public void BeforeSendReply(ref Message reply,
object correlationState)
{
long startime = (long)correlationState;

TimeSpan timetaken = new TimeSpan(DateTime.Now.Ticks - startime);

}
}



Note : the return value of AfterReceiveRequest will be passed as a parameter in the BeforeSendReply() method.



We will capture the start time in the AfterReceiveRequest() method and send this start time as correlation state to the BeforeSendReply(). In the BeforeSendReply() we will subtract current time with the start time to calculate the request execution time.



Endpoint Behavior



With the help of endpoint behavior you can add message inspectors to the DispatchRuntime. To create endpoint behavior, we just have to implement IEndpointBehavior as shown :




class ServiceModelTimeTakenEndpointBehavior : IEndpointBehavior
{
public void ApplyDispatchBehavior(ServiceEndpoint endpoint,
EndpointDispatcher endpointDispatcher)
{
endpointDispatcher.DispatchRuntime.MessageInspectors.Add(
new ServiceModelTimeTakenMessageInspector(serviceModelTimeTakenConfig));
}

}



Custom Performance Counter



Creating customer performance counter in .NET is very easy, we just have to follow these three steps:




  1. Create Performance Object ( PerformanceCounterCategory )


  2. Create Instances ( PerformanceCounter )


  3. Set Value ( Dcrement(), Increment(), RawValue() )



Creating Performance Object : name of our custom performance object is ServiceModelTimeTaken




static public void CreateCategory()
{
//
// check if the category exists
//
if (!PerformanceCounterCategory.Exists("ServiceModelTimeTaken"))
{
CounterCreationDataCollection ccdc = new CounterCreationDataCollection();
CounterCreationData ccd = new CounterCreationData("Executing", "",
PerformanceCounterType.NumberOfItems32);
ccdc.Add(ccd);
ccd = new CounterCreationData("Hits", "",
PerformanceCounterType.NumberOfItems32);
ccdc.Add(ccd);
ccd = new CounterCreationData("TimeTaken", "",
PerformanceCounterType.NumberOfItems32);
ccdc.Add(ccd);

PerformanceCounterCategory.Create("ServiceModelTimeTaken",
"Custom performance counter to capture WCF operation timetaken",
PerformanceCounterCategoryType.MultiInstance, ccdc);
}
}



Creating Instances : we are going to create a new instance of performance counter per operation




//
// check if the category exists
//
if (PerformanceCounterCategory.Exists("ServiceModelTimeTaken"))
{
//
// create instance
//
ret = new GroupPerformanceCounter();
ret.Executing = new PerformanceCounter("ServiceModelTimeTaken", "Executing", action, false);
ret.Hits = new PerformanceCounter("ServiceModelTimeTaken", "Hits", action, false);
ret.TimeTaken = new PerformanceCounter("ServiceModelTimeTaken", "TimeTaken", action, false);

}



Assigning values to Performance Counters : In the AfterReceiveRequests() we will increment “executing” custom performance counter. And in the BeforeSendReply(), we will decrement “executing” counter and increment “Hits”  counter and set the execution time to “timetaken” counter as shown




gpc.Executing.Decrement();
gpc.Hits.Increment();
gpc.TimeTaken.RawValue = excutionTime;



To reduce the overhead of logging value to these custom performance counter, we will assign the counter values in a separate thread.



Web.config or App.config



At the WCF Service side, we have to modify the Web.config or App.config file to add our custom Message Inspector as shown:



Note : we need to copy the ServiceModelTimeTaken.dll to WCF service’s bin folder




<system.serviceModel>
<extensions>
<behaviorExtensions>
<add name="ServiceModelTimeTakenExtensionName"
type="ServiceModelTimeTaken.ServiceModelTimeTakenBehaviorExtensionElement,
ServiceModelTimeTaken, Version=1.0.0.0,
Culture=neutral, PublicKeyToken=null"/>

</behaviorExtensions>
</extensions>
<behaviors>
<endpointBehaviors>
<behavior name="ServiceModelTimeTakenBehavior">
<!-- only performance counters -->
<ServiceModelTimeTakenExtensionName />

<!-- performance counters and capture a dump -->
<!--<ServiceModelTimeTakenExtensionName captureDumpAfterSeconds="180"
dumpCmd="c:\temp\dumpCmd.bat"

dumpLimit="13"
pollIntervalSeconds="60" />-->

</behavior>
</endpointBehaviors>
</behaviors>
<services>
<service behaviorConfiguration="MexBehavior" name="Host.StockMarket">
<endpoint behaviorConfiguration="ServiceModelTimeTakenBehavior"
binding="basicHttpBinding"
contract="Host.IStockMarket"
listenUriMode="Explicit"/>
</service>
</services>
</system.serviceModel>



Capturing a dump



For more details please click here



This custom message inspector can also capture a dump when any WCF operation is taking more than the specified number of seconds. This dump is more useful as it is captured when the request is still executing, so you will see one thread in the dump executing the long running WCF request.  With others tool, dumps are captured only after the request execution is completed.



This custom message inspector will monitor all WCF requests and once it sees any WCF request not getting completed within the “ captureDumpAfterSeconds ” seconds, it will execute the “ dumpCmd ” to capture a dump.



In the Web.Config or App.Config, we need to set these parameters




  1. captureDumpAfterSeconds – the min number of seconds after which dump should be created if the WCF request is not completed


  2. dumpCmd – the debugger command to capture the dump


  3. dumpLimit – the max number of dumps to capture


  4. pollIntervalSeconds – time interval between each check for long running WCF requests



Here is the sample Web.config or App.config file




<system.serviceModel>
<extensions>
<behaviorExtensions>
<add name="ServiceModelTimeTakenExtensionName"
type="ServiceModelTimeTaken.ServiceModelTimeTakenBehaviorExtensionElement,
ServiceModelTimeTaken, Version=1.0.0.0,
Culture=neutral, PublicKeyToken=null"/>

</behaviorExtensions>
</extensions>
<behaviors>
<endpointBehaviors>
<behavior name="ServiceModelTimeTakenBehavior">
<!-- only performance counters -->
<!--<ServiceModelTimeTakenExtensionName />-->

<!-- performance counters and capture a dump -->
<ServiceModelTimeTakenExtensionName captureDumpAfterSeconds="180"
dumpCmd="c:\temp\dumpCmd.bat"
dumpLimit="13"
pollIntervalSeconds="60" />

</behavior>
</endpointBehaviors>
<serviceBehaviors>
<behavior name="MexBehavior">
<serviceMetadata httpGetEnabled="true"/>
</behavior>
</serviceBehaviors>
</behaviors>
<services>
<service behaviorConfiguration="MexBehavior" name="Host.StockMarket">
<clear/>
<endpoint behaviorConfiguration="ServiceModelTimeTakenBehavior"
binding="basicHttpBinding"
contract="Host.IStockMarket"
listenUriMode="Explicit"/>
<endpoint address="mex"
binding="basicHttpBinding"
bindingConfiguration=""
contract="IMetadataExchange"/>
<host>
<baseAddresses>
<add baseAddress="http://localhost:8080/IStockMarket"/>
</baseAddresses>
</host>
</service>
</services>
</system.serviceModel>



Here is the command to capture dump:




"c:\Program Files\Debugging Tools for Windows (x64)\adplus.exe" -hang -p %1 -Do -o c:\temp




Source Code



Complete source code is here

Version history
Last update:
‎Nov 16 2018 06:41 AM
Updated by: