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 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 :
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.
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 :
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
Creating Instances : we are going to create a new instance of performance counter per operation
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
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
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
Here is the command to capture dump:
Complete source code is here