Click here to Skip to main content
15,918,808 members
Articles / Programming Languages / C#
Tip/Trick

The importance of a good Log component

Rate me:
Please Sign up or sign in to vote.
4.00/5 (1 vote)
23 Aug 2011CPOL 14.2K   7   2
Even though most people don't realize, a bad Log component can be the cause of so much performance "pain" in an application.

Thinking a little bit about it, it is really easy to understand why...

In sum, a Log component is a component that repeatedly performs I/O operations into the file system every single time something is meant to be logged. Also, it is quite common that it'll be called from multiple components, at different layer depths and also from different threads. This makes the log component very much a prime candidate to be the source of quite a few issues.

Here's a take on a possible solution for it.


C#
///
/// Public class that provides implementation of Logging mechanisms
///
public static class Log
{
  ///
  /// Log level enumeration
  ///
  public enum Level
  {
 
    ///
    ///
    Error = 0,
 
    ///
    ///
    FailureAudit = 1,
 
    ///
    ///
    Warning = 2,
 
    ///
    ///
    Information = 3,
 
    ///
    ///
    SuccessAudit = 4,
 
    ///
    ///
    Debug = 5
  }
 
  private static Level level;
  private static Queue events;
  private static Timer logWriterTimer;
  private const string LogLineTemplate = "{dateTime} - {logLevel} - {message}";
  private static string logFilePathValue;
 
  ///
  /// Boolean property that will tell us if the Log component has already been initiated
  ///
  public static bool Initialized
  {
    get
    {
      return events != null;
    }
  }
 
  ///
  /// Initializes the Log component
  ///
  ///The full path of the target log file
  ///The minimum log level required for any LogEvent to be written to the text file
  ///The interval, in milliseconds, in which the log events should be written to the file
  public static void Initialize(string logFilePath, Level logLevel, int writeDelayInMilliseconds)
  {
    logFilePathValue = logFilePath;
    level = logLevel;
    events = new Queue();
    WriteToLog(Level.Information, "Starting the Log component.");
    // Starting a new timer that will run the WriteToFile method
    logWriterTimer = new Timer(WriteToFile, null, 0, writeDelayInMilliseconds);
  }
 
  ///
  /// Diposes of the Log component.
  ///
  ///Occurs whenever Dispose is called without calling the Initialize method first
  public static void Dispose()
  {
    if (events == null)
      throw new Exception("You must first Initialize the Log component.");
    logWriterTimer.Dispose();
    WriteToLog(Level.Information, "Stopped the Log component.");
    // Called to flush any remaining items in the queue
    WriteToFile(null);
  }
 
  /// 
  /// Writes all events in the queue to the log file
  /// 
  /// required parameter for the Timer object
  private static void WriteToFile(object sender)
  {
    // StringBuilder to accumulate all current items
    var logPortion = new StringBuilder();
 
    // Lock the events to make sure we're thread safe
    lock (events)
    {
      while (events.Count > 0)
      {
        var currentEvent = events.Dequeue();
        // Extract all the events into the StringBuilder
        logPortion.Append(currentEvent.Message + Environment.NewLine);
      }
    }
 
    try
    {
      if (logPortion.Length == 0)
        return;
 
      // Create a new StreamWriter that writes to the logFilePath replacing the date time markers
      using (var writer = new StreamWriter(logFilePathValue.ReplaceDateTimeMarkers(DateTime.Now), true, Encoding.UTF8))
      {
        // Write once all the events instead of cycling through them to make the process a lot faster
        writer.WriteLine(logPortion.ToString());
      }
    }
    catch (Exception exception)
    {
      // Catch and rethrow any occured the exceptions
      throw new Exception("An error has occured while trying to write to the log file. See the inner exception for more detail.", exception);
    }
  }
 
  ///
  /// Adds the specified message to the log queue if the log level is higher or the same as the defined log level
  ///
  ///The event's log level
  ///The message to be logged
  public static void WriteToLog(Level logLevel, string message)
  {
    // Only log if the message's log level is the same or higher than the defined log level
    if (logLevel < level)
      return;
 
    // Apply message template replacements
    var eventDateTime = DateTime.Now;
    var messageToLog = LogLineTemplate.Replace("{message}", message, true);
    messageToLog = messageToLog.Replace("{logLevel}", logLevel.ToString(), true);
    messageToLog = messageToLog.Replace("{datetime}", eventDateTime.ToString(), true);
 
    // If the queue of events hasn't been initialized, we'll just trace the message and return
    if (events == null)
    {
      Trace.WriteLine(messageToLog);
      return;
    }
 
    // Create a new LogEvent
    var logEvent = new LogEvent { EventDateTime = eventDateTime, Message = messageToLog };
 
    // Lock the queue of events to make sure we're thread safe
    lock (events)
    {
      // Enqueue the event to the queue
      events.Enqueue(logEvent);
    }
  }
 
