Real World Performance Comparison: Enterprise Library Logging Block vs log4net

Any search on the web you find will consistently show log4net outperforming EL by a factor of around 4:1.  Most of these tests are typically tight for/loops, and comments will end up saying things like “oh well that’s not a realistic test” or “well you shouldn’t be logging that much anyway”, etc etc.  Well, let’s see how important choosing your logging infrastructure is in terms of overall system performance in a multithreaded application.

One of my recent tasks was hunting down a memory leak.  So I downloaded the trial of the ANTS .NET Bundle which contains a memory profiler and performance profiler.  Hunting the memory leak was a pain since I wasn’t the one who wrote the code, so it took a while for me to realize which objects were “leaked.”  I eventually found it, and then I turned my attention to using the performance profiler to see if any obvious places could be optimized.

At this point I decided to swap in the Enterprise Logging Block to see how it would fair.  The logging migration project was still in progress, and we haven’t made the full switch yet, but I figured I should try out it anyway because I’m the curious type.

The software already uses the Trace diagnostics extensively.  Practically every message, error, you name it, will get Trace.WriteLined…and then a LogFileWriter will pick it up, and dump it to a file.  In my testing, I simply added an extra line of code here, namely Logger.Write(LogEntry).  Thus, anything that used to get logged, will also get logged by the EL.

Then, it was basically running the application to a similar set of scenarios, and then seeing what the profiler says.  Obviously each run will not be exactly the same as the previous, but overall I think if we look at percentages we can begin to see where the CPU is taking the most time.

Here is what the application does without any modifications.

Here is the application after adding Logger.Write(LogEntry).

Yeah, I was pretty surprised too.  That one method ended up being the most expensive method in the entire application.

A quick look at the source revealed quite a bit of code dedicated to thread safety.  So digging deeper, I decided to avoid the static Logger.Write method altogether, create instance LogWriters directly, and have them all go to a singleton FileTraceListener.

That’s a noticeable improvement…it’s not #1 anymore.  The CPU time also dropped from ~15% to ~10%.  That means that ~5% of CPU time was in the static Logger.Write(LogEntry) method.  If you look at the graphs you’ll notice a common pattern among them, because I wanted to test with the same scenario to get as close to as measurable results as possible…but to illustrate how bad the EL’s performance can get, here’s one:

I literally fell off my chair when I first discovered this as I didn’t think it could be possible something that’s supposed to be non-invasive could end up taking this much CPU.  This is one of the earlier tests I did where  I didn't have a set scenario yet.

And of course, here are the results with log4net.

So what does that leave us?

log4net:  5%
EL static:  15%
EL instance:  10%

So what should you get out of this?  Be very careful of how you invoke Logger.Write()…it may not be as cheap as you think it is.  Even log4net took much more CPU time than I expected.

I redid the test using Castle’s logging framework, which is a barebones dump messages to a file.  The total CPU time for this was 0.016%.  Yep!  I had to scroll down to even find it!

I guess this shows that even log4net, which is touted for high-performance, comes at a cost.

Fixing ReSharper 5 EAP Missing Colors

I think anyone’s who has used ReSharper for an extended period of time has experienced the colors disappearing all of a sudden from Fonts & Colors.  This is excruciatingly annoying when I have a dark color scheme set up and the colors disappear on me.

In the case of RS5, it seems even more flakey than RS4, and installing/uninstalling other addins have a pretty high probability of losing the colors, and this time, repairing the installation doesn’t fix the problem (nor does the registry restore trick).

For me, to fix the problem I had to:

a) Uninstall RS5.
b) Install RS4.5
c) Open VS!!!  Go into settings, and verify all the colors are in Fonts & Colors.
d) Upgrade to RS5.

If you skip (c), it will not restore colors…at least it didn’t when I tried it.  Following the above fixed it for me in 2 occasions already.  If Jetbrains sees this blog post, PLEASE fix this extremely annoying bug.

Multiple Inheritance in C# with Castle DynamicProxy Mixins

Having some significant experience with C++, every once in a while I’ll really miss features available in C++ that just aren’t possible in C#.  Sure, linking takes forever and if you could calculate the percentage of time for a C++ developer spent on linking time I’m sure it’d be around 50%.  Nonetheless, there’s a certain seductive pull to stepping through the debugger and the sheer speed of a C++ program (arguably debugger is being made obsolete with TDD).  If you’re only used C# for a long time, you probably didn’t even know that C++ was THAT much faster until you try this out.  Even a simple hello world program: you can tell a difference.
But that’s not the point of this post.  This post is about mixins!
So what is a mixin?  You can wikipedia it, but basically it’s a way to add functionality to an existing object.  In a way, it’s like multiple inheritance, but not exactly.  If you wanna go CS101 terms, this is not a “is-a” relationship, but more of a “can-do” relationship.  Both methods promote code reuse, and of course, both can be abused.
In a way, C# extension methods are a form of mixin, but really it’s just syntactic sugar.  It’s a static method but looks like a instance method.  True mixins are actual instances.
I’ve been playing around with Castle.DynamicProxy lately, and some of it is going into production code soon.  This is honestly kind of scary, because I really don’t want to mess up production code which generates daily profit for the company.  However, if NHibernate’s using dynamic proxy, and that has been proven to work in countless production environments, I’m sure the complexity of the proxies I’m doing pales in comparison to what NHibernate does.
Most of the examples available on the web show you how a mixin works.  Basically, you create a target, and then you mixin extra stuff.  Basic stuff…but there’s a really cool trick you can do to make all consuming code a lot easier to use by removing the need of consuming code to cast to a mixin instance.  In my case, the system is a very complex piece of legacy code where there are threads all over the place locking things all over the place.  I was given the task of keeping track of who owned the lock.
Originally I started with an extension method, but I soon realized that even though it’s nice that along with IDisposable, I could do something like this:

using (anyInstance.Lock()) {
anyInstance.DoStuff();
}

Where Lock() is an extension method which returns an IDisposable, which when Dispose() is invoked will call Monitor.Exit.  This is all nice and dandy use of the ‘using’ syntax, but as you can see this is all just syntactic sugar.  At the end of the day, this is still a public static method can is accessible by thousands of other objects.  And once you need to keep track of all those owners, you need to create a dictionary of object hashcodes, and locking on that thing for each incoming lock on an instance is…well…very very bad.

Anyways, so with DynamicProxy2, I decided to mix in this lock tracking logic.  Now, the interface is simple:

public interface ILockMixin {
IDisposable Lock(string tag);
IDisposable TryLock(string tag);
}

Now, the particular thing I wanted to target happened to be a hashtable, so with a little interface trick, you could do this:

public interface ILockableHashtable : IDictionary, ILockMixin { }

Finally, any code that references hashtable needs to be replaced with ILockableHashtable, but the beauty of this is that none of the existing code had to change, and now all proxied hashtables have the Lock() method as well.  And alongside Windsor, this is brain-dead simple to wire up:

kernel.Register(
Component.For<IDictionary, ILockableDictionary>()
.ImplementedBy<Hashtable>()
.Proxy.AdditionalInterfaces(typeof(ILockableDictionary))
.Proxy.MixIns(new Locker()));

And that’s it!  BTW, I realize I could have easily achieved the same effect and with a lot less effort if I just inherited from Hashtable directly (and avoid the negligible proxy/performance cost), but if I needed this locking mechanism for any other code, I would have to resort to either copy/pasting a lot of code, or a lot of copy/paste/redirect to a static class.

Edit: There is a bug in this last bit, check out my latest entry about this topic.