Benchmarking MicroLite 4.0 part 1

In the previous post MicroLite 5.0 – Performance Summary we gave an overview of the performance improvement between MicroLite 4.0 and MicroLite 5.0 and mentioned that we would drill into how some of those gains were achieved.

In order to see what the cost of using the framework is, we need a benchmark. The one we built is available on GitHub MicroORM.Benchmark.

We also need a profiling tool, fortunately YourKit have kindly provided an Open Source license for their excellent .NET Profiler.

Running the benchmark against MicroLite 4.0 and running 10 iterations of inserting 100 entity instances gives us the following result (anything below 2% of the cost is excluded):

MicroLite 4.0 InsertMicroLite 4.0 Insert

Looking at this, there are a few points which are quite surprising:

  1. Using a HashSet is costing us 41% of the execution time
  2. We spend 5% of the execution time resolving the ObjectInfo
  3. We spend 4% of the execution time loading resource strings
  4. The .Each extension method is costing 6% of the execution time

new HashSet<string>() – The reason we used the HashSet is that we get O(1) lookup performance rather than O(n) with a List. It turns out however for our purposes that the List is actually more performant. The reason for this is that the cost of creating a HashSet compared to the cost of creating a List is much higher. Also, it turns out that generally we have less than 15 items in the list so even with the O(n) cost of doing list.Contains() we still end up much better off.

Resulting Change – replace HashSet with List.

Lesson – don’t make assumptions about the performance of a piece of code without verifying those assumptions are true.

ObjectInfo.For() – ObjectInfo is the class MicroLite uses to resolve the mapping details between a class and a table. The value is only created on the first call and then cached but we had a number of calls to ObjectInfo.For(instance.GetType()) throughout the code (5 separate resolutions per call to Insert).

Resulting Change – Since the ObjectInfo is used by multiple classes in the call execution, we can resolve it once and pass the value through the call stack. Changed from 5 calls to ObjectInfo.For to 2 calls.

Lesson – DRY (don’t repeat yourself) can apply to a single line of code if the result of that call can be passed to another class/method which needs it as a parameter.

ResourceManager.GetString() – The only thing the resource files are used for by MicroLite is to contain log messages which may be written to the logger. In MicroLite 4.0, the logging statements looked like this:

log.TryLogDebug(Messages.Transaction_Committing);

The reason for the TryLogDebug method is that if no logging library was registered, the log would be null so we created an extension method to verify that the log wasn’t null before calling it. The problem with this as it turns out is that the cost of resolving the resource message is incurred for every call regardless of whether a logger is actually specified or even cares about the level of the log statement.

Resulting Change – In MicroLite 5.0, we have made 2 changes to the logger. Firstly, we always return a log instance (even if it doesn’t write to anything). Secondly, we add IsDebug etc properties which are checked before calling the method:

if (log.IsDebug)
{
    log.Debug(LogMessages.Transaction_Committing);
}

Lesson – avoid doing unnecessary work

IEnumerable.Each() – This is your typical combination of Extension Methods and Lambdas – pretty much every project since .NET 3.5 has probably included the following:

internal static void Each<T>(this IEnumerable<T> source, Action<T> action)
{
    foreach (var item in source)
    {
        action(item);
    }
}

MicroLite 4.0 made extensive use of this – for example invoking the IListeners:

this.listeners.Each(l => l.BeforeInsert(instance));
...
this.listeners.Reverse().Each(l => l.AfterInsert(instance, identifier));

Nice one liners I’m sure you’ll agree & perfectly readable. There are however some “hidden” factors here, the lambda l => l... is created each time the method is called which incurs an object allocation (cheap) and extra work for the garbage collector to clean up after it (not so cheap). Also, an enumerator is created for the iteration of the foreach which again needs allocation and clean up.

Resulting Change – In MicroLite 5.0, we have removed the extension method and reverted to a standard for loop:

for (int i = 0; i < this.listeners.Count; i++)
{
    this.listeners[i].BeforeInsert(instance);
}
...
for (int i = this.listeners.Count - 1; i >= 0; i--)
{
    this.listeners[i].AfterInsert(instance, identifier);
}

Lesson – avoid doing unnecessary work & nice code is not necessarily fast code. Now before you all count this as a needless micro optimisation, I’m not suggesting you go an revert back to for loop in your own code! However where performance is more critical then it can make a difference. For standard line of business code – the stuff we mostly write all day at work, stick with the lambdas & readability unless you can prove that the payoff is worth it.

That’s probably enough for one post, we’ll go into more in the next post. For the curious among you, here’s the insert cost in MicroLite 5.0 (there are more changes than just those mentioned in this post which make up the difference):

MicroLite 5.0 InsertMicroLite 5.0 Insert

As you can see, MicroLite 5.0 introduces far less overhead in it’s use.

Advertisements

One thought on “Benchmarking MicroLite 4.0 part 1

  1. Pingback: Benchmarking MicroLite 4.0 part 2 | MicroLite ORM

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s