Monday, February 26, 2007

Oracling your log4net messages Log4NetOracleAppender

Log4Net has gained enormous popularity across .Net developers over the last years. And there is no wonder, at last there is a logging utility that is powerful and yet easy to use.
For those of you who don''t know log4net, check it out at http://logging.apache.org/log4net/.
One of the coolest things about log4net, is the Appender class that allows developers to output their logs to different logging targets.

log4net is supplied with more than a couple appenders (see examples here http://logging.apache.org/log4net/release/config-examples.html)
with them we can output our logs in to text files, event viewer, xml, console, smtp, database and many more. But there is still one question remains, what appender should I use?

Chossing an Appender
Projects are usually struggling with the question, of what appender is most suitable for their application. The first obvious choice is usually the RollingFileAppender, which is simple, reliable and easy to configure. But what about DatabaseAppender (or in it's formal name 'AdoNetAppender')?

Writing logs to database has a lot of advantages:


  • Deals well with large quantities of data. can store millions and millions of rows, and has a built in mechanism for archiving.
  • Shared across multiple applications, and more importantly across multiple applications servers.
  • And maybe the most important thing: messages written to database, are formatted to fields, and therefore queryable. Message stored in the database can be easily sorted, filtered, grouped and so on.

But what about the disadvantages?
The most common issues developers usually raise against storing messages in the database are:

  • What if I have a problem in my system that's related with the database itself? That is indeed a good issue, but databases are much more stable these days, and in a well maintained environment, this should be a rare issue. Besides, isn't this problem also relevant to files? Writing to a file also isn't fault-safe, file can be locked by other process, the disk can be full. So in any case, a backup log is a good practice.
  • The 2nd one is usually, what about the performance? Well this is cool part.
    Log4net and the AdoNetAppender in particular, are designed to make the performance optimal, to the point that it's a non-issue in most systems.

Some performance tricks

  • Maybe the most importance thing is that log messages are asynchronous, meaning - your application never waits till message is actually written to database, so logging doesn't really affect the application response time.Connection always opened. Because the logger is a singleton in the system, there is no sense in opening and closing connections for each execution. So there is no overhead for opening connections.
  • AdoNetAppender also uses statement caching against the database. This feature minimizes the execution process very significantly.
  • Messages aren't flushed to the database for every message, thanks to log4net's buffering Appenders, messages persistence is deferred until the buffer is full so database round trips are minimized.

So, can it get any better than this?
The answer is yes, it can!

Log4NetOracleAppender

So I was looking at the source code of the AdoNetAppender, to see how is the database execution is implemented. And there it was:



a For loop 
    With a cmd.ExecuteNonQuery() inside



Why not use bind array ?!
In that moment I was shocked, all that hard work for nothing, to go that far and ruin it all at the end?
ok, maybe I'm exaggerating a little bit , AdoNetAppender is a generic database appender and not Oracle appender, so obviously it would not use that feature. But actually, bind array perform up to a 100 times better than multiple executions (depends on network and the number of rows).

OracleAppender

So I took AdoNetAppender, and twiked it a little. Basically making it to work with ODP.NET.
The major change is in the SendBuffer method, which is the method responsible for adding the records to the database, when the buffer is full. And it goes something like this...




ArrayList paramArr = null;
foreach (OracleAppenderParameter param in m_parameters)
{
    paramArr = 
new ArrayList();
    
OracleParameter oracleParam = (OracleParameter)m_dbCommand.Parameters[param.ParameterName];
    
foreach (LoggingEvent in events)
    {
        
object value = param.Layout.Format(e);
        
if (value.ToString()=="(null)")
        {
            value = System.
DBNull.Value;
        }
        paramArr.Add(value);
        
    }
    oracleParam.Value = paramArr.ToArray();
}
m_dbCommand.ArrayBindCount = events.Length;
m_dbCommand.ExecuteNonQuery();



You can download the complete code here: Log4netOracleAppender.zip.
It's a good practice that you compile it into a dedicated assembly. If you do, make sure you use the full qualified name for the type, in the configuration (described later on)

Configuration

The configuration isn't really different from the built-in AdoNetAppender, but to save you the hassle of reading some documentation, here is the short version:

Add the OracleAppender section




<appender name="OracleAppendertype="log4net.Appender.OracleAppender>
  <
connectionString value="data source=xe;User ID=tomer;Password=tomer/>
  <
bufferSize value="20"/>
  <
commandText value="INSERT INTO Log (LogDate,Thread,logLevel,Logger,Message) VALUES (to_timestamp(:log_date, 'dd-MM-yyyy HH24:mi:ss.ff6'), :thread, :log_level, :logger, :message)/>
  <
parameter>
    <
parameterName value=":log_date/>
    <
dbType value="String/>
    <
layout type="log4net.Layout.PatternLayoutvalue="%date{dd'-'MM'-'yyyy HH':'mm':'ss'.'ffffff}/>
  </
parameter>
  <
parameter>
    <
parameterName value=":thread/>
    <
dbType value="String/>
    <
size value="255/>
    <
layout type="log4net.Layout.PatternLayoutvalue="%thread/>
  </
parameter>
  <
parameter>
    <
parameterName value=":log_level/>
    <
dbType value="String/>
    <
size value="50/>
    <
layout type="log4net.Layout.PatternLayoutvalue="%level/>
  </
parameter>
  <
parameter>
    <
parameterName value=":logger/>
    <
dbType value="String/>
    <
size value="255/>
    <
layout type="log4net.Layout.PatternLayoutvalue="%logger/>
  </
parameter>
  <
parameter>
    <
parameterName value=":message/>
    <
dbType value="String/>
    <
size value="4000/>
    <
layout type="log4net.Layout.PatternLayoutvalue="%message/>
  </
parameter>
</
appender>


Make sure you change the connection string parameter to the desired database. You can also change the commandText to suit your database table and columns.

The BufferSize parameter is where you can set how many rows will be buffered until all rows flushed to the database with one Bind Array statement.

Now just make sure that you create the logs table itself, for example:



CREATE TABLE "LOG" 
("LOGDATE" 
TIMESTAMP(6),
"THREAD" VARCHAR2(255 BYTE),
"LOGLEVEL" VARCHAR2(20 BYTE),
"LOGGER" VARCHAR2(255 BYTE),
"MESSAGE" VARCHAR2(4000 BYTE))  


5 comments:

Shmuel Krakower said...

Great post! Very in-depth.. still I have one question about this open source logger. It logs the records in an async way... There might be a case that the application will hang/crush right after the log method has been invoked but because it is async we'll miss it, right?
Is there a way tell Log4Net to work in a sync way?

Tomer Avissar said...

Well Shmuel, log4net's logging itself is synchronous, but the writing to the appender is sometimes asynchronous, like in the case of AdoAppender / OracleAppender (basically all appenders that extends BufferingAppenderSkeleton).
In the case of an expected shutdown of a system, application should call LogManager.Shutdown() which make log4net flush all the buffering appenders. But in a case of a crash, the only option as I see it, is to implement a SyncDatabaseAppender, that doesn't use a buffer. Of course these will have a performance overhead.

Ayesha said...

Hi
I am using log4net in variety of programs and till now there is no issues with it till now. It scales good and works well in multithreading environment also..

Ayesha
http://dotnetinterviews.blogspot.com/

Anonymous said...

Thanks for the nice post!

Tomer Avissar said...

try to connect with sqlplus or other tool to with the same user/pass defined in your connectionString tag.
Then try to execute "select * from Log" and see if you get the same error message or not.

This is typically either a permission problem or you are missing the schema name.