Subprocess profile pt. 4

README.md

Continuation of Subprocess Profiling pt. 1.

Tested on play-with-docker, for consistent results across multiple collaborators. Results vary between runs, so I'm attaching two runs below.

$ python subprocess_profile.py --iterations=10000 --size=100 --plot
                   Read: 1,929.443 MB/s
                  Write: 1,668.109 MB/s
             Total time: 1.179 s
             Write Time: |- 0.585 s
              Wait Time: |- 0.594 s
             Wait/Write: |- 1 / 1.01
             Iterations: 10,000
 Avarage roundtrip time: 0.118 ms/request
     Min roundtrip time: 0.049 ms/request
     Max roundtrip time: 0.748 ms/request
   Delta roundtrip time: 0.699 ms
                   Size: 102,400 B
            Buffer size: 32,768 B
                  Peaks: 26

subprocess_profile.py

import os
import sys
import time
import argparse
import subprocess
from collections import defaultdict

KB = 1 << 10
MB = 1 << 20

parser = argparse.ArgumentParser()
parser.add_argument("--iterations", default=10000, type=int)
parser.add_argument("--size", default=64, type=int)
parser.add_argument("--bufsize", default=64, type=int)
parser.add_argument("--buffered", action="store_true")
parser.add_argument("--plot", action="store_true")
opt = parser.parse_args()

bufsize = opt.bufsize * KB
iterations = opt.iterations
size = opt.size * KB
data = b"0" * size
totalsize = size * iterations
timings = defaultdict(list)


if not os.getenv("CHILD"):
    args = [sys.executable, "-u", __file__]

    if opt.buffered:
        args = [sys.executable, __file__]

    popen = subprocess.Popen(
        args + sys.argv[1:],
        env=dict(os.environ, **{"CHILD": "1"}),
        stdin=subprocess.PIPE,
        stdout=subprocess.PIPE,
        bufsize=bufsize,
    )

    totaltime = time.clock()
    writetime = 0  # writing to child
    waittime = 0  # waiting for child to reply
    roundtime = 0  # writing + reading from child

    for i in range(iterations):
        t0 = time.clock()
        popen.stdin.write(data)
        popen.stdin.flush()
        t1 = time.clock()

        response = popen.stdout.read(size)
        t2 = time.clock()

        write_duration = t1 - t0
        round_duration = t2 - t0
        wait_duration = t2 - t1

        writetime += write_duration
        waittime += wait_duration
        roundtime += round_duration

        timings["write"].append(write_duration)
        timings["roundtrip"].append(round_duration)
        timings["wait"].append(wait_duration)

    totaltime -= time.clock()
    totaltime = abs(totaltime)

    # Throws an IO error in the child, breaking the while-loop
    popen.stdin.close()
    popen.stdout.close()

    popen.wait()

    mbps = float(totalsize) / MB / writetime
    avgtime = (sum(timings["roundtrip"][1:]) / iterations) * 1000
    mintime = min(timings["roundtrip"][1:]) * 1000
    maxtime = max(timings["roundtrip"][1:]) * 1000
    deltime = maxtime - mintime
    timeratio = waittime / writetime

    # Detect outliers, "peaks"
    peaks = len([v for v in timings["roundtrip"] if (v * 1000 / 2) > avgtime])

    print("""\
                  Write: {mbps:,.3f} MB/s
             Total time: {roundtime:,.3f} s
             Write Time: |- {writetime:,.3f} s
              Wait Time: |- {waittime:,.3f} s
             Wait/Write: |- 1 / {timeratio:.2f}
             Iterations: {iterations:,}
 Avarage roundtrip time: {avgtime:.3f} ms/request
     Min roundtrip time: {mintime:.3f} ms/request
     Max roundtrip time: {maxtime:.3f} ms/request
   Delta roundtrip time: {deltime:.3f} ms
                   Size: {size:,} B
            Buffer size: {bufsize:,} B
                  Peaks: {peaks:}\
""".format(**locals()))

    if opt.plot:
        import pygal
        fname = os.path.join(os.getcwd(), "strict.svg")
        print("Plotting to %s.." % fname)

        # = write + wait
        timings.pop("roundtrip")

        plot = pygal.Line(width=2000, height=500)
        plot.title = "Time per iteration"
        for name, values in timings.items():
            values = map(lambda v: v * 1000, values)  # ms
            plot.add(name + " (ms)", values[1:], show_dots=False)

        plot.render_to_file(fname)


else:
    readtime = 0

    while True:
        response = sys.stdin.read(size)

        try:
            t0 = time.clock()
            sys.stdout.write(data)
            sys.stdout.flush()
            t1 = time.clock()
        except IOError:
            break

        readtime += t1 - t0

    assert readtime > 0, "Too fast"
    rate = float(totalsize) / MB / readtime
    sys.stderr.write("                   Read: {mbps:,.3f} MB/s\n".format(
        mbps=rate
    ))

xplot1.svg