Adding Logging Capabilities to an Application

Article
06/10/2008

This topic describes how you can use the functionalities provided by System.IO.Log to add logging capabilities to your application.

FileRecordSequence versus LogRecordSequence

To choose a simple file-based log and a Common Log File System (CLFS)-based log, you have to consider the following four criteria: platform support, feature richness, robustness and performance.

Simple file-based logs are available on all platforms for which System.IO.Log is supported, whereas CLFS based logs are only available on Windows Server 2003 R2 and Windows Vista platforms. In addition, some CLFS features are disabled on Windows Server 2003 R2. This can affect your application's handling of specific conditions such as automatic growth handling. For more information on such limitations, see LogRecordSequence.

Policy and multiplexing are two features that contribute to the feature richness of the CLFS-based LogRecordSequence class, compared to the simple file-based FileRecordSequence class. Setting policies using the LogPolicy structure allows very fine grained control over maintenance features, such as auto-grow and auto-shrink of log size, minimum and maximum extent containers, and tail-pinned thresholds. These features also allow the creation of circular logs using the CLFS-based LogRecordSequence class. Multiplexing, or the ability to manipulate NTFS file streams, can yield increased performance and convenience within a single application or multiple applications working together as a unit. Therefore, applications designed for long-running scenarios or extremely high performance can benefit most from using the LogRecordSequence class, as opposed to the FileRecordSequence class.

In addition, CLFS provides robustness and performance advantages. CLFS is designed to be used by high-performance applications or in an enterprise environment. If application constraints allow for running on a CLFS supported platform, the LogRecordSequence class will not only allow for more options when controlling log file maintenance through the LogPolicy class, but will also lead to increased IO performance.

Major Classes in System.IO.Log

The followings are three of the most important classes in System.IO.Log. For more information on their usage, see their respective reference documentation.

IRecordSequence
LogRecordSequence
LogPolicy

Using System.IO.Log

Opening a Log and Adding Extents

Opening a log and adding extents is typically the first task for adding logging capabilities to your application. Notice that adding extents can only be performed when using the CLFS-based LogRecordSequence class.

You should consider the location of the log, as well as the number and size of extents to be added to the log initially. Storage location is only limited by the user account for which the application is running under. A valid location can be anywhere on the local system where this user has write-access to. The number of extents and their size, however, requires more application-specific consideration. When adding the initial extent to the log, a size must be provided. This size is used for all additional extents added to the log either manually or through the auto-grow behavior. Furthermore, in order to take advantage of many features provided by the LogPolicy class, at least two extents must be present at all times for a given sequence.

The following example demonstrates how to create a log and add two, 1MB extent containers to it.

LogRecordSequence recordSequence = new LogRecordSequence("application.log", FileMode.CreateNew);
recordSequence.LogStore.Extents.Add("app_extent0", 1024 * 1024);
recordSequence.LogStore.Extents.Add("app_extent1");

Setting a Policy

Setting log policies using the LogPolicy structure should be the second task in developing your logging application. Notice that this task can only be performed when using the CLFS-based LogRecordSequence class, and must be set each time a log is opened as policies are not persisted.

A policy contains important options such as auto-grow and maximum extent count. Throughout the course of an application's lifetime, varying loads can cause the initial set of extents to become depleted, possibly resulting in a SequenceFullException during execution. To prevent this from happening, it is often desirable to allow the log to automatically grow to accommodate this additional load transparently. Note that manual addition of extents during SequenceFullException is supported, and can be used instead of transparent auto-grow.

When working with a circular log, you should also set a maximum extent count. In addition, the LogPolicy structure offers several common auxiliary settings such as auto-shrink and growth-rate settings. Manipulating these values can have significant effects on application performance, and should be adjusted based on the I/O rate to any given log within the system.

The following example demonstrates setting a log policy for auto-growth up to a maximum of 100 extents, growing by 5 extents at a time.

recordSequence.LogStore.Policy.AutoGrow = true;
recordSequence.LogStore.Policy.MaximumExtentCount = 100;
recordSequence.LogStore.Policy.GrowthRate = new PolicyUnit(5, PolicyUnitType.Extents);
recordSequence.LogStore.Policy.Commit();
recordSequence.LogStore.Policy.Refresh();

