Click here to Skip to main content
Email Password   helpLost your password?

Introduction

When you want to log from multisource into single log using log4net, the theory is using AdoNetAppender or EventLogAppender.

But if it's hard to use Databases , EventLog, syslog and so on. Here is the way to logging into single logfile from mutli-process runnning concurrently.

Problem

The problem of using Fileappender from processes runnning concurrently is file lock confilict.
When the first process gets write lock for logfile, any other process can't get write lock for logfile and can't write a LogEntry into logfile.

log4net has a solution for this problem, it's called MinimalLock locking model.
In this locking model, log4net gets write lock when the looger write LogEntry into logifile, and release lock once LogEntry is logged.
So this locking model holds lock for minimal time, it's reduce the conflicts but not eliminate.

I extends Minimallock and eliminate conflict.

Solution

The concept is,
1. Caching LogEntry into cache instead of writing into file directory.
2. Dequeue and writing into file in new thread.
3. When Confilict is detected, wait random time and retry.

public class ConcurrentMinimalLock : FileAppender.MinimalLock
 {
  private string m_filename;
  private bool m_append;
  private Stream m_stream=null;
  private ConcurrentStream c_stream = null;
  public override void OpenFile(string filename, bool append, Encoding encoding)
  {
   m_filename=filename;
   m_append=append;
  }
  public override void CloseFile()
  {
   // NOP
  }
  public override Stream AcquireLock()
  {
   if (m_stream==null)
   {
    try
    {
     using(CurrentAppender.SecurityContext.Impersonate(this))
     {
      string directoryFullName = Path.GetDirectoryName(m_filename);
      if (!Directory.Exists(directoryFullName))
      {
       Directory.CreateDirectory(directoryFullName);
      }
      
      if(c_stream == null)
      {
       c_stream = ConcurrentStream.GetInstance(m_filename, m_append, FileAccess.Write, FileShare.Read);
      }
      m_stream = c_stream;
      m_append=true;
     }
    }
    catch (Exception e1)
    {
     CurrentAppender.ErrorHandler.Error("Unable to acquire lock on file "+m_filename+". "+e1.Message);
    }
   }
   return m_stream;
  }
  public override void ReleaseLock()
  {
   using(CurrentAppender.SecurityContext.Impersonate(this))
   {
    m_stream.Close();
    m_stream=null;
   }
  }
 }

First, I extends MinimalLock Class and Replace stream with ConcurrentStream

public class ConcurrentStream : Stream
 {
  private string path;
  private bool append;
  private FileAccess access;
  private FileShare share;
  private QueueManager queueManager;
  private static ConcurrentStream instance;
  
  public static ConcurrentStream GetInstance(string path,
   bool append,
   FileAccess access,
   FileShare share)
  {
   if(instance == null)
   {
    instance = new ConcurrentStream(path,append,access,share);
   }
   return instance;
  }
  private ConcurrentStream (
   string path,
   bool append,
   FileAccess access,
   FileShare share
   )
  {
   this.path = path;
   this.append = append;
   this.access = access;
   this.share = share;
   this.queueManager = QueueManager.GetInstance(path,append,access,share);
  }

  public override void Write(byte[] buffer, int offset, int count)
  {
   CachedEntry entry = new CachedEntry(buffer,offset,count);
   queueManager.Enqueue(entry);
  }
 }

Next, Create ConcurrentStream Class extending Stream.
Write method doesn't write directly, instead write information into queue.

internal class QueueManager
 {
  
  private string path;
  private bool append;
  private FileAccess access;
  private FileShare share;
  
  private Queue syncQueue = Queue.Synchronized(new Queue());
  
  private bool running = false;
  private Random rnd = new Random();
  private DateTime retryTime = DateTime.MaxValue;
  
  private static TimeSpan RETRY_MAX_SPAN = TimeSpan.FromMinutes(1);
  private static QueueManager instance;
  private const int MAX_BATCH_SIZE = 100;
  
  
  public static QueueManager GetInstance(string path,
            bool append,
            FileAccess access,
            FileShare share)
  {
   if(instance == null)
   {
    instance = new QueueManager(path,append,access,share);
   }
   return instance;
  }
  private QueueManager(
   string path,
   bool append,
   FileAccess access,
   FileShare share)
  {
   this.path = path;
   this.append = append;
   this.access = access;
   this.share = share;
  }
  internal void Enqueue(CachedEntry entry)
  {
   syncQueue.Enqueue(entry);
   
   if(!running)
   {
    lock(this)
    {
     running = true;
     Thread th = new Thread(new ThreadStart(this.Dequeue));
     th.Start();
    }
   }
  }
  private void Dequeue()
  {
   CachedEntry entry =null;
   try
   {
    using(FileStream fs = new FileStream(path,FileMode.Append,access,share))
    {
     int processedCount = 0;
     while(true)
     {
      processedCount ++;
      if(syncQueue.Count == 0)
      { 
       //quit when queue is empty
       lock(this)
       {
        running = false;
        return;
       }
      }
      else
      {
       entry = (CachedEntry) syncQueue.Dequeue();
      }
  
      if(entry !=null )
      {
       Write(entry,fs);
      }
     }
    }
   }
   catch(IOException ioe)
   {
    if(DateTime.Now - retryTime > RETRY_MAX_SPAN)
    {
     lock(this)
     {
      running = false;
     }
     throw;
    }
    //When can't aquire lock
    //Wait random time then retry
    Thread.Sleep(rnd.Next(1000));
    Console.WriteLine("Retry:" + DateTime.Now);
    retryTime = DateTime.Now;
    Dequeue();
   }
  }
  private void Write(CachedEntry entry,FileStream fs)
  {
   fs.Write(entry.Buffer,entry.Offset,entry.Count);
   fs.Flush();
  }
 }

