README.md

run python3 go.py with xsnap in $PATH

Observe that the 70th iteration is 10x slower than the 1st: ~0.5sec vs ~0.05sec.

go.py

import logging
import re

log = logging.getLogger(__name__)


def main(cwd, check_call, now):
    scripts = cwd.glob('output/deliver-*.js')
    byNum = {deliveryNum(str(s)): s for s in scripts}
    # log.debug('scripts %s', byNum)
    todo = sorted(byNum.items())
    # log.debug('scripts %s', scripts)

    prune(cwd)
    run_deliveries(check_call, todo, now, cwd)


def run_deliveries(check_call, todo, now, cwd):
    # check_call('xsnap -m output/build.js -w state0.xsnap'.split())
    check_call('xsnap -m perf-start.js -w state0.xsnap'.split())

    t0 = now()
    stats = []
    for ix, (num, script) in enumerate(todo):
        t_start = now()
        cmd = ['xsnap', '-m',
               # str(script),
               'perf-iter.js',
               '-r', f'state{num}.xsnap',
               '-w', f'state{num + 1}.xsnap']
        log.info('cmd: %s', ' '.join(cmd))
        check_call(cmd)
        t_finish = now()
        size = (cwd / f'state{num + 1}.xsnap').stat().st_size
        log.info('size %d, dur %s elapsed %s',
                 size, t_finish - t_start, t_finish - t0)
        stats.append((ix, t_finish - t_start, size))
    print('delivery,dur,size')
    for row in stats:
        print(','.join([str(cell) for cell in row]))


def deliveryNum(fname):
    """
    >>> deliveryNum('output/deliver-39.js')
    39
    """
    m = re.match(r'output/deliver-(?P<num>\d+).js', fname)
    return int(m.group('num'))


def prune(cwd):
    old = list(cwd.glob('*.xsnap'))
    log.info('deleting old snapshots: %s', [str(p) for p in old])
    for snap in old:
        snap.unlink()


if __name__ == '__main__':
    def _script_io():
        from pathlib import Path
        from subprocess import check_call
        from datetime import datetime

        logging.basicConfig(level=logging.DEBUG)
        main(cwd=Path('.'), check_call=check_call, now=datetime.now)

    _script_io()

log.txt

Compilation started at Wed Oct 28 13:35:08

