January 2006 - Posts
With the release of the Enterprise Library 2.0 Application Blocks from Microsoft I was interested to find out if the Logging Application Block provided is faster than the tried and true Log4Net library I've been using for a few years from SourceForge. To do this, I figured I'd perform two sets of head-to-head tests - flat file based logging and database logging.
Part I - File logging
I first decided to tackle file based logging as it is easier to get set up and would allow me to get familiar with the basics of the new application block code. In order to make it a fair test I had to make sure the application block would be configured to log the same output I'm getting with my customzied Log4Net wrapper class. My standard output fields from Log4Net with every log entry are:
- DateTime stamp
- Tick count (in case logging occurs at the same millisecond the tick count is more finite and allows me to determine the order of events in tied time stamp records)
- Log Level (Error, Warning, Info, Debug, Verbose), some people call it severity
- Machine name
- Thread ID
- Source (the name of the assembly and class logging the message)
- Method (name of the method logging the message)
- Context (optional additional context data, not used in these tests)
- Message
The Logging application block code was able to give me all of the above fields except for the Source and Method. This didn't surprise me too much as I had to customize Log4Net to get that information originally. So, to make the tests equivalent I took the same reflection code that I use in my Log4Net wrapper class and put it in the test application to look up the source and method values and pass them in with the Logging Application Block Logger.Write method.
The one significant difference between the two loggers that could affect the results is that the code for Log4Net was written for the .Net 1.1 Framework and the Enterprise Library Logging Application Block was written for the .Net 2.0 Framework. Advantage: Logging Application Block.
The output for each log would be a single line entry in a text file. Here is the conversion pattern used for the Log4Net AllTypesRollingLogFileAppender in the app.config:
<!--
value="#TIME TICK_COUNT THREAD_ID LOG_LEVEL MACHINE_NAME SOURCE METHOD CONTEXT MESSAGE\r\n" --><param name="ConversionPattern" value="%d{yyyy'-'MM'-'dd HH':'mm':'ss'.'fff}|*|%P{tick_count}|*|%-5p|*|%X{machine}|*|%t|*|%c|*|%M|*|%x|*|%m|*|%n"/>
Here is the formatter for the Logging Application Block that the Flat File TraceListener will use. I'm adding two dictionary entries with a key name of Source and Method in my code so they will appear in the dictionary section of the output format string.
<
formatters>
<
add template="{timestamp}|*| {win32ThreadId}|*|{severity}|*|{machine}|*|{dictionary({key} - {value}; )}|*|{message}"
type="Microsoft.Practices.EnterpriseLibrary.Logging.Formatters.TextFormatter, Microsoft.Practices.EnterpriseLibrary.Logging, Version=2.0.0.0, Culture=neutral, PublicKeyToken=null" name="Text Formatter" />
</
formatters>
The (Unofficial) Results
After getting my test application together it would simply run a loop writing log entries based on a user entered loop iteration count. Both loggers would continue appending the entries to their respective log file until the test cycle was done. The next text cycle would start with a fresh log file again. I also ran an iteration of one log entry for each logger as an initializer as each logger has an initial performance hit when first called to initialize the file, load assemblies and spin up shared resources. The WinForm test application was run in stand-alone release mode to simulate a normal production application.
Test Run 1
| # of Log Messages |
Log4Net (ms) |
Logging Application Block (ms) |
| 1 (initializer) |
140 |
190 |
| 1 |
20 |
< 1 |
| 10 |
10 |
< 1 |
| 100 |
50 |
40 |
| 1000 |
430 |
360 |
| 10000 |
3955 |
3545 |
Test Run 2
| # of Log Messages |
Log4Net (ms) |
Logging Application Block (ms) |
| 1 (initializer) |
150 |
190 |
| 1 |
10 |
< 1 |
| 10 |
10 |
< 1 |
| 100 |
70 |
30 |
| 1000 |
400 |
350 |
| 10000 |
3915 |
3485 |
Test Run 3
| # of Log Messages |
Log4Net (ms) |
Logging Application Block (ms) |
| 1 (initializer) |
140 |
190 |
| 1 |
20 |
< 1 |
| 10 |
10 |
< 1 |
| 100 |
50 |
40 |
| 1000 |
390 |
340 |
| 10000 |
3965 |
3545 |
So far the Logging Application Block is winning the competition. I'd be interested to know if there are changes that could be made to Log4Net to take advantage of the changes in the .Net Framework 2.0 and eliminate the time differences or if the Logging Application Block would still hold the advantage.
For my next segment I'll display the results of testing the two loggers writing to a SQL database. Stay tuned!
Coincidentally, Microsoft just released their .NET 2.0 versions of the enterprise application blocks. If after my last post you started looking into a standard code base to use to perform logging the Logging Application Block is a great set of code to consider. You could also look to quickly integrate the other enterprise blocks and conform all your projects to utilize common data access, configuration and caching code. Check out
http://msdn.microsoft.com/library/en-us/dnpag2/html/EntLib2.asp?frame=true for the .NET 2.0 versions and
http://msdn.microsoft.com/library/en-us/dnpag2/html/entlib.asp?frame=true for those continuing on with the .NET 1.1 framework.
Do your enterprise applications log? If they aren't, when there is a system problem you probably wish they did or wish the logging you worked in was more robust or consolidated. I encounter a lot of applications where logging was an after-thought that occurred when issues began occurring in production and team's realized they can't hit F5 and step through code to determine the problem. For a lot of developers logging is not something that is intuitively thought of when writing code, primarily because the everyday development IDE now has such robust debugging capabilities logging isn't needed during development. Once code is in production though the situation is drastically different and trace logging becomes a critical difference between solving an issue in 5 minutes or 5 hours. Five hours in production downtime can equate to thousands or millions of dollars depending on the system.
How a system will log should be a feature discussed during system design along with business functionality. In many enterprise systems today there are multiple servers and applications all contributing to the end result. A centralized and real-time configurable logging architecture is crucial. There are many ways to log - writing to a database, writing to files, dropping messages on a queue, utilizing the event log, etc. My preference is to centralize logging to a stand alone database so that the OLTP application database is not affected by the logging activity. This centralized data is where all of the different applications write their log entries. The log data can then be viewed, searched or reported using any sort of package reporting software (such as Crystal Reports) or a simple custom WinForm/Web application (a data grid and query buttons to load information). When using centralized logging it is important to log with each message entry the machine name, date/time, thread, log level (error, warning, informational, verbose, etc) and component that the entry originated from. With this meta data you can easily isolate and view log entries from only one trouble server, buggy component, period of time, ect.
There are two simple ways you can incorporate logging into your applications. One is to use a freeware community component called log4net (found on Sourceforge - http://sourceforge.net/projects/log4net). This component has been around for a few years now so it is very reliable and the performance overhead is small if you limit your active logging level in production (and this level can be changed on the fly without restarting your applications). Log4net allows you to log to a single or multiple locations by just changing the settings in your app.config file. It has built in support to log to a database, event viewer, and file and you can extend it with custom code to allow it to log to any customized logging architecture you may be using.
Another way to log is to make your own TraceListener class and then use Trace.Write calls within your code to utilized your custom trace class. To make a TraceListener you need to inherit from the TraceListener class and Overload the Write and WriteLine methods to direct the log entry to your custom logging location. Here is an example of a simple trace listener that writes to a database.
'Internal ClientLog class that derives from the TraceListener framework class. Log entries are pulled from the trace listener
'and inserted into the database if the log level declared is active. Err and Warn LogLevel's are always logged. Debug LogLevel's
'are only logged if the Debug appSetting is set to true in the app.config file.
'To enable debug logging add the following line in the <configuration><appSettings> section of the app.config:
' <add key="DEBUG" value="true" />
Friend
Class ClientLog
Inherits TraceListener
Public Overloads Overrides Sub Write(ByVal message As String)
Me.Write(message, Convert.ToString(LogLevel.Debug))
End Sub
Public Overloads Overrides Sub WriteLine(ByVal message As String)
Me.Write(message, Convert.ToString(LogLevel.Debug))
End Sub
'Main method that logs, all other overloads call this method to log the message
Public Overloads Overrides Sub Write(ByVal message As String, ByVal category As String)
Try
'check the configuration, load the log level
Dim isLoggingEnabled As Boolean = Convert.ToBoolean(ConfigurationSettings.AppSettings("Debug"))
'if category of logging was 1 or 2 then always log, if 3 then log if isLoggingEnabled is true
Dim logEntryLevel As Integer = Convert.ToInt32(category)
If (logEntryLevel < 3) Or isLoggingEnabled Then
'log an entry into the database
Dim tickCnt As Integer = Environment.TickCount
'TODO: You'll want to have other data available here to log such as the methodname, thread information, etc. Just expand your write method signature to pass along that information too.
'insert the log entry
SqlHelper.ExecuteNonQuery(SqlHelper.LOCAL_DPEDB_CONNECTION_STRING, CommandType.Store
dProcedure,
"Logs_Insert", New SqlParameter() {New SqlParameter("@SeverityLevel", logEntryLevel), New SqlParameter("@TickCount", tickCnt), New SqlParameter("@Message", message)})
End If
Catch ex As Exception
'TODO: handle the exception but don't throw it to the caller. You don't want logging issues (such as the logging database down for maintanence) causing your business logic to fail.
End Try
End Sub
End
Class
You can then wrap this with a static class entry point that configures and then executes the TraceListener class.
Public
Enum LogLevel
Err = 1
Warn = 2
Debug = 3
End
Enum
Public
Class Log
Private Shared _logType As LogType = LogType.Client
Public Enum LogType
Client
Server
End Enum
Public Shared Sub InitializeLogging(ByVal logType As LogType)
_logType = logType
Trace.Listeners.Add(New ClientLog)
Trace.AutoFlush = True
End Sub
Public Shared Sub Write(ByVal message As String)
Write(message, LogLevel.Debug)
End Sub
Public Shared Sub Write(ByVal message As String, ByVal level As LogLevel)
Trace.Write(message, Convert.ToString(level))
End Sub
End
Class
Once you have logging built into the architecture its still up to your project team to make it a habit of entering log writing statements into their code. If they don't there will be nothing to help trace the execution path of the code when you enable logging in that production outage scenario. Teach your developers to get in the habit of logging with the correct log level at decision points in the code. I try to follow rules similar to these:
- Log an error in all exception handlers. This includes writing the exception information into the log.
- Log a warning in logic branches where code is continuing, but data did not look as it was expected. Be sure to include the suspect data value(s) in the log entry.
- Log an informational entry when a significant piece of logic completes including how much data was transacted and/or how long the transaction took. (i.e. "The file c:\data.txt was successfully processed for 45 orders.")
- Log debug/verbose entries at logic branch points to help perform a detailed trace of the code. These low level log entries won't show up in the log in normal production mode, they would only be enabled when there was a serious problem that needed to be traced through or during development to help follow code execution without having to step through logic in the debugger.
It's hard to express how beneficial good logging is until you run into a production issue where you wish you would have had it!
Happy New Year everyone! As part of the new year I've decided to begin posting bi-monthly blogs (at the least, some may be more frequenet) on technical topics that are currently captivating my interest. For my first blog I'm going to start off with a less discussed updated feature of Visual Studio 2005 - project templates. I know, most people will see that topic and thing 'who ever uses those things?'. That's the same thought I initially had when I began working on my recent MSDN article (http://msdn.microsoft.com/library/default.asp?url=/library/en-us/dnvs05/html/CreatStrtKt.asp) but after playing with it I starting thinking of how useful this would be to my development teams. There were two main uses that came to mind that I think almost any development team would find helpful.
1. Windows services projects - I've built a lot of windows services projects and there is a bunch of routine steps that always have to be coded at the beginning of the project before even getting to business specific logic such as the start/stop controling of worker threads, setting service name attributes, and adding informational logging code to record start/stop/failure. Since all of this stuff is the the same a project template would fit these projects perfectly. The template can contain my main service class and my worker thread classes already defined with public start/stop methods so that they can be manipulated from the service code in response to a service start/shut down command. The main service class can already have the informational logging and entry point for worker thread creation. With a little extra effort you could add a project template wizard implementation (an advanced template feature) that allowed the user to specify the service attributes when they were opening a new windows service project and then fill it into the class for them. Now with this project template anyone on the development team could create a new service that conforms to the same standards as all the service created by the team.
2. Windows Form projects - There is some repititive stuff in Windows Forms projects a template could handle for me too. The main thing is adding all the project references to third party components. Having a standard sub Main routine could be helpful too as it would allow a standard entry point for all windows programs where additional code could be added (such as splash screen start ups, application update code, large data loading, etc). Since I'm making templates anyway, adding a class template for a windows form that inherits from a common base class (which could have all your application logging, resource loading, standard window look/feel) would be helpful too. Then developers could just select the custom form template off the Add New Item menu and go right to work on laying out the form design.
These will be my first two templates created once I'm on a project that uses 2005 exclusively. I'm sure there are more, but they may be more architecture specific - such as templates for components that must implement an interface, or web site/intranet work where projects must utilize common look and feel elements or state management. I encourage everyone to take a look at this feature and I bet ideas will start popping into your mind on reptitive project tasks you do now. It's definitely not one of the snazzy features talked about in all the Visual Studio press, but the templates team did a great job on making it simple to use and greatly improving it over the VS 2003 version.