Forward/Backward loop performance analysis

Question

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?

Answer 1

Old question and this may not be exact reason in this case but there's a difference when the loops get down to the IL or assembly or whatever your language's lower language happens to be. At a very minimum with the normal for loop you're getting the count value and then doing a comparison of you index variable against that on every loop. In a reverse loop you get the count once as your starting point and then the comparison is always against 0 which is easier to compare and the compilers can even optimize for. Your mileage may vary though and depending on the rest of the code it may be a negligible difference. but if you need every clock cycle reverse loops are awesome.