Ely Office: six offline-first desktop apps in Rust and GPUI

ElyDoc, ElyTable, ElyShow (LibreOfficeKit), ElyPDF (MuPDF), ElyTree (Git),
ElyMark (Milkdown and CodeMirror in CEF). ElyMail and ElyAgent follow.

tests/perf/bench.py

@@ -0,0 +1,391 @@
+#!/usr/bin/env python3
+"""PERF-01 to PERF-08 on release builds, written as a record."""
+
+import argparse
+import datetime
+import hashlib
+import json
+import os
+import platform
+import re
+import shutil
+import subprocess
+import sys
+import tempfile
+import time
+
+import samples
+
+ROOT = os.path.abspath(os.path.join(os.path.dirname(__file__), "..", ".."))
+APPS = {"ely-doc": "ElyDoc", "ely-table": "ElyTable", "ely-show": "ElyShow",
+        "ely-pdf": "ElyPDF", "ely-tree": "ElyTree", "ely-mark": "ElyMark"}
+TARGETS = {"PERF-01": 3000, "PERF-02": 100, "PERF-03": 5000, "PERF-04": 5000,
+           "PERF-05": 3000, "PERF-06": 1000, "PERF-07": 2000}
+
+
+def sh(*args, **kw):
+    return subprocess.run(args, check=True, capture_output=True, text=True, **kw).stdout
+
+
+def tools(folder):
+    for tool in ["ax-values", "ax-press", "click"]:
+        sh("swiftc", "-O", "-o", os.path.join(folder, tool), os.path.join(ROOT, "tests", "scripts", tool + ".swift"))
+
+
+class App:
+    """A release app run, timed from spawn, read via log."""
+
+    def __init__(self, slug, home, args=(), smoke="hold"):
+        self.slug, self.home, self.tools = slug, home, os.path.dirname(home)
+        self.log = os.path.join(home, "Library", "Application Support", "ElyOffice", slug, "ely.log")
+        # Starts may trim the log; each run starts fresh.
+        if os.path.exists(self.log):
+            os.remove(self.log)
+        self.seen = 0
+        env = dict(os.environ, HOME=home, ELY_SMOKE=smoke, ELY_LOCALE="en", ELY_NO_DIALOG="1",
+                   ELY_LOG="debug", ELY_STALLS="1")
+        self.start = time.monotonic()
+        self.process = subprocess.Popen([os.path.join(ROOT, "target", "release", slug), *args], env=env,
+                                        stdout=subprocess.PIPE, stderr=subprocess.DEVNULL, text=True)
+
+    def lines(self):
+        if not os.path.exists(self.log):
+            return []
+        with open(self.log, errors="replace") as log:
+            log.seek(self.seen)
+            return log.read().splitlines()
+
+    def wait(self, pattern, after=None, timeout=60):
+        """Milliseconds from spawn until a line matches, past `after`."""
+        called = time.monotonic()
+        while time.monotonic() - called < timeout:
+            lines = self.lines()
+            if after is not None:
+                at = next((i for i, line in enumerate(lines) if re.search(after, line)), None)
+                lines = [] if at is None else lines[at + 1:]
+            if any(re.search(pattern, line) for line in lines):
+                return (time.monotonic() - self.start) * 1000
+            time.sleep(0.01)
+        tail = "\n".join(self.lines()[-12:])
+        raise RuntimeError(f"{self.slug}: no {pattern!r} in {timeout} s; the log ends:\n{tail}")
+
+    def ready(self, timeout=60):
+        """ELY_SMOKE=1: milliseconds until the first frame."""
+        out, _ = self.process.communicate(timeout=timeout)
+        took = (time.monotonic() - self.start) * 1000
+        if f"ready {APPS[self.slug]}" not in out:
+            raise RuntimeError(f"{self.slug} did not report ready: {out!r}")
+        # Its engine may still be starting; the next run waits.
+        for _ in range(300):
+            if subprocess.run(["pgrep", "-f", self.home], capture_output=True).returncode != 0:
+                break
+            time.sleep(0.05)
+        return took
+
+    def family(self):
+        out = sh("ps", "-A", "-o", "pid=,ppid=,rss=")
+        rows = [tuple(map(int, line.split())) for line in out.splitlines()]
+        ours, grew = {self.process.pid}, True
+        while grew:
+            grew = False
+            for pid, ppid, _ in rows:
+                if ppid in ours and pid not in ours:
+                    ours.add(pid)
+                    grew = True
+        return ours, sum(rss for pid, _, rss in rows if pid in ours)
+
+    def memory_mb(self):
+        return self.family()[1] / 1024
+
+    def files(self):
+        ours, _ = self.family()
+        return sum(len(sh("lsof", "-p", str(pid)).splitlines()) for pid in ours)
+
+    def front(self):
+        sh("osascript", "-e", f'tell application "System Events" to set frontmost of (first process whose unix id is {self.process.pid}) to true')
+        time.sleep(0.5)
+
+    def ax(self):
+        return sh(os.path.join(self.tools, "ax-values"), str(self.process.pid))
+
+    def stop(self):
+        ours, _ = self.family()
+        for pid in ours:
+            try:
+                os.kill(pid, 9)
+            except ProcessLookupError:
+                pass
+        self.process.wait()
+
+
+def keys(script):
+    sh("osascript", "-e", 'tell application "System Events"', "-e", script, "-e", "end tell")
+
+
+def percentile(values, p):
+    ordered = sorted(values)
+    return ordered[min(len(ordered) - 1, int(len(ordered) * p))]
+
+
+# A page that failed to paint voids the run.
+PAINT_FAILED = r"lok: tile \(.*\) failed|pdf: drawing a page failed"
+
+
+def opened(slug, home, sample, marks, runs):
+    """Spawn with a file until `marks` all appear, in order."""
+    times, memory = [], []
+    for _ in range(runs):
+        app = App(slug, home, [sample])
+        try:
+            after = None
+            for mark in marks:
+                took = app.wait(mark, after)
+                after = mark
+            failed = [line for line in app.lines() if re.search(PAINT_FAILED, line)]
+            if failed:
+                raise RuntimeError(f"{slug}: {sample} did not paint: {failed[0]}")
+            times.append(took)
+            memory.append(app.memory_mb())
+        finally:
+            app.stop()
+    return times, memory
+
+
+def laid_out(work, sample, pages):
+    """The kernel lays `sample` out to exactly `pages` pages."""
+    app = App("ely-doc", os.path.join(work, "home-pages"), [sample])
+    try:
+        app.wait(rf"lok: {pages} pages$", timeout=120)
+        time.sleep(3)
+        counts = [line for line in app.lines() if re.search(r"lok: \d+ pages$", line)]
+        if not counts[-1].endswith(f" {pages} pages"):
+            raise RuntimeError(f"{sample} lays out as {counts[-1]}, not {pages} pages")
+    finally:
+        app.stop()
+
+
+def perf01(work, runs):
+    rows = []
+    for slug in APPS:
+        home = os.path.join(work, "home-" + slug)
+        first = App(slug, home, smoke="1").ready()
+        daily = [App(slug, home, smoke="1").ready() for _ in range(runs)]
+        rows.append((slug, first, daily))
+    return rows
+
+
+def perf02(work, runs):
+    """Key to new tile in ElyDoc, and main-thread stalls meanwhile."""
+    app = App("ely-doc", os.path.join(work, "home-typing"))
+    try:
+        app.wait("opened Untitled")
+        app.front()
+        tick = r"lok: edit to tile (\d+) ms"
+        for n in range(runs):
+            keys('keystroke "x"')
+            # Each key must show; a lost one fails the run.
+            for _ in range(500):
+                if sum(1 for line in app.lines() if re.search(tick, line)) > n:
+                    break
+                time.sleep(0.01)
+            else:
+                raise RuntimeError(f"ely-doc: key {n + 1} of {runs} never reached a tile")
+            time.sleep(0.15)
+        lines = app.lines()
+    finally:
+        app.stop()
+    ticks = [int(m.group(1)) for line in lines if (m := re.search(tick, line))]
+    if len(ticks) != runs:
+        raise RuntimeError(f"ely-doc: {runs} keys gave {len(ticks)} timings")
+    stalls = [int(m.group(1)) for line in lines if (m := re.search(r"main thread was busy (\d+) ms", line))]
+    return ticks, stalls
+
+
+def perf06(work, repo, runs):
+    """History first screen, then a common query's first results."""
+    home = os.path.join(work, "home-ely-tree")
+    first, found = [], []
+    for _ in range(runs):
+        app = App("ely-tree", home, [repo])
+        try:
+            app.wait("tree: opened")
+            app.front()
+            pressed = (time.monotonic() - app.start) * 1000
+            sh(os.path.join(work, "ax-press"), str(app.process.pid), "History")
+            first.append(app.wait(r"history shows \d+ commits, searched false") - pressed)
+            field = next(line for line in app.ax().splitlines() if line.startswith("AXTextField"))
+            x, y = field.rsplit("at=", 1)[1].split(",")
+            sh(os.path.join(work, "click"), x, y)
+            keys('keystroke "part 42"')
+            asked = (time.monotonic() - app.start) * 1000
+            keys("key code 36")
+            found.append(app.wait(r"searched true") - asked)
+        finally:
+            app.stop()
+    return first, found
+
+
+def raise_main(app):
+    """The document window as key, once a dialog closed."""
+    sh("osascript", "-e", f'tell application "System Events" to tell (first process whose unix id is {app.process.pid}) '
+       f'to perform action "AXRaise" of window "{APPS[app.slug]}"')
+    time.sleep(0.3)
+
+
+def perf08(work, cycles=40):
+    """New and close a document; memory, handles and live documents."""
+    app = App("ely-doc", os.path.join(work, "home-cycles"))
+    docs = r"lok-worker: (\d+) documents open"
+
+    def open_docs():
+        counts = [int(m.group(1)) for line in app.lines() if (m := re.search(docs, line))]
+        return counts[-1] if counts else None
+
+    try:
+        app.wait("opened Untitled")
+        app.front()
+        time.sleep(2)
+        baseline = (app.memory_mb(), app.files(), open_docs())
+        seen = []
+        for n in range(cycles):
+            keys('keystroke "n" using command down')
+            for _ in range(40):
+                if "title=Use template" in app.ax():
+                    break
+                time.sleep(0.25)
+            sh(os.path.join(work, "ax-press"), str(app.process.pid), "Use template", "AXButton")
+            app.wait(f"opened Untitled {n + 2} ", timeout=30)
+            time.sleep(1)
+            # A keystroke can miss a window still taking focus.
+            for _ in range(3):
+                app.front()
+                raise_main(app)
+                keys('keystroke "w" using command down')
+                try:
+                    app.wait(f"office: closed Untitled {n + 2}$", timeout=5)
+                    break
+                except RuntimeError:
+                    # A keystroke that lost its Command edits the document.
+                    if "title=Don't Save" in app.ax():
+                        raise RuntimeError(f"ely-doc: Untitled {n + 2} was edited by a stray key; it asks to save")
+                    continue
+            else:
+                said = [line for line in app.lines() if re.search("clos|dialog|opened|focus", line)]
+                raise RuntimeError(f"ely-doc: Untitled {n + 2} never closed: {said[-8:]}")
+            # The kernel lets go in the background.
+            for _ in range(100):
+                if open_docs() == baseline[2]:
+                    break
+                time.sleep(0.05)
+            time.sleep(0.5)
+            seen.append((app.memory_mb(), app.files(), open_docs()))
+    finally:
+        app.stop()
+    # The first dialog loads system fonts and AppKit tables once.
+    first, last = seen[0], seen[-1]
+    if last[1] != first[1] or last[2] != baseline[2]:
+        raise RuntimeError(f"ely-doc: after {cycles} cycles {last[1:]} files and documents, "
+                           f"not {first[1]} and {baseline[2]}")
+    return baseline, seen
+
+def environment(found):
+    gpu = re.findall(r"Chipset Model: (.+)", sh("system_profiler", "SPDisplaysDataType"))
+    fonts = sum(len(files) for folder in ["/System/Library/Fonts", "/Library/Fonts"] for _, _, files in os.walk(folder))
+    builds = {slug: hashlib.sha256(open(os.path.join(ROOT, "target", "release", slug), "rb").read()).hexdigest()[:16]
+              for slug in APPS}
+    return {
+        "date": datetime.date.today().isoformat(),
+        "machine": sh("sysctl", "-n", "hw.model").strip(),
+        "cpu": sh("sysctl", "-n", "machdep.cpu.brand_string").strip(),
+        "cores": sh("sysctl", "-n", "hw.ncpu").strip(),
+        "memory_gb": int(sh("sysctl", "-n", "hw.memsize")) // 2**30,
+        "gpu": ", ".join(gpu),
+        "system": f"macOS {platform.mac_ver()[0]}",
+        "fonts": fonts,
+        "builds": builds,
+        "samples": {name: value[1] for name, value in found.items()},
+    }
+
+
+def main():
+    parser = argparse.ArgumentParser()
+    parser.add_argument("--runs", type=int, default=30)
+    parser.add_argument("--only", nargs="*")
+    parser.add_argument("--out", default=os.path.join(ROOT, "docs", "perf"))
+    args = parser.parse_args()
+    want = lambda perf: not args.only or perf in args.only
+    if sys.platform != "darwin":
+        sys.exit("SKIP: the bench drives macOS windows")
+    sh("cargo", "build", "--release", "-q", "--bins", "-p", "ely-lok", "-p", "ely-pdf-engine",
+       *[arg for slug in APPS for arg in ("-p", slug)], cwd=ROOT)
+    git = os.path.join(ROOT, "engines", "git", "bin", "git")
+    found = samples.made(os.path.join(ROOT, "engines", "bench"), git)
+    work = tempfile.mkdtemp()
+    tools(work)
+    rows = []
+    try:
+        if want("PERF-01"):
+            for slug, first, daily in perf01(work, args.runs):
+                rows.append(("PERF-01", f"{slug} first run", [first], None))
+                rows.append(("PERF-01", f"{slug} daily start", daily, None))
+            # The window opens first; the blank document follows the engine.
+            for slug in ["ely-doc", "ely-table", "ely-show"]:
+                blank = []
+                for _ in range(args.runs):
+                    app = App(slug, os.path.join(work, "home-" + slug))
+                    try:
+                        blank.append(app.wait("opened Untitled"))
+                    finally:
+                        app.stop()
+                rows.append(("PERF-01", f"{slug} blank document ready", blank, None))
+        if want("PERF-02"):
+            ticks, stalls = perf02(work, args.runs)
+            rows.append(("PERF-02", "ElyDoc key to new tile", ticks, None))
+            rows.append(("PERF-02", f"main thread busy >100 ms: {len(stalls)} times", stalls or [0], None))
+        cases = [("PERF-03", "ely-doc", "doc.docx", ["opened doc.docx", r"lok: tile \(\d+, \d+\) shown"]),
+                 ("PERF-04", "ely-table", "sheet.xlsx", ["opened sheet.xlsx", r"lok: tile \(\d+, \d+\) shown"]),
+                 ("PERF-05", "ely-pdf", "pages.pdf", ["opened pages.pdf", r"pdf: a tile of page 0 drawn"]),
+                 ("PERF-07", "ely-mark", "notes.md", ["opened notes.md", r"mark: shown as \"visual\""])]
+        if want("PERF-03"):
+            laid_out(work, found["doc.docx"][0], 100)
+        for perf, slug, name, marks in cases:
+            if want(perf):
+                times, memory = opened(slug, os.path.join(work, "home-" + slug), found[name][0], marks, args.runs)
+                rows.append((perf, f"{APPS[slug]} {name}", times, max(memory)))
+        if want("PERF-06"):
+            first, searched = perf06(work, found["repo"][0], args.runs)
+            rows.append(("PERF-06", "ElyTree history, press to first screen", first, None))
+            rows.append(("PERF-06", "ElyTree query 'part 42', first results", searched, None))
+        held = perf08(work) if want("PERF-08") else None
+    finally:
+        shutil.rmtree(work, ignore_errors=True)
+    write(args.out, environment(found), rows, held, args.runs)
+
+
+def write(out, env, rows, held, runs):
+    os.makedirs(out, exist_ok=True)
+    path = os.path.join(out, f"{env['date']}-{env['machine']}.md")
+    lines = [f"# Benchmark {env['date']}", "", "Format: docs/perf/README.md.", "", "```json",
+             json.dumps(env, indent=2), "```", "",
+             "| PERF | Case | Runs | P50 ms | P95 ms | Target ms | Total memory MB |", "| --- | --- | --- | --- | --- | --- | --- |"]
+    for perf, case, times, memory in rows:
+        target = TARGETS.get(perf)
+        p95 = percentile(times, 0.95)
+        verdict = "" if target is None or "busy" in case else (" ✓" if p95 <= target else " ✗")
+        mem = "" if memory is None else f"{memory:.0f}"
+        lines.append(f"| {perf} | {case} | {len(times)} | {percentile(times, 0.5):.0f} | {p95:.0f}{verdict} | "
+                     f"{target or ''} | {mem} |")
+    if held:
+        (memory, files, docs), seen = held
+        lines += ["", f"PERF-08, ElyDoc creating and closing a document {len(seen)} times "
+                  "(total memory MB / open files / kernel documents):", "",
+                  f"before: {memory:.0f}/{files}/{docs}", "",
+                  " ".join(f"{memory:.0f}/{files}/{docs}" for memory, files, docs in seen)]
+    lines += ["", "PERF-09 (Agent sessions) belongs to the second release.", ""]
+    with open(path, "w") as record:
+        record.write("\n".join(lines))
+    print(path)
+
+
+if __name__ == "__main__":
+    main()