Written by The performance measurement is one of the most important things in the software development. Performance should be addressed throughout the whole development process and not only when the risks become problems. Major motivation for running something in the cloud is the fault-tolerance and scalability. Notice: without performance, scalability doesn’t exists.
“Performance and scalability are inseparable from each other. It doesn’t make sense to talk about scalability if a software system doesn’t perform. However, a software system may perform but not scale.”
This article shows you an approach how to dynamically measure performance of your code at runtime. With the help of PostSharp I created the aspect which is applicable to the all members in the solution. This aspect is using the performance counter of type AverageTimer32 to the measure average execution time.
Creating the Performance Counter
The class PerformanceCounterAverageTimer32 encapsulates the general PerformanceCounter class. 
The creation of performance counter is pretty straightforward. Before we create concrete performance counter we should create own Performance Counter Category. The creation of a performance category will be invoked in the constructor.
public PerformanceCounterAverageTimer32(string categoryName, string counterName, string instanceName, string categoryHelp = "", string counterHelp = "")
{
CreatePerformanceCounterCategory(categoryName, counterName, categoryHelp, counterHelp);
_performanceCounter = _performanceCounterManagement.CreateOrGetPerformanceCounterInstance(categoryName, counterName, instanceName);
_performanceCounterBase = _performanceCounterManagement.CreateOrGetPerformanceCounterInstance(categoryName, GetAverageBasePerformanceCounterName(counterName), instanceName);
}
Because the performance counter can generally be applied on various members, the Category Type must be MultiInstance. Since we are creating a performance counter of type AverageTimer32 we must also create a performance counter of type AverageBase. That’s the rule.
private void CreatePerformanceCounterCategory(string categoryName, string counterName, string categoryHelp = "", string performanceCounterHelperText = "")
{
string averageBasePerformanceCounterName = GetAverageBasePerformanceCounterName(counterName);
if (!PerformanceCounterCategory.Exists(categoryName))
{
Trace.TraceInformation(@"Creating performance counter category '{0}', performance counter '\{0}(*)\{1}' and performance counter '\{0}(*)\{2}'", categoryName, counterName, averageBasePerformanceCounterName);
var counters = new CounterCreationDataCollection
{
new CounterCreationData(counterName, performanceCounterHelperText, PerformanceCounterType.AverageTimer32),
new CounterCreationData(averageBasePerformanceCounterName, string.Empty, PerformanceCounterType.AverageBase)
};
PerformanceCounterCategory.Create(categoryName, string.Empty, PerformanceCounterCategoryType.MultiInstance, counters);
Trace.TraceInformation(@"Performance counter category '{0}', performance counter '\{0}(*)\{1}' and performance counter '\{0}(*)\{2}' created", categoryName, counterName, averageBasePerformanceCounterName);
}
Trace.TraceWarning(@"Performance counter category '{0}' already exists! Performance counter '\{0}(*)\{1}' and performance counter '\{0}(*)\{2}' will not be created!", categoryName, counterName, averageBasePerformanceCounterName);
}
In the next step are we getting the instance of created performance counters, to be able interact with them.
_performanceCounter = _performanceCounterManagement.CreateOrGetPerformanceCounterInstance(categoryName, counterName, instanceName); _performanceCounterBase = _performanceCounterManagement.CreateOrGetPerformanceCounterInstance(categoryName, GetAverageBasePerformanceCounterName(counterName), instanceName);
Digging in PostSharp
The aspect AverageTimePerformanceCounterAspectAttribute inherits from the class OnMethodBoundaryAspect. When the aspect is applied to the concrete member, the result after compilation is the code wrapped into a try…finally block. The original code will be changed at the load time with the help of weaver. There are many ways in PostSharp how to apply the aspect. The standard way is using the attributes.
[AverageTimePerformanceCounterAspect]
private string ThreadSleepRandom(string methodName)
{
int sleep = _rand.Next(_maxSleepTime);
Thread.Sleep(sleep);
return (string.Format("Method '{0}' execution slept for {1} milliseconds", methodName, sleep));
}
The code after weaving.
private string ThreadSleepRandom(string methodName)
{
string str2;
MethodExecutionArgs args = new MethodExecutionArgs(null, null);
<>z__Aspects.a0.OnEntry(args);
try
{
int millisecondsTimeout = this._rand.Next(this._maxSleepTime);
Thread.Sleep(millisecondsTimeout);
str2 = string.Format("Method '{0}' execution slept for {1} milliseconds", methodName, millisecondsTimeout);
}
finally
{
<>z__Aspects.a0.OnExit(args);
}
return str2;
}
PostSharp is using the load time weaving. Using the attributes is not enough, because each time we want to measure performance of the new member we need to recompile and redeploy. The better way for us to use the aspect is applying them to the whole assembly:
[assembly: AverageTimePerformanceCounterAspect(AspectPriority = 0, AttributePriority = 0)]
This method is better for our purposes, because we can dynamically control which members should be measured, without need to recompile and redeploy.
In the method CompileTimeInitialize , which is invoked at compile time, we have a chance to get the name of the member on which the aspect is applied.
public override void CompileTimeInitialize(MethodBase method, AspectInfo aspectInfo)
{
_instanceName = method.DeclaringType.FullName + "." + method.Name;
}
Otherwise than CompileTimeInitialize the method RuntimeInitialize is invoked at run time. This is the only way to perform aspect initialization at runtime, because the aspect constructor is not invoked at run time. Here we are principally doing two things: assigning the ConfigurationChanged EventHandler (which is invoked when the configuration file will be changed) to the instance of the IPerformanceCountersAspectsSettingsManager class and initializing the performance counters.
public override void RuntimeInitialize(MethodBase method)
{
if (_performanceCounterSettingsManager == null)
{
_performanceCounterSettingsManager = PerformanceCountersAspectsServiceLocator.PerformanceCountersAspectsSettingsManager;
if (PerformanceCountersAspectsServiceLocator.PerformanceCountersAspectsSettingsManager == null)
{
throw new InvalidAnnotationException(string.Format("To allow to use '{0}' aspect you must implement concrete type of '{1}' and assign them to the '{2}'!", typeof (AverageTimePerformanceCounterAspectAttribute),
typeof (IPerformanceCountersAspectsSettingsManager), typeof (PerformanceCountersAspectsServiceLocator)));
}
_performanceCounterSettingsManager.ConfigurationChanged += (sender, args) => ConfigurationChanged();
}
_isEnabled = _performanceCounterSettingsManager.MembersToMeasured.Any(memberName => memberName == _instanceName);
if (_isEnabled)
{
_performanceCounter = new PerformanceCounterAverageTimer32(_categoryName,_counterName, _instanceName, _performanceCounterHelperText);
}
}
private void ConfigurationChanged()
{
try
{
_isEnabled = _performanceCounterSettingsManager.MembersToMeasured.Any(memberName => memberName == _instanceName);
if (_isEnabled)
{
_performanceCounter = new PerformanceCounterAverageTimer32(_categoryName, _counterName, _instanceName, _categoryHelpText, _performanceCounterHelperText);
}
else
{
if (_performanceCounter != null)
{
_performanceCounter.RemoveInstance();
_performanceCounter = null;
}
}
}
catch (Exception e)
{
Trace.TraceError(e.ToString());
}
}
The only way to assign some values to the aspect is the constructor (same way as in attributes in C#). Because the constructor is executed at compile time, only static values are allowed. PerformanceCountersAspectsServiceLocator acts as bridge between the application and the aspect at the run time. The PerformanceCountersAspectsServiceLocator is holding the instance of the IPerformanceCountersAspectsSettingsManager.
namespace Aspects
{
public static class PerformanceCountersAspectsServiceLocator
{
public static IPerformanceCountersAspectsSettingsManager PerformanceCountersAspectsSettingsManager { get; set; }
}
}
The property MembersToMeasured holds fully qualified member name(s), separated by semicolon, which are measured. ConfigurationChanged is holding the reference to the concrete EventHandler as described above.
When we are overriding the methods OnEntry and OnExit we have the possibility to do some things before the actual code will be executed an after that. In our case in the method OnEntry we are getting the actual time and in the OnExit we are calculating the difference. This way we are get to know how long the method execution takes. The elapsed time will be passed to the instance of the performance counter.
public override void OnEntry(MethodExecutionArgs args)
{
try
{
if (!_isEnabled)
{
return;
}
args.MethodExecutionTag = Stopwatch.ElapsedMilliseconds;
base.OnEntry(args);
}
catch (Exception e)
{
Trace.TraceError(e.ToString());
}
}
public override void OnExit(MethodExecutionArgs args)
{
try
{
//MethodExecutionTag is null when the OnEntry was no executed. This can be the case when you change the configuration at runtime.
if (!_isEnabled || args.MethodExecutionTag == null)
{
return;
}
long time = Stopwatch.ElapsedMilliseconds - (long) args.MethodExecutionTag;
_performanceCounter.Increment(time);
base.OnExit(args);
}
catch (Exception e)
{
Trace.TraceError(e.ToString());
}
}
Testing and using the Performance Counter in Windows Azure
The testing scenario is easy. We are running three methods TestMethod(), TestMethod2() and TestMethod3(). Each method falls asleep for random time. We want the see how long the execution of each method takes.
public static class TestClassRunner
{
public static void Run()
{
var testClass = new TestClass(100000);
IList<Task> tasks = new List<Task>();
Trace.TraceInformation("Starting the tests");
tasks.Add(Task.Factory.StartNew(() =>
{
while(true)
{
try
{
Trace.TraceInformation(testClass.TestMethod());
}
catch (Exception e)
{
Trace.TraceError(string.Format("Exception was thrown on TestMethod(). See exception stack trace for more details: {0}", e));
}
}
}, TaskCreationOptions.LongRunning));
tasks.Add(Task.Factory.StartNew(() =>
{
while (true)
{
try
{
Trace.TraceInformation(testClass.TestMethod2());
}
catch (Exception e)
{
Trace.TraceError(string.Format("Exception was thrown on TestMethod2(). See exception stack trace for more details: {0}", e));
}
}
}, TaskCreationOptions.LongRunning));
tasks.Add(Task.Factory.StartNew(() =>
{
while (true)
{
try
{
Trace.TraceInformation(testClass.TestMethod3());
}
catch (Exception e)
{
Trace.TraceError(string.Format("Exception was thrown on TestMethod3(). See exception stack trace for more details: {0}", e));
}
}
}, TaskCreationOptions.LongRunning));
Task.WaitAll(tasks.ToArray());
}
}
public class TestClass
{
private readonly int _maxSleepTime;
private readonly Random _rand = new Random();
private string ThreadSleepRandom(string methodName)
{
int sleep = _rand.Next(_maxSleepTime);
Thread.Sleep(sleep);
return (string.Format("Method '{0}' execution slept for {1} milliseconds", methodName, sleep));
}
public TestClass(int maxSleepTime)
{
_maxSleepTime = maxSleepTime;
}
public string TestMethod()
{
return ThreadSleepRandom("TestMethod()");
}
public string TestMethod2()
{
return ThreadSleepRandom("TestMethod2()");
}
public string TestMethod3()
{
return ThreadSleepRandom("TestMethod3()");
}
}
We are executing the TestRunner class from the Azure Worker role in the Run() method.
public class WorkerRole : RoleEntryPoint
{
readonly CancellationTokenSource _cancelSource = new CancellationTokenSource();
public WorkerRole()
{
PerformanceCountersAspectsServiceLocator.PerformanceCountersAspectsSettingsManager = new PerformanceCountersAspectsSettingsManager();
}
public override void Run()
{
TestClassRunner.Run();
_cancelSource.Token.WaitHandle.WaitOne();
}
public override bool OnStart()
{
// Set the maximum number of concurrent connections
ServicePointManager.DefaultConnectionLimit = 12;
// For information on handling configuration changes
// see the MSDN topic at http://go.microsoft.com/fwlink/?LinkId=166357.
return base.OnStart();
}
}
If you are running the solution in the Windows Azure Emulator you can use the Management Console to see the data.
There are two methods monitored, but in reality, three have been invoked!
[WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' by value 63770! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' incremented by value 63770! [WaWorkerHost.exe] Method 'TestMethod3()' execution slept for 63772 milliseconds [Diagnostics]: Checking for configuration updates 25.10.2013 14:41:06. [WaWorkerHost.exe] Method 'TestMethod2()' execution slept for 85265 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call' by value 90081! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call' incremented by value 90081! [WaWorkerHost.exe] Method 'TestMethod()' execution slept for 90085 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' by value 25300! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' incremented by value 25300! [WaWorkerHost.exe] Method 'TestMethod3()' execution slept for 25301 milliseconds [WaWorkerHost.exe] Method 'TestMethod2()' execution slept for 16629 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' by value 27279! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' incremented by value 27279! [WaWorkerHost.exe] Method 'TestMethod3()' execution slept for 27280 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' by value 3412! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' incremented by value 3412! [WaWorkerHost.exe] Method 'TestMethod3()' execution slept for 3412 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call' by value 43892! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call' incremented by value 43892! [WaWorkerHost.exe] Method 'TestMethod()' execution slept for 43894 milliseconds [Diagnostics]: Configuration poll finished. [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' by value 60115! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' incremented by value 60115! [WaWorkerHost.exe] Method 'TestMethod3()' execution slept for 60118 milliseconds [WaWorkerHost.exe] Method 'TestMethod2()' execution slept for 82425 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' by value 17387! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' incremented by value 17387! [WaWorkerHost.exe] Method 'TestMethod3()' execution slept for 17387 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' by value 7406! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call' incremented by value 7406! [WaWorkerHost.exe] Method 'TestMethod3()' execution slept for 7406 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call' by value 74258! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call' incremented by value 74258! [WaWorkerHost.exe] Method 'TestMethod()' execution slept for 74261 milliseconds [WaWorkerHost.exe] Incrementing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call' by value 2918! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call' incremented by value 2918!
We are changing the configuration file by adding the new member to be monitored. You find the configuration file in the [SolutionDirectory]\Azure\bin[Debug|Release].
<?xml version="1.0" encoding="utf-8"?>
<!--
**********************************************************************************************
This file was generated by a tool from the project file: ServiceConfiguration.Local.cscfg
Changes to this file may cause incorrect behavior and will be lost if the file is regenerated.
**********************************************************************************************
-->
<ServiceConfiguration serviceName="Azure" xmlns="http://schemas.microsoft.com/ServiceHosting/2008/10/ServiceConfiguration" osFamily="3" osVersion="*" schemaVersion="2013-03.2.0">
<Role name="WorkerRole">
<Instances count="1" />
<ConfigurationSettings>
<Setting name="Microsoft.WindowsAzure.Plugins.Diagnostics.ConnectionString" value="UseDevelopmentStorage=true" />
<Setting name="MembersToBeMeasured" value="TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3;TestClasses.TestClass.TestMethod2" />
</ConfigurationSettings>
</Role>
</ServiceConfiguration>
After that we are executing csrun.exe to emulate locally configuration settings change. Before you do that ensure that you are running the code without debugging, otherwise the execution will be stopped. You will find the deployment-id in the Windows Azure Compute Emulator (deployment-id is the number in brackets).
csrun.exe /update:<deployment-id>;<service-configuration-file>
You can see the result here:
[runtime] Role environment is changing - Cancellable changes [WaWorkerHost.exe] Configuration changing! [runtime] Role environment change accepted - Cancellable changes [runtime] Role environment change completing [WaWorkerHost.exe] Configuration changed! [WaWorkerHost.exe] Configuration entry 'MembersToBeMeasured' changed Getting "MembersToBeMeasured" from ServiceRuntime: PASS (TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3). [WaWorkerHost.exe] The configuration entry 'MembersToMeasured' has value(s) 'TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3' Getting "MembersToBeMeasured" from ServiceRuntime: PASS (TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3). Getting "MembersToBeMeasured" from ServiceRuntime: PASS (TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3). Getting "MembersToBeMeasured" from ServiceRuntime: PASS (TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3). Getting "MembersToBeMeasured" from ServiceRuntime: PASS (TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3). [WaWorkerHost.exe] Performance counter category '_Custom Category' already exists! Performance counter '\_Custom Category(*)\average execution time for member call' and performance counter '\_Custom Category(*)\average execution time for member call base' will not be created! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call don't exist! New instance will be created! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod)\average execution time for member call base don't exist! New instance will be created! Getting "MembersToBeMeasured" from ServiceRuntime: PASS (TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3). [WaWorkerHost.exe] Removing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod2)\average execution time for member call'! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod2)\average execution time for member call' removed! [WaWorkerHost.exe] Removing performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod2)\average execution time for member call base'! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod2)\average execution time for member call base' removed! Getting "MembersToBeMeasured" from ServiceRuntime: PASS (TestClasses.TestClass.TestMethod;TestClasses.TestClass.TestMethod3). [WaWorkerHost.exe] Performance counter category '_Custom Category' already exists! Performance counter '\_Custom Category(*)\average execution time for member call' and performance counter '\_Custom Category(*)\average execution time for member call base' will not be created! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call don't exist! New instance will be created! [WaWorkerHost.exe] Performance counter instance \_Custom Category(TestClasses.TestClass.TestMethod3)\average execution time for member call base don't exist! New instance will be created! [runtime] Role environment change completed
As you can now see in the Management Console, the method Testmethod3 is monitored now. You should notice that the scale value should be set to thousand otherwise you will not be able to watch anything. This is because the Performance Monitor Console shows the values in seconds, but the values we are writing are in milliseconds.
To enable logging the performance counters in the Windows Azure you must just add the performance counter name in the diagnostics.wadcfg. The syntax to access the performance counters is: [Category Name]([Instance Name]|*)[Performance Counter Name].
<?xml version="1.0" encoding="utf-8"?>
<DiagnosticMonitorConfiguration configurationChangePollInterval="PT1M" overallQuotaInMB="4096" xmlns="http://schemas.microsoft.com/ServiceHosting/2010/10/DiagnosticsConfiguration">
<DiagnosticInfrastructureLogs />
<Directories>
<IISLogs container="wad-iis-logfiles" />
<CrashDumps container="wad-crash-dumps" />
</Directories>
<Logs bufferQuotaInMB="1024" scheduledTransferPeriod="PT1M" scheduledTransferLogLevelFilter="Information" />
<PerformanceCounters bufferQuotaInMB="250" scheduledTransferPeriod="PT1M">
<PerformanceCounterConfiguration counterSpecifier="\_Custom Category(*)\average execution time for member call" sampleRate="PT1S" />
</PerformanceCounters>
<WindowsEventLog bufferQuotaInMB="1024" scheduledTransferPeriod="PT1M" scheduledTransferLogLevelFilter="Error">
<DataSource name="Application!*" />
</WindowsEventLog>
</DiagnosticMonitorConfiguration>
After you deploy, the performance counter values are logged in the WADPerformanceCountersTable. You can see the data for example using the Azure Management Studio.
As usually you can find the complete solution here.
Anton Kalcik 