Appending a Record

You should consider various techniques for providing data in a format understood by the Append methods.

The current Append methods have been optimized for handling byte arrays and lists of byte arrays. However, you can also use it in conjunction with higher-level serialization classes. The resulting record format must still be understood in order to effectively leverage features provided by the IRecordSequence class. The following demonstrates a high-level serialization code sample using the features based on DataContractAttribute in System.Runtime.Serialization.Formatters.

SomeDataContractClass someClassInstance = new SomeDataContractClass(…);
ArraySegment<byte>[] recordData = new ArraySegment<byte>[1];

using (MemoryStream formatStream = new MemoryStream())
{
   IFormatter formatter = new NetDataContractSerializer();
   formatter.Serialize(formatStream, someClassInstance);
   formatStream.Flush();
   recordData[0] = new ArraySegment<byte>(formatStream.GetBuffer());
}

recordSequence.Append(recordData, …);

When appending records to a record sequence, you should carefully consider the space and time constraints of your application. For example, your application may enforce that an append operation only succeed if there is sufficient space remaining in the log to write additional records in the future using ReservationCollection class. ARIES-based transaction processing systems may typically refer to such records as compensation or undo records, which are used when work needs to be rolled-back. Similarly, some systems have stringent rules governing the time when records should be written. Selecting which records to flush to disk, and which to allow lazy-flush are based exclusively on application requirements and system constraints. These considerations can affect both performance and correctness.

Both space and time options are exposed to the user through the various Append methods. The following example demonstrates setting such options by appending three records and ensuring space for later records. It only forces a flush to happen upon the very last record write.

// Assume recordData is smaller or equal to 1000bytes 
// Reserve space in the log for three 1000byte records ReservationCollection reservations = recordSequence.CreateReservationCollection();
reservations.Add(1000);
reservations.Add(1000);
reservations.Add(1000);

// The following three appends are guaranteed to succeed if execution 
// flows to here
recordSequence.Append(recordData1,
                                   userSqn,
                                   previousSqn,
                                   RecordAppendOptions.None,    // No flush
                                   reservations);
recordSequence.Append(recordData2,
                                   userSqn,
                                   previousSqn,
                                   RecordAppendOptions.None,    // No flush
                                   reservations);
recordSequence.Append(recordData3,
                                   userSqn,
                                   previousSqn,
                                   RecordAppendOptions.ForceFlush,    // Flush
                                   reservations);

If the RetryAppend property is true, and an Append operation fails because there is no space in the sequence, the record sequence attempts to free space, and retry the operation. The exact implementation of freeing up space varies. For example, the LogRecordSequence class will invoke the CLFS policy engine, as described in the "Freeing Up Space Using the TailPinnedEvent" section below.

Reserving

Reservations can be performed in two ways as shown in the following examples. You can adopt the practices in the samples for robust processing. Notice that this task can only be performed when using the CLFS-based LogRecordSequence class.

Using the ReserveAndAppend Method

ReservationCollection reservations = recordSequence.CreateReservationCollection();
long[] lengthOfUndoRecords = new long[] { 1000 };
recordSequence.ReserveAndAppend(recordData,
                                                     userSqn,
                                                     previousSqn,
                                                     RecordSequenceAppendOptions.None,
                                                     reservations,
                                                     lengthOfUndoRecords);
recordSequence.Append(undoRecordData,    // If necessary …
                                    userSqn,
                                    previousSqn,
                                    RecordSequenceAppendOptions.ForceFlush,
                                    reservations);

Using the Manual Approach

ReservationCollection reservations = recordSequence.CreateReservationCollection();
reservations.Add(lengthOfUndoRecord);
try
{
   recordSequence.Append(recordData, userSqn, previousSqn, RecordAppendOptions.None);
}
catch (Exception)
{
   reservations.Remove(lengthOfUndoRecord);
   throw;
}

recordSequence.Append(undoRecordData, userSqn, previousSqn, RecordAppendOptions.ForceFlush, reservations);

Reading the Log

