I've been investigating some performance issues for an Event Viewer application that we have on our development site when I noticed an interesting issue in the algorithm. I then created a simplified test project to test two different algorithms. This program basically retrieves Windows Event Logs using the EventLog
class, and then translates those logs into queryable EventLogItem
entities.
This operation is performed and timed using two different loops. The first (backward) loop starts at the index of the last item in the list, translates the item and then decreases the index. The method is defined like this:
private static void TranslateLogsUsingBackwardLoop()
{
Stopwatch stopwatch = new Stopwatch();
stopwatch.Start();
var originalLogs = EventLog.GetEventLogs();
var translatedLogs = new List<EventLogItem>();
Parallel.ForEach<EventLog>(originalLogs, currentLog =>
{
for (int index = currentLog.Entries.Count - 1; index >= 0; index--)
{
var currentEntry = currentLog.Entries[index];
EventLogItem translatedEntry = new EventLogItem
{
MachineName = currentEntry.MachineName,
LogName = currentLog.LogDisplayName,
CreatedTime = currentEntry.TimeGenerated,
Source = currentEntry.Source,
Message = currentEntry.Message,
Number = currentEntry.Index,
Category = currentEntry.Category,
Type = currentEntry.EntryType,
InstanceID = currentEntry.InstanceId,
User = currentEntry.UserName,
};
lock (translatedLogs)
{
translatedLogs.Add(translatedEntry);
}
}
});
stopwatch.Stop();
Console.WriteLine("{0} logs were translated in {1} using backward loop.", translatedLogs.Count, stopwatch.Elapsed);
}
The second (forward) loop starts at index 0 and increments the index. This method is defined like this:
private static void TranslateLogsUsingForwardLoop()
{
Stopwatch stopwatch = new Stopwatch();
stopwatch.Start();
var originalLogs = EventLog.GetEventLogs();
var translatedLogs = new List<EventLogItem>();
Parallel.ForEach<EventLog>(originalLogs, currentLog =>
{
for (int index = 0; index < currentLog.Entries.Count; index++)
{
var currentEntry = currentLog.Entries[index];
EventLogItem translatedEntry = new EventLogItem
{
MachineName = currentEntry.MachineName,
LogName = currentLog.LogDisplayName,
CreatedTime = currentEntry.TimeGenerated,
Source = currentEntry.Source,
Message = currentEntry.Message,
Number = currentEntry.Index,
Category = currentEntry.Category,
Type = currentEntry.EntryType,
InstanceID = currentEntry.InstanceId,
User = currentEntry.UserName,
};
lock (translatedLogs)
{
translatedLogs.Add(translatedEntry);
}
}
});
stopwatch.Stop();
Console.WriteLine("{0} logs were translated in {1} using forward loop.", translatedLogs.Count, stopwatch.Elapsed);
}
And the main method:
static void Main(string[] args)
{
TranslateLogsUsingForwardLoop();
Console.WriteLine();
Thread.Sleep(2000);
TranslateLogsUsingBackwardLoop();
Console.ReadLine();
}
This is what I get (performed this test several times, and results are almost identical):
Note that the server I tested this on logs to the Event Log every second, that's why the number of translated logs are not the same. So why is the backward loop faster? I initially thought it's because in the backward loop algorithm, currentLog.Entries.Count
is evaluated just once, where as in the forward loop it needs to be calculated and compared against index
on every loop iteration, but then again that doesn't seem right. Any ideas?