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:
-
Create Performance Object ( PerformanceCounterCategory )
-
Create Instances ( PerformanceCounter )
-
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
-
captureDumpAfterSeconds
– the min number of seconds after which dump should be created if the WCF request is not completed
-
dumpCmd
– the debugger command to capture the dump
-
dumpLimit
– the max number of dumps to capture
-
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