Reading from the log can occur at any time during an application's lifetime. Depending on the situation, however, it may be necessary to iterate over the records stored in the log in different orderings. In addition to the standard directions specified by Next and Previous for the log, you can also iterate in a user-defined order that is specified when appending each individual record to the sequence. You should also note that Previous is not always sequential in terms of the physical log, since the user can specify the previous record appended by the current thread of execution during an Append operation.

The following example reads a log in sequential forward order, starting from the record with sequence number 'startSqn'.

foreach (LogRecord record in recordSequence.ReadLogRecords(startSqn, LogRecordEnumeratorType.Next))
{
   Stream dataStream = record.Data;
   // Process dataStream, which can be done using deserialization
}

Freeing Up Space Using the TailPinnedEvent

One of the approaches a record sequence can use to free space is firing the TailPinned event. This event indicates that the tail of the sequence (that is, the base sequence number) needs to be moved forward to free up space.

The event can be fired at any time when the record sequence decides that it must free up space, for any reason. For example, the CLFS policy engine may decide to fire the event when it determines that the tails of two log clients sharing the same log file are too far apart. Freeing space can be done by either writing restart areas, or truncating the log and using the AdvanceBaseSequenceNumber method to clear space. The following example demonstrates the second approach.

recordSequence.RetryAppend = true;
recordSequence.TailPinned += new EventHandler<TailPinnedEventArgs>(HandleTailPinned);

void HandleTailPinned(object sender, TailPinnedEventArgs tailPinnedEventArgs)
{
   // tailPinnedEventArgs.TargetSequenceNumber is the target 
   // sequence number to free up space to.  
   // However, this sequence number is not necessarily valid.  We have
   // to use this sequence number as a starting point for finding a
   // valid point within the log to advance toward. You need to
   // identify a record with a sequence number equal to, or greater
   // than TargetSequenceNumber; let's call this 
   // realTargetSequenceNumber. Once found, move the base

   recordSequence.AdvanceBaseSequenceNumber(realTargetSequenceNumber);

}

You can also call the WriteRestartArea method outside of the TailPinned event to free space. A restart area is similar to a checkpoint in other log processing systems. Calling this method indicates that the application considers all prior records before the restart area as fully completed, and usable for future record appends. Similar to any other records, the record written by this method requires actual free space in the log to function.

Multiplexing

When you have multiple applications working together as a unit, you can use the CLFS-based LogRecordSequence class to manipulate a single NTFS file stream. The following example demonstrates how to create a multiplexed log with two streams. Interleaving append and read operations to the log records are performed.

