Iterating over thousands of objects to generate html

Question

Currently I am working on a profiling unit that does not require stack traces to preserve the call stack, and can return the performance in a html format.

All though the logging in itself is fairly fast (negligible overhead on each function), the visualisation of the information is not.

With a little over 25k objects generated in a development environment it takes roughly 38 seconds since the addition of parallel loops. As before these it would take >5 minutes to compose the resulting data. In a testing environment this can grow up to a 20x this size.

Previously the data would be stored for an hour. To reduce the collective memory and performance stamps this got reduced to 20 minutes (1200seconds)

The code to generate the HTML is fairly simple in itself, The function DataToLines seems to be the culprit.

Public void ProfilingResult()
{
  /* several lines of html generation */ <0.0001ms
  ProfileData data = ApplicationLogging.GetProfilerData(); // < 0.012ms
  // Root is a predefined ProfileData, interval contains the ints 120 and 1200. amount of seconds of data to visualize. 
  string[][][] dataLines = DataToLines(data , 0, "root", intervals); // bottleneck
  /* Generate html based on these lines * // 0.031ms
}

Taking a look at this function I found it to be fairly slow as it takes up about 3-5 seconds. But the real culprit clearly is getProfilingStats. Taking a rough 32 seconds.

private string[][][] DataToLines(ProfileData data, int indent, string parentGuid, int[] intervals)
{
    List<string[][]> lines = new List<string[][]>();
    Parallel.ForEach(profiledata.Children, (child) =>
    {
        string guid = GUID.NewGuid().ToString();
        // The real, real culprit
        ProfileStats[] stats = child.Value.getProfilingStats(intervals);
        for(int i = 0; i < stats.Length; i++)
        {
          line[i][0] = parentGuid;
          /* another 13 values being assigned in a similar way.  */
        }
        lines.Add(line);
        // Here we recurse to maintain the call stack order
        if(child.Value.Children.Count > 0)
            lines.AddRange(DataToLines(child.Value, indentation + 1, guid, intervals);
    });
  return lines.ToArray();
}

getProfilingStats iterates over all the logs of a particular thread of functional calls, and obtains the shortest, highest and average execution times. Meaning, that this will iterate over a mere 25k objects.

    public ProfileStats[] getProfilingStats(int[] intervals)
    {
        ProfileStats[] stats = new ProfileStats[intervals.Length];

        for (int i = 0; i < intervals.Length; i++)
            stats[i] = new ProfileStats();

        int now = (Int32)(DateTime.UtcNow.Subtract(new DateTime(1970, 1, 1))).TotalSeconds;

        if (queue.Count == 0)
            return stats;

        long[] totalDurations = new long[intervals.Length];

        Parallel.ForEach(queue, (profilingRequest) =>
        {
            for (int i = 0; i < intervals.Length; i++)
            {
                if (now - profilingRequest.timestamp < intervals[i])
                {
                    if (stats[i].queueCount == 0)
                        stats[i].minDuration = stats[i].maxDuration = profilingRequest.duration;
                    else if (profilingRequest.duration < stats[i].minDuration)
                            stats[i].minDuration = profilingRequest.duration;
                    else if (profilingRequest.duration > stats[i].maxDuration)
                        stats[i].maxDuration = profilingRequest.duration;

                    stats[i].queueCount++;
                    totalDurations[i] += profilingRequest.duration;
                    if (profilingRequest.containsExceptions)
                        stats[i].exceptionsCount++;
                }
            }
        });

        for (int i = 0; i < intervals.Length; i++)
        {
            if (stats[i].queueCount > 0)
            {
                stats[i].averageDuration = totalDurations[i] / stats[i].queueCount;
            }
        }
        return stats;
    }

The ProfileData looks as following

public class ProfileData
{
    internal struct ProfilingRequest
    {
        public int timestamp;
        public long duration;
        public bool containsExceptions;

        public ProfilingRequest(int timestamp, long duration, bool containsExceptions)
        {
            this.timestamp = timestamp;
            this.duration = duration;
            this.containsExceptions = containsExceptions;
        }
    }

