Profling performance of custom logger class, for an application reading Word document

Question

I have an application which reads comments and paragraphs from a .docx file, using OpenXmlPowerTools. It is a console application, and it creates a debug.log file while it is running.

There is a logger class implemented, which saves messages to the text file in all builds, and prints those messages to the console for debug builds. The following code is part of this logger class:

public static class Logger
{
    public enum LogLevel
    {
        ERROR, WARNING, DEBUG
    }

    public static void Log(string message, LogLevel level, bool newline)
    {
        try
        {
            // the very next line was a hotspot, as shown in the profiler
            using (StreamWriter sw = File.AppendText(path))
            {
                // write the messages to this file
            }
        }
        catch (Exception ex)
        {
            // handle it
            // I know it is bad practice to catch System.Exception, I need to fix this.
        }
     }
}

In the code, this function is frequently called like this:

private void doSomething(string someParameter)
{
    Logger.Log("The parameter is: " + someParameter, Logger.LogLevel.DEBUG, true);
}

I have profiled the performance of this, and for a fairly large word document with dozens of comments, it took 1 min 40 s to complete. Without logging, it took only a few seconds. After some investigation, it seems like File.AppendText is very slow in .NET.

As an alternative, I tried using a buffer:

using (StreamWriter sw = new StreamWriter(path, false, Encoding.UTF8, 65536)
{
    // write the messages to the file
}

Contrary to the information in an article I have read where this approach was recommended, the performance seemed to worsen (taking more than 2 minutes). Why is this? How can I improve the performance of this?

Answer 1

Your logging code is wrong. This is how Entprise Library did start 15 years ago and it did not turn out well. Use a logging Framework and be done with it.

Now to your actual issue. You open and close the file for every log call this dead slow and causes much overhead. Keep the Log file and StreamWriter open and use a lock to ensure that you do not write concurrently data to the log file. Next you need to deal with lifetime issues because if the FileStream is finalized first your StreamWriter will not be able to flush pending data to disk and you loose the last log messages (most probably the important ones with the crash exception messsage).

To work around that flush on every log call the StreamWriter (slow) or create a wrapper class which derives from CriticalFinalizerObject and holds your FileStream open and call GC.SuppressFinalize on the FileStream instance to prevent early finalization during application shutdown.

That are the most common pitfalls you will encounter when creating your own logging library.

A small logger is e.g. here (written by me): https://github.com/Alois-xx/WMIWatcher/blob/master/FileLogger.cs