  ///
  /// Writes the message of the exception using Level.Error
  ///
  ///Exception to be logged
  public static void WriteToLog(Exception exception)
  {
    if (events == null)
      throw new Exception("You must first Initialize the Log component.");
 
    var message = exception.Message;
 
    // If the defined log level is Debug, then we also include the exception's Source and StackTrace
    if (level == Level.Debug)
    {
      message = message + "\r\nSource:" + exception.Source + "\r\nStackTrace:" + exception.StackTrace;
    }
 
    // Call the other overload of WriteToLog using the produced message
    WriteToLog(Level.Error, message);
  }
 
  ///
  /// Writes to log using Level.Debug
  ///
  ///The message to be logged
  public static void WriteToLog(string message)
  {
    // Call the other overload of WriteToLog using the message
    WriteToLog(Level.Debug, message);
  }
 
  ///
  /// Converts a string to the Log.Level enumerable value
  ///
  ///The string representation of the log level (debug, error, failureaudit, information, successaudit, warning)
  ///
  public static Level GetLogLevelFromString(string logLevel)
  {
    switch (logLevel.ToUpper())
    {
      case "DEBUG":
        return Level.Debug;
      case "ERROR":
        return Level.Error;
      case "FAILUREAUDIT":
        return Level.FailureAudit;
      case "INFORMATION":
        return Level.Information;
      case "SUCCESSAUDIT":
        return Level.SuccessAudit;
      case "WARNING":
        return Level.Warning;
    }
    // By default, we return the Error log level
    return Level.Error;
  }
}
 
///
/// Represents a single log event
///
public class LogEvent
{
  ///
  /// The date time in which the event is generated
  ///
  public DateTime EventDateTime { get; set; }
 
  ///
  /// The message to be logged
  ///
  public string Message { get; set; }
}
 
///
/// Extension methods for the string class
///
internal static class StringExtensions
{
  ///
  /// Extension method that replaces strings within the string
  ///
  ///This string instance
  ///The string to be replaced
  ///The string to replace
  ///Boolean flat toignore case
  ///
  public static string Replace(this string text, string searchText, string replaceText, bool ignoreCase)
  {
    // If we're not ignoring case, then just skip and return the results of the normal replace method.
    if (!ignoreCase)
    {
      return text.Replace(searchText, replaceText);
    }
 
    var result = string.Empty;
    searchText = searchText.ToUpper();
    var temp = text.ToUpper();
    var position = temp.IndexOf(searchText);
    while (position >= 0)
    {
      result = result + text.Substring(0, position) + replaceText;
      text = text.Substring(position + searchText.Length);
      temp = temp.Substring(position + searchText.Length);
      position = temp.IndexOf(searchText);
    }
    return result + text;
  }
 
  ///
  /// Extension method that replaces specific date/time markers ({year}, {month}, {day}, {hour}, {minute}, {second}) with the values of the passed dateTime argument
  ///
  ///This string instance
  ///the date/time from which we should get the values
  ///
  public static string ReplaceDateTimeMarkers(this string text, DateTime dateTime)
  {
    var result = text;
    result = result.Replace("{year}", dateTime.Year.ToString(), true);
    result = result.Replace("{month}", dateTime.Month.ToString(), true);
    result = result.Replace("{day}", dateTime.Day.ToString(), true);
    result = result.Replace("{hour}", dateTime.Hour.ToString(), true);
    result = result.Replace("{minute}", dateTime.Minute.ToString(), true);
    result = result.Replace("{second}", dateTime.Second.ToString(), true);
    return result;
  }
}

License

This article, along with any associated source code and files, is licensed under The Code Project Open License (CPOL)


Written By
Chief Technology Officer Soundnet Ltd
United Kingdom United Kingdom
This member has not yet provided a Biography. Assume it's interesting and varied, and probably something to do with programming.

Comments and Discussions

 
Questionbuffering...good idea Pin
JimH6923-Aug-11 4:45
JimH6923-Aug-11 4:45 
This is a good thing (IO performance) to keep in mind. It makes me curious to think what is the underlying hardware doing about this issue. Is there buffering going on at that level as well? If so is the buffering you introduce helping or hindering or simply redundant? That’s not a critique, just a random thought.

Another point to consider is that with buffering you run the (smallish) risk of losing multiple log entries if the system goes down or the application crashed unexpectedly. This could potentially cause one to misinterpret where the app was in its processing when things went sideways.

That said I really like your design and plan to incorporate it in my current logging code. Many thanks. Smile | :)
AnswerRe: buffering...good idea Pin
luisvaldez23-Aug-11 5:10
luisvaldez23-Aug-11 5:10 

General General    News News    Suggestion Suggestion    Question Question    Bug Bug    Answer Answer    Joke Joke    Praise Praise    Rant Rant    Admin Admin   

Use Ctrl+Left/Right to switch messages, Ctrl+Up/Down to switch threads, Ctrl+Shift+Left/Right to switch pages.