Logging is one of the most popular areas used as example to illustrate dependecy injection technique. Components need to log their activities, and to remove hard dependency on actual logger implementation, it’s reasonable to define an interface (something like ILog) that is sent to class constructors, thus freeing components from knowledge about logging details.
Unfortunately things are different in practice. And if your application uses several third-party libraries that depend on different logging frameworks, you are often out of luck if you try to harmonize their logging and route its output to common log sinks (or listeners).
Take for example log4net. It’s LogManager looks DI-compliant: it has a method GetLogger that returns an instance of ILog interface:
ILog log = LogManager.GetLogger(“MyLog”);
You would then expect a way to configure LogManager to return a custom logger. Nope! You can’t control that. log4net does not give you a chance to write your own logger.
But isn’t this wish outside log4net purpose? Since ILog interface is not a generic .NET interface but a contract that is defined by log4net, isn’t it fair to assume that log4net will use its own logging engine leaving possibilities to write custom appenders? Well, as long as log4net is the only third-party component that you use, this will be sufficient. Once you add more, this can become a problem.
Our components use Enterprise Library Logging Application Block for its logging purposes. Recently we started using WCF and NHibernate and would like to aggregate all log output. Not an easy task.
With WCF it seems that there is a way to redirect its logging. There is a special log listener called EntLibLoggingProxyTraceListener used as a bridge between WCF log messages and Enteprise Library LAB. But NHibernate uses log4net, and it looks that the only way to route NHibernate logs to our listeners is to write a special appender. The effort to write such appender is not more complex than to write a custom implementation of ILog interface. I just believe that if a framework provide all necessary elements to fully implement dependency injection pattern (interface definition, factory), it should make the last step and make class instantiation configurable, opening for external implementation of the class.
David Bryon in his recent post wonders why developers still ask questions about how much OR mappers slow down database applications. He explains that modern ORMs keep the overhead of communicating with the database as low as possible, so in fact use of ORM may (and I believe in many cases will) speed up database access.
When it comes to non-database communication, such as message queuing or inter-process data exchange, there seem to be more reasons to avoid additional layers and transfer data directly, using native protocol. Usually such communication can’t be optimized by discarding redundant messages or removing unaffected parameters. So sometimes suggestion to use WCF as communication platform can cause certain skepticism – “it’s an extra layer, we don’t need this overhead, let’s go native”.
Few years ago I wrote an article about performance implications of exceptions. The metrics in this articles show that while exception management is obviously more costly than returning numerical error codes, it has no real influence on performance of business logic operations. A single database call makes CPU cycles used on exception processing completely insignificant.
The same can be said about overhead associated with WCF. Data that cross processes or machine boundaries take a long trip not to invoke a simple in-memory algorithm – nobody will implement inter-process string concatenation except for demo purpose. And for real world business logic operation the advantages of using WCF infrastructure should outperform its marginal performance overhead.
And it is always measurable how marginal it is. Let’s take named pipes. It’s a good choice for inter-process communication, now with native .NET support. How much can we gain from using it directly? Let’s measure.
I created two sets of client/server applications, each consisting of a server and a client. First application pair communicated using .NET implementation of named pipes (System.IO.Pipes), second used WCF with NetNamedPipeBinding. I tested these applications using different scenarios: an empty operation, reading directory entries and writing 100 bytes in the middle of a 1 megabyte file. Each scenario was executed several thousand times, to calculate an average number of calls per second. The measurements were done on my Dell Latitude D830 notebook.
|Operation ||System.IO.Pipes |
(calls per second)
|WCF NetNamedPipeBinding |
(calls per second)
|Empty ||108695 ||4770 ||2179 |
|Read directory entries ||5747 ||1546 ||272 |
|Write to a file ||67 ||59 ||14 |
|Write to a file twice ||35 ||34 ||3 |
You can see from this table how much faster is native named pipe communication. But… only if an operation consists of the actual call, with no business logic contained. Once an operation starts looking like a real business logic method, all communication overhead is not worth consideration. But what is worth consideration is a unified communication model offered by WCF, with all power of configuration options and tools. There must be really extraordinary reasons to discard them and “go native”.