Using Custom Performance Counters to measure multi-threaded operation durations
When building WCF Services it's very useful to know how long the individual operations within it's various methods are taking that are outside of the Service itself e.g. calls to other services or to databases as the question is often asked, "Why is this Service [in Production] so slow right now?" By firing up perfmon against the Production box and Admin can check the counters you've created for that Service and tell you which one is taking longer than usual to give you an indication of what steps to take next.
Creating custom counters is quite straightforward:
PerformanceCounter _testCounter = null;
PerformanceCounter _testBaseCounter = null;
string _testCounterName = "Test Counter";
string _testBaseCounterName = "Test Base Counter";
string _performanceCounterCategory = "Test Counters";
if (!PerformanceCounterCategory.Exists(_performanceCounterCategory))
{
CounterCreationData cdTestCounter = new CounterCreationData();
cdTestCounter.CounterName = _testCounterName;
cdTestCounter.CounterType = PerformanceCounterType.AverageTimer32;
CounterCreationData cdTestBaseCounter = new CounterCreationData();
cdTestBaseCounter.CounterName = _testBaseCounterName;
cdTestBaseCounter.CounterType = PerformanceCounterType.AverageBase;
// Add counters to the collection. Make sure Base Counters come after Timer Counters.
CounterCreationDataCollection counterCreationDataCollection = new CounterCreationDataCollection(
new CounterCreationData[] {
cdTestCounter,
cdTestBaseCounter
});
// Create the category and pass the collection to it.
PerformanceCounterCategory.Create(_performanceCounterCategory, "Test Performance Counter.",
PerformanceCounterCategoryType.SingleInstance, counterCreationDataCollection);
}
else
Console.WriteLine(string.Format("Performance Counter Category '{0}' already created.", _performanceCounterCategory));
And you'd think this would be ok in order to use them:
int howLongToWait = new Random().Next(1000, 2000);
Console.WriteLine(string.Format("{0}: Waiting {1} ms", Thread.CurrentThread.ManagedThreadId, howLongToWait));
if (_testCounter != null) _testCounter.RawValue = Stopwatch.GetTimestamp();
Thread.Sleep(howLongToWait);
if (_testBaseCounter != null) _testBaseCounter.Increment();
What you'd expect to happen when you fire up perfmon on your nice new Performance Counter is that you would see the value the same as "howLongToWait" in the code above every time the last line of the code above executes (it reverts to zero shortly after). HOWEVER when you run this code in multiple threads, then the time taken to execute your method will be reported as much shorter than you know it to be; the more threads - the quicker it appears to run!
Luckily the solution is quite simple (and maybe you've thought of it already, but it took me a while...):
long ticksAtStart = Stopwatch.GetTimestamp(); // Record the start-time
Thread.Sleep(howLongToWait); // Wait
if (_testCounter != null) _testCounter.IncrementBy(Stopwatch.GetTimestamp() - ticksAtStart); // Thread Safe!
if (_testBaseCounter != null) _testBaseCounter.Increment(); // This tells the counter one iteration has happened
Here is a full example in case this helps. Run it as a console app and point perfmon at a a Category "Test Counters" and monitor the counter "Test Counter" and you should see values that are more like you'd expect (however depending on the frequency of the updates and the umber of theads you might not see every setting the application makes.)
using System;
using System.Threading;
using System.Diagnostics;
namespace Test
{
class Program
{
static void Main(string[] args)
{
for (int i = 0; i < 10; i++)
{
Console.WriteLine("Scheduling New Task...");
ThreadPool.QueueUserWorkItem(new WaitCallback(DoSomething));
}
Console.ReadLine();
}
private static void DoSomething(object state)
{
TestClass testClass = new TestClass();
testClass.DoSomething();
}
class TestClass
{
PerformanceCounter _testCounter = null; // Main timer counter
PerformanceCounter _testBaseCounter = null; // We need two counters to measure a duration.
string _testCounterName = "Test Counter";
string _testBaseCounterName = "Test Base Counter";
string _performanceCounterCategory = "Test Counters";
public TestClass()
{
// Init Perf Counters in Constructor
if (!PerformanceCounterCategory.Exists(_performanceCounterCategory))
{
CounterCreationData cdTestCounter = new CounterCreationData();
cdTestCounter.CounterName = _testCounterName;
cdTestCounter.CounterType = PerformanceCounterType.AverageTimer32;
CounterCreationData cdTestBaseCounter = new CounterCreationData();
cdTestBaseCounter.CounterName = _testBaseCounterName;
cdTestBaseCounter.CounterType = PerformanceCounterType.AverageBase;
// Add counters to the collection. Make sure Base Counters come after Timer Counters.
CounterCreationDataCollection counterCreationDataCollection = new CounterCreationDataCollection(
new CounterCreationData[] {
cdTestCounter,
cdTestBaseCounter
});
// Create the category and pass the collection to it.
PerformanceCounterCategory.Create(_performanceCounterCategory, "Test Performance Counter.",
PerformanceCounterCategoryType.SingleInstance, counterCreationDataCollection);
}
else
Console.WriteLine(string.Format("Performance Counter Category '{0}' already created.", _performanceCounterCategory));
}
public void DoSomething()
{
if (!PerformanceCounterCategory.Exists(_performanceCounterCategory))
{
Console.WriteLine(string.Format("Not collecting Performance Statistics for this call; PerformanceCounterCategory {0} not found.", _performanceCounterCategory));
return;
}
if (PerformanceCounterCategory.CounterExists(_testCounterName, _performanceCounterCategory))
_testCounter = new PerformanceCounter(_performanceCounterCategory, _testCounterName, false);
if (PerformanceCounterCategory.CounterExists(_testBaseCounterName, _performanceCounterCategory))
_testBaseCounter = new PerformanceCounter(_performanceCounterCategory, _testBaseCounterName, false);
while (true)
{
int howLongToWait = new Random().Next(1000, 2000);
Console.WriteLine(string.Format("{0}: Waiting {1} ms", Thread.CurrentThread.ManagedThreadId, howLongToWait));
long ticksAtStart = Stopwatch.GetTimestamp(); // Record the start-time
Thread.Sleep(howLongToWait); // Wait
if (_testCounter != null) _testCounter.IncrementBy(Stopwatch.GetTimestamp() - ticksAtStart); // Set the Counter
if (_testBaseCounter != null) _testBaseCounter.Increment(); // This tells the counter one iteration has happened
}
}
}
}
}