Introduction
I've recently begun seriously working with the .NET framework. I found a need for a .NET logging framework, something offering more robust features and better scalability than the classes in the System.Diagnostics namespace. Not finding anything fitting the bill either in the .NET class library or on the web, I cowboyed up and rolled my own. After a month of work in my spare time to write umpteen lines of code and another two weeks to document everything, I feel like I'm at a good breathing point. (For a help-oriented message board, the project's bug-tracking system, the latest version of the project's code and documentation, and contact information, please visit http://sourceforge.net/projects/nspring.)
Background
My background for the last seven or eight years has mostly been in Java development; however, when the release of the .NET framework somewhat coincided with the buyout of my shop by a Microsoft-centered company, I was determined to learn everything I could about the competition. I spent some time getting my MCSD .NET, and learned a lot along the way about how Microsoft likes to do things. Well, I've been pleasantly surprised so far! All in all, I find the .NET Framework to offer a pleasing blend of performance and features. However (and I suspect that this may be mostly due to the youth of the platform) it is still missing crucial features, logging support among them.
What's so important about logging?
First off, I'm not saying that System.Diagnostics classes Debug and Trace are bad. They're fine for quick troubleshooting, and the choice of the name "diagnostics" for their name reflects the intent of these classes. This isn't quite the same as full-featured logging support, however; true logging is not just diagnostic but historical in nature. I would never, for instance, dream of writing an important server-side application that depended solely on Debug and Trace for recording information about configuration, client connections, etc. The performance isn't there, and neither are the programmability features I've come to expect in a good logging package, having dealt with several in different languages over the years.
You may skip the next section and go right to the programming samples if you like, then download the .zip file. It contains extensive HTML documentation, including a programming sample illustrating the use of each logger, event formatter, and data formatter type in detail. The documentation has actually taken me longer to write than the code.
Logging package features
The new logging package offers the following features, among others:
High performance: Classes Debug and Trace are slow; unbuffered use of these classes can entail a significant performance degradation in application code. Loggers in this framework provide buffering ability (asynchronous output) as well as other caching features; this results in ~500 nanosecond per-message log times on a P4-M 2.0GHz laptop. Further performance optimizations are planned for later releases.
Stability: Every class in the logging package is thread-safe and performance-tuned for use in a multithreaded environment. Also, logging-failure support can be provided via classes implementing the ExceptionHandler interface; since the Logger base class itself implements this interface, all loggers can provide failover logging support for each other.
Ease of use: Loggers provided in this package are easy to understand and to use. Each one represents a different form of output; many different pre-written loggers are provided, covering everything from email logging to database logging to various forms of file-based logging, and most of them can be easily configured by calls to their constructor methods. Care has been taken to make each interface as intuitively easy-to-use as possible.
Ease of extension: Users can define their own loggers, filters, exception handlers, event formatters, data formatters, and log levels with ease, usually by just instantiating an object or implementing one or two methods. For instance, a custom Logger subclass can be created by implementing just a single method and still gain all the benefits of the Logger class, including buffering support.
Levels: Each log message (Event) is accompanied by a "priority" level. Each Logger has an associated level, and discards all events lower than this default level, providing simple yet fine-grained message-filtering ability. Users can also define their own levels, as long as they contain unique information.
Flexible filtering: A hallmark of good logging support is the ability to selectively discard logged data based on more in-depth criteria than can be provided by the use of levels. Not only are many prebuilt filters provided in the NSpring.Logging.Filters namespace, but it's easy to implement custom filters by subclassing the Filter class.
Flexible formatting: Useful types of log-record formatting are supplied via the classes in the NSpring.Logging.EventFormatters namespace. The XMLEventFormatter is highly configurable, and users can also supply their own formatting logic by subclassing the EventFormatter class. A simple formatting language also provides a great deal in formatting flexibility.
Data support: Each log event can carry an object data "payload". Support is built in for correct output of all arrays, lists and dictionary classes, together with the ability to supply format strings for each primitive type, as well as such structures as DateTime and TimeSpan. Users can extend the data formatting abilities of loggers by subclassing DataFormatter. Three types of data-formatting implementations are provided out-of-the-box.
Partitioned access: Debug and Trace provide only two points of global access to logging facilities in your applications. This can be bad for many reasons, not least of which is that the default ways of segregating content (the Indent() and Unindent() static methods) were provided without any thought of multithreaded use. In other words, two threads attempting simultaneous use of Debug and Trace can interfere with each other. Also, while you can create various listeners for these two classes, the classes must implement their own filtering logic (entailing a worst-case exponential performance slowdown with each listener added) because all output is funneled through either Debug or Trace. This leads to the next point.
Naming: Loggers can be registered with one or more names using a LoggerRegistry object. The Logger class itself provides global named access to loggers by use of an internal static default LoggerRegistry.
Composition: Loggers in this framework can be added to each other as children, receiving hand-me-down events. Different logging structures can be created for different needs, all organized under one easy-to-use name. Filters can also be composed of other filters using the CompositeFilter class.
Event categorization: Debug and Trace provide only four possible data fields for each logged event: a string message, a more-detailed string message, a string category, and an object data payload. There are no provisions made for different applications/modules logging using the same logging subsystem, etc. Each Event object logged by the NSpring logging framework contains fields for timestamp, text message, data object, event category, event code, event ID, event severity level, application name, and system name. Many different variations on the Logger class' Log method are provided to make these easy to use, and log filters (via the Filter class and its children) are provided that work with each of the fields. Certain loggers (such as FileLogger and MessageQueueLogger) have the ability to "scatter" output to many different files, queues, etc. based on the properties of the events logged through them. The ability to send output to different named loggers also provides a useful degree of categorization ability.
Support for existing code: The logging package may be used with existing code that depends on Debug and Trace by use of the DebugLogger and TraceLogger classes; by using logger composition, the same output can easily be redirected through other forms of output as well. (Also in the works: a series of event-source classes that can listen to a variety of data sources, including Debug and Trace, and pipe the resulting data through logging classes.)
Programming sample #1: Logging to files
(This and the following two examples were taken at random from the project documentation.)
Instances of FileLogger write their output to files. The file path may be relative or complete, and may be hard-coded or a formatting pattern.
The logger will create any directories necessary to write to any file. Where it doesn't involve a large memory commitment, FileLogger caches knowledge of known directories to improve performance. Buffering/asynchronous output is highly recommended with this logger, as each file is closed between logging operations. Performance in unbuffered mode is acceptable for most situations, but performance in buffered mode is very fast.
File output may be "scattered" to multiple files by the use of a formatting pattern in the file path. This may be used, for example, to implement "rolling" log files, where output is redirected on a periodic (say, hourly) basis. Performance in scattering mode is still excellent, as the logger holds multiple streams open in buffering mode (unless the path contains often-changing information such as the event ID or any time-based token value containing the millisecond. Use of such volatile paths still works just fine, but it results in the opening and closing of a stream for each event, resulting in slower performance).
Archiving is supported through the use of the IsArchivingEnabled, ArchiveDirectoryPath, and MaximumFileSize properties. If archiving is enabled, any file that reaches the maximum size is moved to the specified directory, named with an extra extension containing timestamp data (in order to differentiate multiple archives of the same file) and an optional extra file extension in order to facilitate easy reading of archives. Archive compression is not supported in this release.
The event formatter used by default is an instance of PatternEventFormatter, using a FlatDataFormatter for data formatting. In the sample below, a factory method is used to create the logger, but it could also be created using a constructor method.
using System;
using NSpring.Logging;
public class FileLoggerExample {
public static void Main(string[] args) {
Logger logger = Logger.CreateFileLogger("c:\\temp\\nspring.log", +
"{ts}{z} [{ln:1w}] {msg}");
logger.IsBufferingEnabled = true;
logger.BufferSize = 1000;
logger.Open();
logger.Log(Level.Debug, "My hamster's name is Wilhelmina");
logger.Log(Level.Verbose, "She has two tails");
logger.Log(Level.Config, "She wears a green mohawk");
logger.Log(Level.Info, "She's studying to be an accountant");
logger.Log(Level.Warning, "Chrysanthemums are her favorite food");
logger.Log(Level.Exception, "Underneath that tough biker exterior," +
" she's just a sweet hamster");
logger.Close();
}
}
Output written to c:\temp\nspring.log:
2003-10-13 12:25:25.895-04:00 [D] My hamster's name is Wilhelmina
2003-10-13 12:25:25.895-04:00 [V] She has two tails
2003-10-13 12:25:25.895-04:00 [C] She wears a green mohawk
2003-10-13 12:25:25.895-04:00 [I] She's studying to be an accountant
2003-10-13 12:25:25.895-04:00 [W] Chrysanthemums are her favorite food
2003-10-13 12:25:25.895-04:00 [E] Underneath that tough biker exterior,
she's just a sweet hamster
Programming sample #2: Using logger composition
This shows a simple example of the use of the CompositeLogger class. Note how the messages are grouped by child logger. The explanation for this is that when in buffering mode, a logger always passes events in batches to each of its children in the hopes that they will take advantage of bulk-writing enhancements. If the parent logger were unbuffered, the statements would be interleaved.
using System;
using NSpring.Logging;
public class CompositeLoggerExample {
public static void Main(string[] args) {
Logger cl1 = Logger.CreateConsoleLogger("Logger 1: {message}");
Logger cl2 = Logger.CreateConsoleLogger("Logger 2: {message}");
Logger logger = Logger.CreateCompositeLogger(cl1, cl2);
logger.IsBufferingEnabled = true;
logger.BufferSize = 10000;
logger.AutoFlushInterval = 15000;
logger.Open();
logger.Log("My hamster's name is Wilhelmina");
logger.Log("She drives a tiny dump truck");
logger.Log("She always wins at arm-wrestling");
logger.Close();
}
}
Output:
Logger 1: My hamster's name is Wilhelmina
Logger 1: She drives a tiny dump truck
Logger 1: She always wins at arm-wrestling
Logger 2: My hamster's name is Wilhelmina
Logger 2: She drives a tiny dump truck
Logger 2: She always wins at arm-wrestling
Programming sample #3: An XMLDataFormatter example
Each XMLDataFormatter instance formats data objects as XML. If a collection is formatted, it is considered to be one of two types: a map (such as a dictionary class) or a list (such as an array or any IEnumerable).
Casing and separator options used in constructing XML names can be set using the NSpring.Logging.XML.XMLFormatOptions class. Formatting of strings, primitive types, and certain structures (such as DateTime, TimeSpan and Decimal) is controlled by setting format strings on properties of the superclass. See the documentation of the DataFormatter superclass for more details.
using System;
using System.Collections;
using NSpring.Logging;
using NSpring.Logging.Loggers;
using NSpring.Logging.DataFormatters;
using NSpring.Logging.EventFormatters;
public class XMLDataFormatterExample {
public static void Main(string[] args) {
ConsoleLogger logger = new ConsoleLogger();
EventFormatter eventFormatter =
new PatternEventFormatter("{message}\n{data}\n");
eventFormatter.DataFormatter = new XMLDataFormatter();
eventFormatter.IsIndentationEnabled = true;
logger.EventFormatter = eventFormatter;
string s = "schmaltz";
int i = 5;
float f = 1.234567F;
TimeSpan ts = new TimeSpan(1, 2, 3, 4, 555);
DateTime dt = DateTime.Now;
Hashtable h = new Hashtable();
h["key1"] = "value1";
h["key2"] = "value2";
object[] oa = {s, i, f, ts, dt, h};
logger.Log("A single string value:", (object)s);
logger.Log("A single integer value:", i);
logger.Log("A single float value:", f);
logger.Log("A single TimeSpan value:", ts);
logger.Log("A single DateTime value:", dt);
logger.Log("A Hashtable value:", h);
logger.Log("An array of the above:", oa);
}
}
Output:
A single string value:
<data type="string">schmaltz</data>
A single integer value:
<data type="integer">5</data>
A single float value:
<data type="float">1.234567</data>
A single TimeSpan value:
<data type="duration">P1DT2H3M4.555S</data>
A single DateTime value:
<data type="dateTime">2003-10-09T18:47:05.181-04:00</data>
A Hashtable value:
<data type="map">
<entry>
<key type="string">key1</key>
<value type="string">value1</value>
</entry>
<entry>
<key type="string">key2</key>
<value type="string">value2</value>
</entry>
</data>
An array of the above:
<data type="list">
<value type="string">schmaltz</value>
<value type="integer">5</value>
<value type="float">1.234567</value>
<value type="duration">P1DT2H3M4.555S</value>
<value type="dateTime">2003-10-09T18:47:05.181-04:00</value>
<value type="map">
<entry>
<key type="string">key1</key>
<value type="string">value1</value>
</entry>
<entry>
<key type="string">key2</key>
<value type="string">value2</value>
</entry>
</value>
</data>
Points of Interest
The main reasons for the speed of the logging framework are twofold: avoidance, wherever possible, of both object creation and synchronization. The bulk of the time quoted above (about 500 nanoseconds for logging a message in buffering mode on a laptop machine) is for constructing the single Event object, the only object creation necessary for logging a message. I haven't been able to come up with a workable object-caching scheme that will let me avoid creating this object, and still provide the openness necessary in an extensible API. However, I haven't yet explored .NET weak references, one area that shows definite promise.
Failing a further reduction (to less than one!) in per-message object creation overhead, I plan to at least defer the creation of this object. So, instead of an application thread driving the creation of an Event object and pushing it into the buffer, I may change things so that the application code pushes the event-related data into a series of arrays, leaving it to the logger's own thread to construct the Event object whenever it gets around to it. This should speed things up quite a bit.
One thing that helped a lot in reducing synchronization overhead was use of object copies and immutable objects; if something can't be changed by another thread, there's no need for synchronization. For instance, the internals of an EventFormatter subclass don't need to be synchronized, since things are arranged so that no two loggers ever use the same event-formatter object, instead storing inside themselves a copy of any passed-in object. I feel that avoiding even an uncontested lock acquisition can be crucial when you're worried about micro- and nanoseconds.
Pattern evaluation turns out to be quite speedy. In fact, testing the formatting of date pattern strings versus .NET date format strings shows that the .NET built-in formatting is slower. I guess it's true, sometimes, what they say-- the more generic the code, the slower the code. For a complete reference on the mini-formatting language, look in the appendix of the HTML docs.
I highly recommend NDoc, a utility put out by the NDoc project on sourceforge.net. I would've never turned out such professional-looking API docs without it.
In the works...
A configuration framework, centralized logging application, and several other enhancements. I'd welcome help on this and other planned features, if you have the time.
History