    public string name { get; private set; }
    public int cleanInterval { get; private set; }
    private ConcurrentQueue<ProfilingRequest> queue = new ConcurrentQueue<ProfilingRequest>();

    public Dictionary<string, ProfileData> Children { get; private set; }
    public ProfileData parent { get; private set; }

    public ProfileData(string name, int cleanInterval)
    {
        Children = new Dictionary<string, ProfileData>();
        parent = null;
        this.name = name;
        this.cleanInterval = cleanInterval;
    }

    public ProfileData GetChild(string groupName)
    {
        lock (Children)
        {
            if (!Children.ContainsKey(groupName))
            {
                ProfileData child = new ProfileData(groupName, cleanInterval);
                child.parent = this;
                Children.Add(groupName, child);
            }
            return Children[groupName];
        }
    }

    public void Clean(int timestamp)
    {
        ProfilingRequest pr;
        while (queue.Count > 0)
        {
            if (queue.TryPeek(out pr))
            {
                if (timestamp - pr.timestamp > cleanInterval)
                    queue.TryDequeue(out pr);
                else
                    break;
            }
        }
    }

Answer 1

In DataToLines, we have this

List<string[][]> lines = new List<string[][]>();
Parallel.ForEach(profiledata.Children, (child) =>
{
    ...
    lines.Add(line);
    ...
});

List<T>.Add is not guaranteed to be thread safe, so calling it in Parallel.ForEach is problematic.

To illustrate the problem, try running the following code

var count = 10000;
var lines = new List<int>();
Parallel.ForEach(Enumerable.Range(0, count), lines.Add);
Debug.Assert(count == lines.Count, $"Expected {count}, actual {lines.Count}");

The output I got when running this was Fail: Expected 10000, actual 9823.

Answer 2

Having not done much with Parallel.ForEach I nevertheless would like to suggest to change it like so

    Parallel.ForEach(queue, (profilingRequest) =>
    {

        var currentTime = now - profilingRequest.timestamp;

        for (int i = 0; i < intervals.Length; i++)
        {

            if (currentTime < intervals[i])
            {

                var currentStat = stats[i];

                if (currentStat.queueCount == 0)
                {
                    currentStat.minDuration = currentStat.maxDuration = profilingRequest.duration;
                }
                else if (profilingRequest.duration < currentStat.minDuration)
                {
                        currentStat.minDuration = profilingRequest.duration;
                }
                else if (profilingRequest.duration > currentStat.maxDuration)
                {
                    currentStat.maxDuration = profilingRequest.duration;
                }
                currentStat.queueCount++;
                totalDurations[i] += profilingRequest.duration;

                if (profilingRequest.containsExceptions)
                {
                    currentStat.exceptionsCount++;
                }
            }
        }
    });  

By calculating the currentTime outside of the loop the access of the profilingRequest is limizted to one time and it isn't calculated for each iteration of the loop.

By using var currentStat = stats[i]; (if the compiler doesn't do this internally) the stats item doesen't need to be accessed by its index that often.

I wonder what should happen if profilingRequest.duration == currentStat.maxDuration this seems to be a forgotten edge case.

Like you see I have added braces although they might be optional. They won't slow down the execution but your code gets better readable and less error prone.

---

Another point to improve would be this

public ProfileData GetChild(string groupName)
{
    lock (Children)
    {
        if (!Children.ContainsKey(groupName))
        {
            ProfileData child = new ProfileData(groupName, cleanInterval);
            child.parent = this;
            Children.Add(groupName, child);
        }
        return Children[groupName];
    }
}  

If you need a value from a dictionary and you aren't sure if it is in the dictionary you should use TryGetValue() because it is faster. See also my answer here : Message bus in C#

That beeing said, changing the former method to

public ProfileData GetChild(string groupName)
{
    lock (Children)
    {
        ProfileData child;
        if(Children.TryGetValue(groupName, out child))
        {
            return child;
        }

        child = new ProfileData(groupName, cleanInterval);
        child.parent = this;
        Children.Add(groupName, child);

        return child;
    }
}   

should improve the speed.