Benchmarking MicroLite 4.0 part 2

Following on from the findings in Benchmarking MicroLite 4.0 part 1 there are a few more things that are worth mentioning.

The cost of params – we use the params keyword throughout the MicroLite codebase for convenience where there there are an unknown number of parameter values which could be passed to a method (which is exactly what the params keyword is for).

Take the following piece of code for example:

var sqlQuery = new SqlQuery(
    "SELECT * FROM Table WHERE Column = @p0",
    "Foo");

When it is compiled, it essentially becomes this:

var args = new object[1];
args[0] = "Foo";

var sqlQuery = new SqlQuery(
    "SELECT * FROM Table WHERE Column = @p0", args);

Notice that the compiler has actually created an array of the correct size for the number of arguments, it does this even if there are no params:

var sqlQuery = new SqlQuery("SELECT * FROM Table");

Compiles to:

var args = new object[0];

var sqlQuery = new SqlQuery("SELECT * FROM Table", args);

This means for every call to a method with params signature, we require the allocation and garbage collection of an array even if there are no values to pass!

Resulting Change – We have added method overloads without params or with additional fixed size args where we might not have any arguments or only 1.

// Additional constructor for SqlQuery with no args
public SqlQuery(string commandText) { }
public SqlQuery(string commandText, params object[] arguments) { }

// Additional method for SqlBuilder with a single arg
IOrderBy OrderByAscending(string column);
IOrderBy OrderByAscending(params string[] columns);

Lesson – Understand the implications of convenience and allow alternatives to avoid unnecessary object allocations/collections.

Re-Generating the same SQL every time – in MicroLite 4.0, we were building the SQL statement every time we inserted/selected/updated/deleted/ an object, however thinking about this a bit more, the command text is always the same for a given class, only the values change per instance.

Resulting Change – We have implemented a query cache per mapped type for each of the CRUD operations (INSERT, SELECT, UPDATE and DELETE) which are generated the first time the action is invoked for a given class.

Lesson – DRY (don’t repeat yourself) can apply to the code executed inside a single method even if the code within that method is not duplicated elsewhere.

Moving to generated MSIL – in MicroLite up to version 5.0 we were using reflection to get and set property values and although the approach evolved over time to be faster it’s still nowhere near as quick as the method would be if you coded it by hand.

Resulting Change – We now generate a dynamic method at runtime by emitting the MSIL which would be produced to access the property.

// Generating the equivalent of:
var value = customer.Name;

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.

MicroLite 5.0 – Performance Summary

We mentioned in the MicroLite 5.0 Released post that there has been some work internally in MicroLite to improve performance and reduce memory usage. We’ll dive into the details in future posts, but for now here’s a brief summary of some of the results.

The calls are based upon a single instance of an entity, with the action performed 100 times inside an individual transaction each time.

The INSERT, UPDATE and DELETE calls were performed against an instance (e.g.)

session.Insert(entity);
session.Update(entity);
session.Delete(entity);

The SELECT call was performed against the identifier of an instance (e.g.)

var entity = session.Single<Entity>(id);

The test also included performing a SELECT query which resulted in 100 results using Fetch and Paged (e.g.):

var entities = session.Fetch<Entity>(
    new SqlQuery("SELECT * FROM Entity WHERE Id <= @p0", 100));

var paged = session.Paged<Entity>(
    new SqlQuery("SELECT * FROM Entity"),
    PagingOptions.ForPage(1, 100));

The tests were run on a virtual machine using a local SQLite database and the results are as follows:

Activity MicroLite 4.0 MicroLite 5.0 Improvement
Writes
INSERT 20.79 ms 15.70 ms 24.48% faster
UPDATE 21.26 ms 16.19 ms 23.85% faster
DELETE 14.13 ms 11.15 ms 21.09% faster
Reads
SELECT (Single) 13.36 ms   7.95 ms 40.49% faster
SELECT (Fetch)   4.07 ms   2.42 ms 40.54% faster
SELECT (Paged)   4.27 ms   2.28 ms 46.60% faster

The following are based upon the above tests run in a profiler.

Version CLR Heap Used CLR Heap Allocated Process Mem Used Process VM Size GC Count
MicroLite 4.0 565 KB 3.8 MB 72 MB 60 MB 28
MicroLite 5.0 395 KB 3.6 MB 69 MB 57 MB 17

MicroLite 5.0 MiniProfiler support

Along with the release of MicroLite 5.0, we have added an extension to integrate with the StackExchange MiniProfiler.

It’s simple to use, install the NuGet package:

Install-Package MicroLite.Extensions.MiniProfiler

Which will pull down the StackExchange MiniProfiler, and also add the extension method to wire it up for MicroLite in your configuration:

Configure
    .Extensions() // If you are also using a logging extension, that should be loaded first.
    .WithMiniProfiler();

After that, follow the instructions for starting and saving profile results (and optionally viewing them in an MVC app) on the website at miniprofiler.com

Version 1.0 of the extension configures MicroLite to use the profiled database commands, in future versions we may look to add additional timings for core MicroLite functionality.