This code takes timings for n invocations of two methods that both do nothing (MyMethod1, MyMethod2) but are decorated with different attributes (MyAspect1, MyAspect2).
MyAspect1 contains no logic apart from letting MyMethod1 run (Proceed()).
MyAspect2 does the same for MyMethod2, but also creates a Task, supplying an anonymous delegate to run, which is meant to equate to near zero work for the CPU (trimming a string).
I'd expect timings for iterations over MyMethod1 and MyMethod2 to be roughly the same.
The actual timings are below; they seem counter intuitive, with MyMethod1 starting off significantly slower (counter to what I'd expect), and eventually with it losing the race significantly from 10000 iterations onwards. Can anyone help me explain this?
Test results (average of 3 runs per iteration value):
No. of iterations | Ticks
Method 1 | Method 2
5 25282 6999
100 22128 8176
1000 22982 23720
10000 25995 265621
1000000 994359 25125076
---------------------------------------------------
public class TestClass2
{
public void MyTest()
{
const int iterations = 100;
var stopWatch = new Stopwatch();
stopWatch.Start();
for (int x = 0; x < iterations; x++)
{
MyMethod1();
}
stopWatch.Stop();
Console.WriteLine("Method1 calls duration: " + stopWatch.ElapsedTicks);
stopWatch.Reset();
stopWatch.Start();
for (int x = 0; x < iterations; x++)
{
MyMethod2();
}
stopWatch.Stop();
Console.WriteLine("Method2 calls duration: " + stopWatch.ElapsedTicks);
}
[MyAspect1]
private void MyMethod1() {}
[MyAspect2]
private void MyMethod2() {}
}
[Serializable]
public class MyAspect1 : AsynchronousMetricsAspect
{
public override void OnInvoke(MethodInterceptionArgs args)
{
args.Proceed();
}
}
//NOTE: this type is the same as MyAspect1, but adds a Task creation
[Serializable]
public class MyAspect2 : AsynchronousMetricsAspect
{
public override void OnInvoke(MethodInterceptionArgs args)
{
args.Proceed();
Task.Factory.StartNew(() => "bleh".Trim()); //invoke the logging method asynchronously
}
}
Further info: Test is being invoked from ReSharper NUnit VS plugin and the attributes are PostSharp MethodInterceptionAspects.
Edit: Updated figures for when the methods are pre-invoked before the tests, to ensure any JIT compilation has occurred.
Test results (ballpark):
No. of iterations | Ticks
Method 1 | Method 2
5 22 437
100 37 2204
1000 192 24476
10000 7931 286403
100000 115451 2862439
1000000 695950 29049021
10000000 8347867 275777590