namespace MyMultiplexLog
{
    class MyMultiplexLog
    {
        static void Main(string[] args)
        {
            try
            {
                string myLog = "MyMultiplexLog";
                string logStream1 = "MyMultiplexLog::MyLogStream1";
                string logStream2 = "MyMultiplexLog::MyLogStream2";
                int containerSize = 32 * 1024;

                LogRecordSequence sequence1 = null;
                LogRecordSequence sequence2 = null;

                Console.WriteLine("Creating Multiplexed log with two streams");

                // Create log stream 1
                sequence1 = new LogRecordSequence(logStream1, FileMode.OpenOrCreate, FileAccess.ReadWrite, FileShare.ReadWrite);

                // Log Extents are shared between the two streams. 
                // Add two extents to sequence1.
                sequence1.LogStore.Extents.Add("MyExtent0", containerSize);
                sequence1.LogStore.Extents.Add("MyExtent1");

                // Create log stream 2
                sequence2 = new LogRecordSequence(logStream2, FileMode.OpenOrCreate, FileAccess.ReadWrite, FileShare.ReadWrite);

                // Start Appending in two streams with interleaving appends.

                SequenceNumber previous1 = SequenceNumber.Invalid;
                SequenceNumber previous2 = SequenceNumber.Invalid;

                Console.WriteLine("Appending interleaving records in stream1 and stream2...");
                Console.WriteLine();

                // Append two records in stream1
                previous1 = sequence1.Append(CreateData("MyLogStream1: Hello World!"), SequenceNumber.Invalid, SequenceNumber.Invalid, RecordAppendOptions.ForceFlush);
                previous1 = sequence1.Append(CreateData("MyLogStream1: This is my first Logging App"), previous1, previous1, RecordAppendOptions.ForceFlush);

                // Append two records in stream2
                previous2 = sequence2.Append(CreateData("MyLogStream2: Hello World!"), SequenceNumber.Invalid, SequenceNumber.Invalid, RecordAppendOptions.ForceFlush);
                previous2 = sequence2.Append(CreateData("MyLogStream2: This is my first Logging App"), previous2, previous2, RecordAppendOptions.ForceFlush);

                // Append the third record in stream1
                previous1 = sequence1.Append(CreateData("MyLogStream1: Using LogRecordSequence..."), previous1, previous1, RecordAppendOptions.ForceFlush);
                
                // Append the third record in stream2
                previous2 = sequence2.Append(CreateData("MyLogStream2: Using LogRecordSequence..."), previous2, previous2, RecordAppendOptions.ForceFlush);
                
                // Read log records from stream1 and stream2

                Encoding enc = Encoding.Unicode;
                Console.WriteLine();
                Console.WriteLine("Reading Log Records from stream1...");
                foreach (LogRecord record in sequence1.ReadLogRecords(sequence1.BaseSequenceNumber, LogRecordEnumeratorType.Next))
                {
                    byte[] data = new byte[record.Data.Length];
                    record.Data.Read(data, 0, (int)record.Data.Length);
                    string mystr = enc.GetString(data);
                    Console.WriteLine("    {0}", mystr);
                }

                Console.WriteLine();             
                Console.WriteLine("Reading the log records from stream2...");
                foreach (LogRecord record in sequence2.ReadLogRecords(sequence2.BaseSequenceNumber, LogRecordEnumeratorType.Next))
                {
                    byte[] data = new byte[record.Data.Length];
                    record.Data.Read(data, 0, (int)record.Data.Length);
                    string mystr = enc.GetString(data);
                    Console.WriteLine("    {0}", mystr);
                }

                Console.WriteLine();

                // Cleanup...
                sequence1.Dispose();
                sequence2.Dispose();

                LogStore.Delete(myLog);

                Console.WriteLine("Done...");
            }
            catch (Exception e)
            {
                Console.WriteLine("Exception thrown {0} {1}", e.GetType(), e.Message);
            }
        }

        // Converts the given data to an Array of ArraySegment<byte> 
        public static IList<ArraySegment<byte>> CreateData(string str)
        {
            Encoding enc = Encoding.Unicode;

            byte[] array = enc.GetBytes(str);

            ArraySegment<byte>[] segments = new ArraySegment<byte>[1];
            segments[0] = new ArraySegment<byte>(array);

            return Array.AsReadOnly<ArraySegment<byte>>(segments);
        }

    }
}

Handling exceptions

Applications which use System.IO.Log must be prepared to handle failfasts resulting from the infrastructure. In some scenarios, System.IO.Log does not use exceptions to communicate errors to an application. Instead, exceptions are used primarily for recoverable errors by which an application developer can act upon. However, failfasts will occur when further execution would result in corrupted or potentially unusable log files. When failfasts occur, no other application action is available to rectify the problem, and an application must be prepared to terminate.

For more information on failfast, see FailFast.

Many of the exceptions being thrown by System.IO.Log are from the internal log implementations. The following lists a few of the important exceptions you should be aware of.

SequenceFullException: This exception may or may not be fatal. If AutoGrow is set to true, and there is sufficient room to grow, a SequenceFullException can still be thrown. This is because the auto-grow implementation is inherently an asynchronous, non-atomic operation, and the growth rate cannot be guaranteed to complete all at once. For example, if the growth rate is set to 100 extents, it can take considerable time for all 100 extents to be added to the log store. This may result in this exception being thrown intermittently during this timeframe.
TailPinned Handler: An exception thrown within the TailPinned event is reported to the internal log implementation. This indicates an application's inability to move the base sequence number. A SequenceFullException will be thrown, as the TailPinned event is an application's last chance to prevent log-full conditions.
ReservationNotFoundException: This exception occurs when you try to append records using a reservation collection, and all reservations of the appropriate size are already taken.