python3 go.py
INFO:__main__:deleting old snapshots: ['state52.xsnap', 'state48.xsnap', 'state26.xsnap', 'state66.xsnap', 'state42.xsnap', 'state34.xsnap', 'state38.xsnap', 'state11.xsnap', 'state39.xsnap', 'state27.xsnap', 'state24.xsnap', 'state60.xsnap', 'state64.xsnap', 'state31.xsnap', 'state33.xsnap', 'state14.xsnap', 'state56.xsnap', 'state59.xsnap', 'state40.xsnap', 'state8.xsnap', 'state12.xsnap', 'state50.xsnap', 'state47.xsnap', 'state1.xsnap', 'state53.xsnap', 'state45.xsnap', 'state43.xsnap', 'state13.xsnap', 'state16.xsnap', 'state62.xsnap', 'state23.xsnap', 'state29.xsnap', 'state32.xsnap', 'state18.xsnap', 'state55.xsnap', 'state10.xsnap', 'state51.xsnap', 'state49.xsnap', 'state61.xsnap', 'state21.xsnap', 'state22.xsnap', 'state44.xsnap', 'state35.xsnap', 'state2.xsnap', 'state4.xsnap', 'state20.xsnap', 'state57.xsnap', 'state17.xsnap', 'state3.xsnap', 'state6.xsnap', 'state30.xsnap', 'state28.xsnap', 'state54.xsnap', 'state37.xsnap', 'state0.xsnap', 'state7.xsnap', 'state70.xsnap', 'state36.xsnap', 'state5.xsnap', 'state15.xsnap', 'state68.xsnap', 'state58.xsnap', 'state9.xsnap', 'state46.xsnap', 'state25.xsnap', 'state19.xsnap', 'state69.xsnap', 'state67.xsnap', 'state41.xsnap', 'state63.xsnap', 'state65.xsnap']
INFO:__main__:cmd: xsnap -m perf-iter.js -r state0.xsnap -w state1.xsnap
1
INFO:__main__:size 273007, dur 0:00:00.045594 elapsed 0:00:00.045606
INFO:__main__:cmd: xsnap -m perf-iter.js -r state1.xsnap -w state2.xsnap
INFO:__main__:size 273007, dur 0:00:00.051844 elapsed 0:00:00.097778
INFO:__main__:cmd: xsnap -m perf-iter.js -r state2.xsnap -w state3.xsnap
INFO:__main__:size 273007, dur 0:00:00.058010 elapsed 0:00:00.156088
INFO:__main__:cmd: xsnap -m perf-iter.js -r state3.xsnap -w state4.xsnap
INFO:__main__:size 273007, dur 0:00:00.065220 elapsed 0:00:00.221602
INFO:__main__:cmd: xsnap -m perf-iter.js -r state4.xsnap -w state5.xsnap
INFO:__main__:size 273007, dur 0:00:00.071381 elapsed 0:00:00.293259
INFO:__main__:cmd: xsnap -m perf-iter.js -r state5.xsnap -w state6.xsnap
INFO:__main__:size 273007, dur 0:00:00.079061 elapsed 0:00:00.372602
INFO:__main__:cmd: xsnap -m perf-iter.js -r state6.xsnap -w state7.xsnap
INFO:__main__:size 273007, dur 0:00:00.085034 elapsed 0:00:00.457950
INFO:__main__:cmd: xsnap -m perf-iter.js -r state7.xsnap -w state8.xsnap
INFO:__main__:size 273007, dur 0:00:00.090967 elapsed 0:00:00.549196
INFO:__main__:cmd: xsnap -m perf-iter.js -r state8.xsnap -w state9.xsnap
INFO:__main__:size 273007, dur 0:00:00.098220 elapsed 0:00:00.647697
INFO:__main__:cmd: xsnap -m perf-iter.js -r state9.xsnap -w state10.xsnap
INFO:__main__:size 273007, dur 0:00:00.103694 elapsed 0:00:00.751666
INFO:__main__:cmd: xsnap -m perf-iter.js -r state10.xsnap -w state11.xsnap
INFO:__main__:size 273007, dur 0:00:00.110714 elapsed 0:00:00.862661
INFO:__main__:cmd: xsnap -m perf-iter.js -r state11.xsnap -w state12.xsnap
INFO:__main__:size 273007, dur 0:00:00.117473 elapsed 0:00:00.980444
INFO:__main__:cmd: xsnap -m perf-iter.js -r state12.xsnap -w state13.xsnap
INFO:__main__:size 273007, dur 0:00:00.124891 elapsed 0:00:01.105614
INFO:__main__:cmd: xsnap -m perf-iter.js -r state13.xsnap -w state14.xsnap
INFO:__main__:size 273007, dur 0:00:00.131683 elapsed 0:00:01.237623
INFO:__main__:cmd: xsnap -m perf-iter.js -r state14.xsnap -w state15.xsnap
INFO:__main__:size 273007, dur 0:00:00.136529 elapsed 0:00:01.374431
INFO:__main__:cmd: xsnap -m perf-iter.js -r state15.xsnap -w state16.xsnap
INFO:__main__:size 273007, dur 0:00:00.144684 elapsed 0:00:01.519425
INFO:__main__:cmd: xsnap -m perf-iter.js -r state16.xsnap -w state17.xsnap
INFO:__main__:size 273007, dur 0:00:00.151626 elapsed 0:00:01.671333
INFO:__main__:cmd: xsnap -m perf-iter.js -r state17.xsnap -w state18.xsnap
INFO:__main__:size 273007, dur 0:00:00.159105 elapsed 0:00:01.830742
INFO:__main__:cmd: xsnap -m perf-iter.js -r state18.xsnap -w state19.xsnap
INFO:__main__:size 273007, dur 0:00:00.163147 elapsed 0:00:01.994173
INFO:__main__:cmd: xsnap -m perf-iter.js -r state19.xsnap -w state20.xsnap
INFO:__main__:size 273007, dur 0:00:00.171005 elapsed 0:00:02.165459
INFO:__main__:cmd: xsnap -m perf-iter.js -r state20.xsnap -w state21.xsnap
INFO:__main__:size 273007, dur 0:00:00.176023 elapsed 0:00:02.341757
INFO:__main__:cmd: xsnap -m perf-iter.js -r state21.xsnap -w state22.xsnap
INFO:__main__:size 273007, dur 0:00:00.183982 elapsed 0:00:02.526038
INFO:__main__:cmd: xsnap -m perf-iter.js -r state22.xsnap -w state23.xsnap
INFO:__main__:size 273007, dur 0:00:00.189154 elapsed 0:00:02.715472
INFO:__main__:cmd: xsnap -m perf-iter.js -r state23.xsnap -w state24.xsnap
INFO:__main__:size 273007, dur 0:00:00.194348 elapsed 0:00:02.910104
INFO:__main__:cmd: xsnap -m perf-iter.js -r state24.xsnap -w state25.xsnap
INFO:__main__:size 273007, dur 0:00:00.201597 elapsed 0:00:03.111985
INFO:__main__:cmd: xsnap -m perf-iter.js -r state25.xsnap -w state26.xsnap
INFO:__main__:size 273007, dur 0:00:00.206851 elapsed 0:00:03.319116
INFO:__main__:cmd: xsnap -m perf-iter.js -r state26.xsnap -w state27.xsnap
INFO:__main__:size 273007, dur 0:00:00.212314 elapsed 0:00:03.531724
INFO:__main__:cmd: xsnap -m perf-iter.js -r state27.xsnap -w state28.xsnap
INFO:__main__:size 273007, dur 0:00:00.222489 elapsed 0:00:03.754493
INFO:__main__:cmd: xsnap -m perf-iter.js -r state28.xsnap -w state29.xsnap
INFO:__main__:size 273007, dur 0:00:00.232713 elapsed 0:00:03.987493
INFO:__main__:cmd: xsnap -m perf-iter.js -r state29.xsnap -w state30.xsnap
INFO:__main__:size 273007, dur 0:00:00.232354 elapsed 0:00:04.220130
INFO:__main__:cmd: xsnap -m perf-iter.js -r state30.xsnap -w state31.xsnap
INFO:__main__:size 273007, dur 0:00:00.237640 elapsed 0:00:04.458055
INFO:__main__:cmd: xsnap -m perf-iter.js -r state31.xsnap -w state32.xsnap
INFO:__main__:size 273007, dur 0:00:00.241995 elapsed 0:00:04.700326
INFO:__main__:cmd: xsnap -m perf-iter.js -r state32.xsnap -w state33.xsnap
INFO:__main__:size 273007, dur 0:00:00.248128 elapsed 0:00:04.948752
INFO:__main__:cmd: xsnap -m perf-iter.js -r state33.xsnap -w state34.xsnap
INFO:__main__:size 273007, dur 0:00:00.255296 elapsed 0:00:05.204360
INFO:__main__:cmd: xsnap -m perf-iter.js -r state34.xsnap -w state35.xsnap
INFO:__main__:size 273007, dur 0:00:00.262146 elapsed 0:00:05.466784
INFO:__main__:cmd: xsnap -m perf-iter.js -r state35.xsnap -w state36.xsnap
INFO:__main__:size 273007, dur 0:00:00.266709 elapsed 0:00:05.733818
INFO:__main__:cmd: xsnap -m perf-iter.js -r state36.xsnap -w state37.xsnap
INFO:__main__:size 273007, dur 0:00:00.272133 elapsed 0:00:06.006243
INFO:__main__:cmd: xsnap -m perf-iter.js -r state37.xsnap -w state38.xsnap
INFO:__main__:size 273007, dur 0:00:00.280232 elapsed 0:00:06.286769
INFO:__main__:cmd: xsnap -m perf-iter.js -r state38.xsnap -w state39.xsnap
INFO:__main__:size 273007, dur 0:00:00.283122 elapsed 0:00:06.570174
INFO:__main__:cmd: xsnap -m perf-iter.js -r state39.xsnap -w state40.xsnap
INFO:__main__:size 273007, dur 0:00:00.290397 elapsed 0:00:06.860854
INFO:__main__:cmd: xsnap -m perf-iter.js -r state40.xsnap -w state41.xsnap
INFO:__main__:size 273007, dur 0:00:00.295584 elapsed 0:00:07.156731
INFO:__main__:cmd: xsnap -m perf-iter.js -r state41.xsnap -w state42.xsnap
INFO:__main__:size 273007, dur 0:00:00.303162 elapsed 0:00:07.460228
INFO:__main__:cmd: xsnap -m perf-iter.js -r state42.xsnap -w state43.xsnap
INFO:__main__:size 273007, dur 0:00:00.308350 elapsed 0:00:07.768870
INFO:__main__:cmd: xsnap -m perf-iter.js -r state43.xsnap -w state44.xsnap
INFO:__main__:size 273007, dur 0:00:00.318331 elapsed 0:00:08.087567
INFO:__main__:cmd: xsnap -m perf-iter.js -r state44.xsnap -w state45.xsnap
INFO:__main__:size 273007, dur 0:00:00.322197 elapsed 0:00:08.410039
INFO:__main__:cmd: xsnap -m perf-iter.js -r state45.xsnap -w state46.xsnap
INFO:__main__:size 273007, dur 0:00:00.329291 elapsed 0:00:08.739641
INFO:__main__:cmd: xsnap -m perf-iter.js -r state46.xsnap -w state47.xsnap
INFO:__main__:size 273007, dur 0:00:00.334283 elapsed 0:00:09.074252
INFO:__main__:cmd: xsnap -m perf-iter.js -r state47.xsnap -w state48.xsnap
INFO:__main__:size 273007, dur 0:00:00.338946 elapsed 0:00:09.413493
INFO:__main__:cmd: xsnap -m perf-iter.js -r state48.xsnap -w state49.xsnap
INFO:__main__:size 273007, dur 0:00:00.347936 elapsed 0:00:09.761723
INFO:__main__:cmd: xsnap -m perf-iter.js -r state49.xsnap -w state50.xsnap
INFO:__main__:size 273007, dur 0:00:00.352610 elapsed 0:00:10.114620
INFO:__main__:cmd: xsnap -m perf-iter.js -r state50.xsnap -w state51.xsnap
INFO:__main__:size 273007, dur 0:00:00.358952 elapsed 0:00:10.473849
INFO:__main__:cmd: xsnap -m perf-iter.js -r state51.xsnap -w state52.xsnap
INFO:__main__:size 273007, dur 0:00:00.365848 elapsed 0:00:10.839973
INFO:__main__:cmd: xsnap -m perf-iter.js -r state52.xsnap -w state53.xsnap
INFO:__main__:size 273007, dur 0:00:00.374274 elapsed 0:00:11.214528
INFO:__main__:cmd: xsnap -m perf-iter.js -r state53.xsnap -w state54.xsnap
INFO:__main__:size 273007, dur 0:00:00.377643 elapsed 0:00:11.592449
INFO:__main__:cmd: xsnap -m perf-iter.js -r state54.xsnap -w state55.xsnap
INFO:__main__:size 273007, dur 0:00:00.384736 elapsed 0:00:11.977461
INFO:__main__:cmd: xsnap -m perf-iter.js -r state55.xsnap -w state56.xsnap
INFO:__main__:size 273007, dur 0:00:00.391998 elapsed 0:00:12.369758
INFO:__main__:cmd: xsnap -m perf-iter.js -r state56.xsnap -w state57.xsnap
INFO:__main__:size 273007, dur 0:00:00.396502 elapsed 0:00:12.766587
INFO:__main__:cmd: xsnap -m perf-iter.js -r state57.xsnap -w state58.xsnap
INFO:__main__:size 273007, dur 0:00:00.403006 elapsed 0:00:13.169891
INFO:__main__:cmd: xsnap -m perf-iter.js -r state58.xsnap -w state59.xsnap
INFO:__main__:size 273007, dur 0:00:00.408891 elapsed 0:00:13.579059
INFO:__main__:cmd: xsnap -m perf-iter.js -r state59.xsnap -w state60.xsnap
INFO:__main__:size 273007, dur 0:00:00.414686 elapsed 0:00:13.994038
INFO:__main__:cmd: xsnap -m perf-iter.js -r state60.xsnap -w state61.xsnap
INFO:__main__:size 273007, dur 0:00:00.422727 elapsed 0:00:14.417044
INFO:__main__:cmd: xsnap -m perf-iter.js -r state61.xsnap -w state62.xsnap
INFO:__main__:size 273007, dur 0:00:00.424785 elapsed 0:00:14.842106
INFO:__main__:cmd: xsnap -m perf-iter.js -r state62.xsnap -w state63.xsnap
INFO:__main__:size 273007, dur 0:00:00.434585 elapsed 0:00:15.276992
INFO:__main__:cmd: xsnap -m perf-iter.js -r state63.xsnap -w state64.xsnap
INFO:__main__:size 273007, dur 0:00:00.439852 elapsed 0:00:15.717126
INFO:__main__:cmd: xsnap -m perf-iter.js -r state64.xsnap -w state65.xsnap
INFO:__main__:size 273007, dur 0:00:00.448109 elapsed 0:00:16.165511
INFO:__main__:cmd: xsnap -m perf-iter.js -r state65.xsnap -w state66.xsnap
INFO:__main__:size 273007, dur 0:00:00.452550 elapsed 0:00:16.618355
INFO:__main__:cmd: xsnap -m perf-iter.js -r state66.xsnap -w state67.xsnap
INFO:__main__:size 273007, dur 0:00:00.457574 elapsed 0:00:17.076205
INFO:__main__:cmd: xsnap -m perf-iter.js -r state67.xsnap -w state68.xsnap
INFO:__main__:size 273007, dur 0:00:00.465621 elapsed 0:00:17.542104
INFO:__main__:cmd: xsnap -m perf-iter.js -r state68.xsnap -w state69.xsnap
INFO:__main__:size 273007, dur 0:00:00.471602 elapsed 0:00:18.013986
INFO:__main__:cmd: xsnap -m perf-iter.js -r state69.xsnap -w state70.xsnap
INFO:__main__:size 273007, dur 0:00:00.478182 elapsed 0:00:18.492445
delivery,dur,size
0,0:00:00.045594,273007
1,0:00:00.051844,273007
...

perf-iter.js

ix += 1;
print(ix)

perf-start.js

globalThis.ix = 0;

stats.csv