CLR and Performance
I was trying to compete with the String.Split() method. I thought I would write a split() method that could perform a little better than the existing framework split() method. The understanding was that the search algorithm is what takes up most of the time. If I could write a binary search in the split, I could perhaps beat the String.Split(). In the process, I discovered something. I used the Diagnostics' Stopwatch() class to measure the performance of the String.Split() method and realized that the first time the split() method is called, the performance is low, but all consequent method calls, the performance is improved drastically, as in by the magnitude of 1000.
Since I was doing Test Driven Development, I wrote my test class first and so presenting the test method which I finally derived goes like this.
public class MyStringTest
{
[SetUp]
public void Init()
{ }
[TearDown]
public void TearDown()
{ }
/// <summary>
/// Tests if mySplit() is more efficient than the framework string.split()
/// </summary>
[Test]
public void TestSplit()
{
Stopwatch watch = new Stopwatch();
Stopwatch watch1 = new Stopwatch();
string input1 = "Nilotpal, Vikas, Sarang, Rajesh, Nabin";
string input2 = "Nilotpal, Vikas, Sarang, Rajesh, Nabin";
//Time my split
watch.Reset();
watch.Start();
input1.Split(',');
watch.Stop();
long myTicks = watch.ElapsedTicks;
Console.WriteLine("My Ticks:" + myTicks.ToString());
//time framework split.
watch1.Reset();
watch1.Start();
input2.Split(',');
watch1.Stop();
long frameworkTicks = watch1.ElapsedTicks;
watch.Reset();
Console.WriteLine("Framework Ticks: " + frameworkTicks.ToString());
Assert.IsTrue(myTicks <= frameworkTicks);
}
}
The console output that I get out of this goes like this:
Now the first thing that came into my mind is that the application or the class is loaded after the function call which consumes 1831 ticks. So the String class, though initialized, is not loaded into memory until the first function call is made. now that is elementary. Any naive intern developer would know that.
Really???!! Is that what's happening in the background? Ok let's confirm that. Let's re-factor. But before we re-factor let's go through the findings of this code. There is a big drastic difference between the first pass and the second pass so let's do a couple of more passes and we are predicting that all the later passes should be approximately the same time. So here is the re-factored code.
[TestFixture]
public class MyStringTest
{
private Stopwatch watch;
private string input;
private long myTicks;
long frameworkTicks;
[SetUp]
public void Init()
{
watch = new Stopwatch();
input = "Nilotpal, Vikas, Sarang, Rajesh, Nabin";
myTicks = 0;
frameworkTicks = 0;
}
[TearDown]
public void TearDown()
{
watch = null;
}
/// <summary>
/// Tests if mySplit() is more efficient than the framework string.split()
/// </summary>
[Test]
public void TestSplit()
{
//First Pass
watch.Reset();
watch.Start();
input.Split(',');
watch.Stop();
myTicks = watch.ElapsedTicks;
Console.WriteLine("First Pass:" + myTicks.ToString());
//Second Pass
watch.Reset();
watch.Start();
input.Split(',');
watch.Stop();
frameworkTicks = watch.ElapsedTicks;
Console.WriteLine("Second Pass:" + myTicks.ToString());
//Third Pass
watch.Reset();
watch.Start();
input.Split(',');
watch.Stop();
myTicks = watch.ElapsedTicks;
Console.WriteLine("Third Pass:" + myTicks.ToString());
//Fourth Pass
watch.Reset();
watch.Start();
input.Split(',');
watch.Stop();
myTicks = watch.ElapsedTicks;
Console.WriteLine("Fourth Pass:" + myTicks.ToString());
//Fifth Pass
watch.Reset();
watch.Start();
input.Split(',');
watch.Stop();
myTicks = watch.ElapsedTicks;
Console.WriteLine("Fifth Pass:" + myTicks.ToString());
Assert.IsTrue(myTicks <= frameworkTicks);
}
}
And here are the test results:
Curiously, the first and the second pass took the same time. and then the third pass onwards the time taken was drastically low...!!!
Now I am extremely curious and want to know what exactly happening under the hood. Because the entire theory that the first method call should load the string method fails here. Because now even in the second pass, after the String has been loaded takes 1835 ticks.
Now I am curious. Let's see what I can do about this. So I moved this code into the class that I was testing and wrote a Windows Application that would call this method and display the results in a window. Surprise surprise!!! This is the result that I get.
The first two passes do take a little more time, but the difference is not a magnitude of a 1000. It is approximately twice. This puts the doubt on the functioning of the NUnit Framework. I confirmed this by debugging into the application and putting breakpoints after StopWatch.Stop(). The results are authentic.
Conclusion: NUnit should be taking more time in loading the required applications or loading CLR into memory. But there is no evidence and there is no theory as to what exactly is happening underneath. More research required. I wonder what would happen if I ran the same tests from the VSTS Testing environment.
I know that VSTS is using the NUnit Testing engine. Would the seamless integration work and provide proper and authentic test results? or is the seamless integration only a benefit for writing tests? I should some day perhaps try it out.
Comments
- Anonymous
November 01, 2007
The CLR Profiler does take some time to load the CLR through NUnit. But I think you should be able to run the profiler and find out what's happening underneath... what are the methods being called. The thing is the profiler is going to load the NUnit Memory map and find out about all the API Calls. This might take time. But it will eventually work.