And above is the queue implementation.
When logentry is enqued, dequeue is runnnin on new thread.
When the conflict occurs, wait random and then retry.(like CSMA/CD)

Thus, we can make multi-process logging successsully.

internal class CachedEntry
 {
  private byte[] buffer;
  private int offset;
  private int count;
  internal byte[] Buffer
  {
   get{return buffer;}
  }
  internal int Offset
  {
   get {return offset;}
  }
  internal int Count
  {
   get {return count;}
  }
  internal CachedEntry(byte[] buffer, int offset, int count)
  {
   this.buffer = new byte[buffer.Length];
   buffer.CopyTo(this.buffer,0);
   this.offset = offset;
   this.count = count;
  }
 }

Finally, above is the entry queued.

And cofiguration file looks like below

<configuration>
 <configSections>
  <section name="log4net" type="System.Configuration.IgnoreSectionHandler" />
 </configSections>
 
 <log4net>
  <appender name="AppenderTest" type="log4net.Appender.FileAppender">
   <param name="File" value="C:\\temp\\logtest.txt" />
   <param name="AppendToFile" value="true" />
   
   <param name="LockingModel" type="ConcurrentLog.ConcurrentMinimalLock,ConcurrentLog"/>
   
   <layout type="log4net.Layout.PatternLayout">
    <param name="ConversionPattern" value="%d [%t] %-5p - %m%n" />
   </layout>
  </appender>
  
  
  <logger name="LoggerTest">
   <level value="DEBUG" />
   <appender-ref ref="AppenderTest" />
  </logger>
  
 </log4net>
</configuration>

You must Sign In to use this message board.
 
 
Per page   
 FirstPrevNext
Generalretry timeout issue
Patrik Hartlén
2:10 16 Nov '09  
Hi, great post!

I think you'll need something like this [1] to be able to handle if it has passed more that one minute since the last file access error occurred. And also not to reset the retry time for every failure.

[1]

Thread.Sleep(rnd.Next(1000));
if (retryTime == DateTime.MaxValue)
retryTime = DateTime.Now;
Dequeue();
retryTime = DateTime.MaxValue;

Questionperformance
shveik
8:36 29 Jul '08  
I wonder if this solution is less taxing overall performance-wise than using a UDP or Remoting Appenders? I guess since you are using ThreadPool threads, the overhead is not that great if this happens often, but otherwise, it's no different than using a new Thread object everytime, and that's pretty expensive. Also one setback is that the message will arrive to the logfile out of order, but the timestamp will be preserved, so i guess you could make a note of that once going through the log file.
GeneralSource code [modified]
mlhmlh
4:42 24 Jul '08  
Very nice article, thanks a lot.
Source code should be included it will help us to know what's missing in ConcurrentStream to build correctly.
As you've designed ConcurrentStream inheriting Stream class who has a lot of abstract members to override.

Cheers
Marc

Anyway, here below my guessed implementation

public override bool CanRead
{
get { return false; }
}

public override bool CanSeek
{
get { return false; }
}

public override bool CanWrite
{
get { return true; }
}

public override void Flush()
{
return;
}

public override long Length
{
get { return 0L; }
}

public override long Position
{
get { return 0L; }
set {;}
}

public override int Read(byte[] buffer, int offset, int count)
{
return 0;
}

public override long Seek(long offset, SeekOrigin origin)
{
return 0L;
}

public override void SetLength(long value)
{}

modified on Thursday, July 24, 2008 11:15 AM

QuestionSource Code
jslaybaugh
9:48 24 Jun '08  
This is exactly what I've been looking for! Kudos! Can you include source code for download? I'm a VB.NET guy and I'm not having much success compiling this as a library in C# with my limited knowledge. Thanks in advance!
GeneralWhy this improvement?
Martin.Holzherr
5:34 3 Jun '08  
Your improvement avoids waits by defering logging.
But did this improvement arise from a real world problem?
Did you encounter bad performance because of logging locks or
was this just an exercise?
GeneralRe: Why this improvement?
Masayuki Tanaka
5:30 4 Jun '08  
Real world problem?

Yes it's is real world problem. But not for perfomance.
In our production evironment, we have a batch application running simultaneously.(same .exe and same .exe.config)

Among these processes, they use same .config, so they log into same file.
In this pattern, first process can log, but other process can't log (not wait).

So I avoid lock by deffering log
GeneralInformative, but one query.
dnpro
1:46 3 Jun '08  
I like the approach for handling logging by multiple threads,

But I have a simple query, that is if one thread is logging some information for some operation e.g. amount transfer. and the operation takes more time due to slower data access. then in these kind of scenarios, other thread will wait or it will log the information in idle time of first thread.

Please correct if i misunderstood something.

Wink

Thanks in advance

dnpro

GeneralRe: Informative, but one query.
Masayuki Tanaka
5:13 4 Jun '08  
Thank you for reading article.

Above scenario may look like this.

01:private void TrasferAmount()
02:{
03: Log.Info("Start Transfer");
04:
05: //Do Some Time consuming process
06:
07: Log.Info("End Transfer")
08:}


In this case, Logger locks logfile on line 03 and writes "Start Transfer" then release lock.
So when this thread executing time-consuming process(line 05), other threads can write log without wait.

If two threads execute line 03 at same time,
the first thread can write log, and second thread creates another thread (say third thread) for wait lock, so second thread itself doesn't have to wait.
JokeVery Good job, it must be included into log4net
Francisco Moreno
1:12 10 Jun '08  
Very good job, in fact in some escenaries with amount of process working it´s a very good alternative. I think it must be included into log4net as a new option.

thanks.


Last Updated 2 Jun 2008 | Advertise | Privacy | Terms of Use | Copyright © CodeProject, 1999-2010