Add frame timing information

[jdm]

jdm@9e3ddc5 is an example of timing information that I added in a branch. I added a cargo feature in jdm@ab0a653 that avoided all of the precise_time_ns calls when profiling was not desired.

[jdm]

jdm/servo@14cd0e7 was the equivalent changes in Servo, along with jdm/servo@1de0d5d.

[jdm]

We'll want to add timing data in a way that will let us answer the following questions:

• what is the most common frame time?
• what is the slowest part of the frame pipeline?
• when a frame takes longer than average, how are the various sub-times affected?
• proportionally, how long is each part of the frame pipeline? is that consistent across frames?

[jdm]

We will also want the timing data to be possible to meaningfully compare between different runs, to easily determine if we're improving or not.

[jdm]

This is the postprocessing script I used for the commits I linked earlier. This script is good at answering questions about the most common times for part of the frame pipeline, but doesn't include overall frame duration and can't answer questions about the other parts of the frame pipeline when one of the parts takes longer than usual.

import sys

lines = []
buckets = {}
with open(sys.argv[1]) as f:
    for line in f.readlines():
        if not line.startswith("!!!"):
            continue
        parts = line.split(' ')
        value = float(parts[-1][:-3])
        name = ' '.join(parts[1:-1])
        if name not in buckets:
            buckets[name] = []
        buckets[name] += [value]

def mean(numbers):
    return float(sum(numbers)) / max(len(numbers), 1)

def histo(numbers):
    buckets = [1, 2, 4, 8, 16, 32, 32]
    bucket_values = [0, 0, 0, 0, 0, 0, 0]
    for number in numbers:
        for (i, max_val) in enumerate(buckets):
            if number < max_val:
                bucket_values[i] += 1
                break
        else:
            bucket_values[-1] += 1
    return zip(buckets, bucket_values)

buckets["raf receive"].pop(0) # First timing information compares against 0 and is invalid

print("Name\t\tmin\t\tmax\t\tmean")
for (name, values) in buckets.iteritems():
    print("%s\t%f\t%f\t%f" % (name, min(values), max(values), mean(values)))
    histogram = histo(values)
    for (i, (bucket, count)) in enumerate(histogram):
        print("%s%d%sms: %d" % ("<" if i != len(histogram) - 1 else "", bucket, "+" if i == len(histogram) - 1 else "", count))
    print

[jdm]

Another feature that would be helpful - ignoring timing information that falls outside of a particular window. This would help provide insight into why the FPS falls over time if the scene doesn't change.

[Manishearth]

import sys
import re
REGEX = re.compile("WEBXR PROFILING \[(.*)\]:\s*([0-9.]+)ms")
lines = []
buckets = {}
with open(sys.argv[1]) as f:
    for line in f.readlines():
        if not line.startswith("WEBXR PROFILING"):
            continue
        result = REGEX.match(line)
        name = result.group(1)
        value = float(result.group(2))
        if name not in buckets:
            buckets[name] = []
        buckets[name] += [value]

def mean(numbers):
    return float(sum(numbers)) / max(len(numbers), 1)

def histo(numbers):
    buckets = [1, 2, 4, 8, 16, 32, 32]
    bucket_values = [0, 0, 0, 0, 0, 0, 0]
    for number in numbers:
        for (i, max_val) in enumerate(buckets):
            if number < max_val:
                bucket_values[i] += 1
                break
        else:
            bucket_values[-1] += 1
    return zip(buckets, bucket_values)

buckets["raf receive"].pop(0) # First timing information compares against 0 and is invalid

print("Name\t\tmin\t\tmax\t\tmean")
for (name, values) in buckets.iteritems():
    print("%s\t%f\t%f\t%f" % (name, min(values), max(values), mean(values)))
    histogram = histo(values)
    for (i, (bucket, count)) in enumerate(histogram):
        print("%s%d%sms: %d" % ("<" if i != len(histogram) - 1 else "", bucket, "+" if i == len(histogram) - 1 else "", count))
    print

[Manishearth]

Updated script, it can now generate a csv for graphing as well:

import sys
import re
REGEX = re.compile("WEBXR PROFILING \[(.*)\]:\s*([0-9.]+)ms")
lines = []
buckets = {}
with open(sys.argv[1]) as f:
    for line in f.readlines():
        if not line.startswith("WEBXR PROFILING"):
            continue
        result = REGEX.match(line)
        name = result.group(1)
        value = float(result.group(2))
        if name not in buckets:
            buckets[name] = []
        buckets[name] += [value]

def mean(numbers):
    return float(sum(numbers)) / max(len(numbers), 1)

def histo(numbers):
    buckets = [1, 2, 4, 8, 16, 32, 32]
    bucket_values = [0, 0, 0, 0, 0, 0, 0]
    for number in numbers:
        for (i, max_val) in enumerate(buckets):
            if number < max_val:
                bucket_values[i] += 1
                break
        else:
            bucket_values[-1] += 1
    return zip(buckets, bucket_values)

buckets["raf receive"].pop(0) # First timing information compares against 0 and is invalid

if sys.argv[2] == "csv":
    l = min(len(values) for (_, values) in buckets.iteritems())
    print(",".join([name for name in buckets]))
    for i in range(l):
        print(",".join([str(buckets[name][i]) for name in buckets]))

else:
    print("Name\t\tmin\t\tmax\t\tmean")
    for (name, values) in buckets.iteritems():
        print("%s\t%f\t%f\t%f" % (name, min(values), max(values), mean(values)))
        histogram = histo(values)
        for (i, (bucket, count)) in enumerate(histogram):
            print("%s%d%sms: %d" % ("<" if i != len(histogram) - 1 else "", bucket, "+" if i == len(histogram) - 1 else "", count))
        print

[Manishearth]

Annoyingly the framerate is down to 30 when i'm doing these measurements, so I can't quite grab the situation where it started out fast and went down over a period of 20ish seconds

[jdm]

It would be worth checking if memory usage stays constant as the framerate drops, to rule out one possibility.