diff --git a/apps/ely-pdf/src/pages.rs b/apps/ely-pdf/src/pages.rs index 6b92151..04cd2eb 100644 --- a/apps/ely-pdf/src/pages.rs +++ b/apps/ely-pdf/src/pages.rs @@ -6,7 +6,7 @@ use ely_gpui_component::theme::ActiveTheme as _; use gpui::{ AnyElement, Context, InteractiveElement as _, IntoElement, MouseButton, ParentElement as _, Pixels, Point, RenderImage, StatefulInteractiveElement as _, Styled as _, Window, canvas, div, - img, point, px, + point, px, }; use image::{Frame, ImageBuffer, Rgba}; @@ -64,6 +64,21 @@ fn span(from: f32, to: f32, sf: f32, side: i32) -> std::ops::RangeInclusive first..=last } +/// Draws `image`, logging failure and first success (PERF-05). +fn drawn_tile(image: Arc, page: usize, view: gpui::Entity) -> gpui::Canvas<()> { + canvas( + |_, _, _| {}, + move |bounds, _, window, cx| match window.paint_image(bounds, bounds, Default::default(), image, 0, false) { + Ok(()) if !view.read(cx).drawn => { + view.update(cx, |view, _| view.drawn = true); + log::info!("pdf: first tile drawn, page {page}"); + } + Ok(()) => {} + Err(error) => log::error!("pdf: drawing a page failed: {error}"), + }, + ) +} + /// A tile as an image; GPUI takes BGRA. pub(crate) fn picture((w, h): (u32, u32), bgra: Vec) -> Option> { let image = ImageBuffer::, _>::from_raw(w, h, bgra)?; @@ -151,7 +166,7 @@ impl PdfView { seen.insert(key); match self.tiles.get(&key) { Some(image) => tiles.push( - img(image.clone()) + drawn_tile(image.clone(), place.page, cx.entity()) .absolute() .left(px(rect[0] as f32 / sf)) .top(px(rect[1] as f32 / sf)) @@ -279,7 +294,7 @@ impl PdfView { }); match painted.map(|bgra| picture((rect[2] as u32, rect[3] as u32), bgra)) { Ok(Some(image)) => { - log::debug!("pdf: a tile of page {} drawn", key.page); + log::debug!("pdf: a tile of page {} came", key.page); if let Some(old) = view.tiles.insert(key, image) { view.retired.push(old); } diff --git a/apps/ely-pdf/src/view.rs b/apps/ely-pdf/src/view.rs index e7b1dab..2d67a21 100644 --- a/apps/ely-pdf/src/view.rs +++ b/apps/ely-pdf/src/view.rs @@ -37,6 +37,8 @@ pub struct PdfView { pub tiles: HashMap>, /// Images no longer drawn, freed at the next render. pub retired: ely_gpui_component::primitives::Retired, + /// A tile reached the screen; logged once (PERF-05). + pub drawn: bool, /// Tiles the worker could not draw; not asked again. pub failed: HashSet, pub text: HashMap>>, @@ -162,6 +164,7 @@ impl PdfView { scroll: ScrollHandle::new(), tiles: HashMap::new(), retired: Default::default(), + drawn: false, failed: HashSet::new(), text: HashMap::new(), asking_text: HashSet::new(), diff --git a/crates/ely-lok/src/view.rs b/crates/ely-lok/src/view.rs index 003a523..6da81c6 100644 --- a/crates/ely-lok/src/view.rs +++ b/crates/ely-lok/src/view.rs @@ -107,6 +107,8 @@ pub struct LokView { moves: u64, last_edit: u64, clock: clock::EditClock, + /// A tile reached the screen; logged once (PERF-03). + drawn: bool, /// Tiles the last frame showed. on_screen: Vec<(i32, i32)>, /// The mark of this view's last copy. @@ -218,6 +220,7 @@ impl LokView { moves: 0, last_edit: 0, clock: clock::EditClock::default(), + drawn: false, on_screen: Vec::new(), copied: None, cursor: None, diff --git a/crates/ely-lok/src/view/render.rs b/crates/ely-lok/src/view/render.rs index af34df6..81a1792 100644 --- a/crates/ely-lok/src/view/render.rs +++ b/crates/ely-lok/src/view/render.rs @@ -91,6 +91,7 @@ impl Render for LokView { } }, move |bounds, painted, window, app| { + let mut drawn = false; for page in &painted.pages { window.paint_quad(fill(*page, paper)); window.with_content_mask( @@ -108,13 +109,18 @@ impl Render for LokView { false, ) }); - if let Err(error) = painted { - log::error!("lok: tile paint failed: {error}"); + match painted { + Ok(()) => drawn = true, + Err(error) => log::error!("lok: tile paint failed: {error}"), } } }, ); } + if drawn && !this.read(app).drawn { + this.update(app, |view, _| view.drawn = true); + log::info!("lok: first tile drawn"); + } window.with_content_mask(Some(ContentMask { bounds }), |window| { for rect in painted.selection { window.paint_quad(fill(rect, selection_color)); diff --git a/docs/perf/2026-10-08-Mac16,10.md b/docs/perf/2026-10-08-Mac16,10.md index adb0423..c134017 100644 --- a/docs/perf/2026-10-08-Mac16,10.md +++ b/docs/perf/2026-10-08-Mac16,10.md @@ -13,15 +13,15 @@ Format: docs/perf/README.md. "system": "macOS 27.0", "fonts": 372, "builds": { - "ely-doc": "bd36fee608ebe0ee", - "ely-table": "4461b4f741a8ae9e", - "ely-show": "8650ed752d6080f1", - "ely-pdf": "af9f8ba1cb599b0e", - "ely-tree": "7cd55cb147481e01", - "ely-mark": "ef45e8053a0ed8fb" + "ely-doc": "0c399c291aea777c", + "ely-table": "14691141a5506fa1", + "ely-show": "0cc42529fee3ecd2", + "ely-pdf": "012e886daa97a613", + "ely-tree": "72c2e357b27e5109", + "ely-mark": "4d57205af957ba11" }, "samples": { - "doc.docx": "5ab234c7fcc6b84242e3318a83849cd1078269bcaba0a6160efbf447e865c426", + "doc.docx": "44320bb46b8032f45eb37f4af5cc0b8c5148c0c40f244a0da9f6730f3fb26f0a", "sheet.xlsx": "356ca8e1c6985257040d205c5c72bbc66c9acc0afb76ec26fba7d6a1566f21a1", "pages.pdf": "d9852531dbbd3699642398c2b454246a361c92ddad5f7dc7483af371f9ce40cb", "notes.md": "2c21622c0242e5460d0df3e6a0b7497a6a2100a4e10363e095519b8f9256bdb3", @@ -32,32 +32,34 @@ Format: docs/perf/README.md. | PERF | Case | Runs | P50 ms | P95 ms | Target ms | Total memory MB | | --- | --- | --- | --- | --- | --- | --- | -| PERF-01 | ely-doc first run | 1 | 192 | 192 ✓ | 3000 | | -| PERF-01 | ely-doc daily start | 30 | 132 | 150 ✓ | 3000 | | -| PERF-01 | ely-table first run | 1 | 181 | 181 ✓ | 3000 | | -| PERF-01 | ely-table daily start | 30 | 127 | 138 ✓ | 3000 | | -| PERF-01 | ely-show first run | 1 | 161 | 161 ✓ | 3000 | | -| PERF-01 | ely-show daily start | 30 | 126 | 135 ✓ | 3000 | | -| PERF-01 | ely-pdf first run | 1 | 171 | 171 ✓ | 3000 | | -| PERF-01 | ely-pdf daily start | 30 | 129 | 133 ✓ | 3000 | | -| PERF-01 | ely-tree first run | 1 | 173 | 173 ✓ | 3000 | | -| PERF-01 | ely-tree daily start | 30 | 132 | 136 ✓ | 3000 | | -| PERF-01 | ely-mark first run | 1 | 491 | 491 ✓ | 3000 | | -| PERF-01 | ely-mark daily start | 30 | 205 | 213 ✓ | 3000 | | -| PERF-01 | ely-doc blank document ready | 30 | 992 | 1020 ✓ | 3000 | | -| PERF-01 | ely-table blank document ready | 30 | 1057 | 1087 ✓ | 3000 | | -| PERF-01 | ely-show blank document ready | 30 | 1183 | 1229 ✓ | 3000 | | -| PERF-02 | ElyDoc key to new tile | 30 | 2 | 5 ✓ | 100 | | +| PERF-01 | ely-doc first run | 1 | 164 | 164 ✓ | 3000 | | +| PERF-01 | ely-doc daily start | 30 | 124 | 133 ✓ | 3000 | | +| PERF-01 | ely-table first run | 1 | 161 | 161 ✓ | 3000 | | +| PERF-01 | ely-table daily start | 30 | 125 | 133 ✓ | 3000 | | +| PERF-01 | ely-show first run | 1 | 153 | 153 ✓ | 3000 | | +| PERF-01 | ely-show daily start | 30 | 121 | 127 ✓ | 3000 | | +| PERF-01 | ely-pdf first run | 1 | 163 | 163 ✓ | 3000 | | +| PERF-01 | ely-pdf daily start | 30 | 124 | 133 ✓ | 3000 | | +| PERF-01 | ely-tree first run | 1 | 172 | 172 ✓ | 3000 | | +| PERF-01 | ely-tree daily start | 30 | 132 | 140 ✓ | 3000 | | +| PERF-01 | ely-mark first run | 1 | 451 | 451 ✓ | 3000 | | +| PERF-01 | ely-mark daily start | 30 | 201 | 215 ✓ | 3000 | | +| PERF-01 | ely-doc blank document ready | 30 | 910 | 963 ✓ | 3000 | | +| PERF-01 | ely-table blank document ready | 30 | 978 | 999 ✓ | 3000 | | +| PERF-01 | ely-show blank document ready | 30 | 1107 | 1132 ✓ | 3000 | | +| PERF-02 | ElyDoc key to new tile | 30 | 2 | 6 ✓ | 100 | | | PERF-02 | main thread busy >100 ms: 0 times | 1 | 0 | 0 | 100 | | -| PERF-03 | ElyDoc doc.docx | 30 | 1260 | 1293 ✓ | 5000 | 412 | -| PERF-04 | ElyTable sheet.xlsx | 30 | 1260 | 1286 ✓ | 5000 | 381 | -| PERF-05 | ElyPDF pages.pdf | 30 | 209 | 223 ✓ | 3000 | 111 | -| PERF-07 | ElyMark notes.md | 30 | 1702 | 1725 ✓ | 2000 | 1095 | -| PERF-06 | ElyTree history, press to first screen | 30 | 381 | 402 ✓ | 1000 | | -| PERF-06 | ElyTree query 'part 42', first results | 30 | 463 | 476 ✓ | 1000 | | +| PERF-03 | ElyDoc doc.docx | 30 | 1182 | 1211 ✓ | 5000 | 426 | +| PERF-04 | ElyTable sheet.xlsx | 30 | 1173 | 1197 ✓ | 5000 | 402 | +| PERF-05 | ElyPDF pages.pdf | 30 | 412 | 425 ✓ | 3000 | 114 | +| PERF-07 | ElyMark notes.md | 30 | 1572 | 1612 ✓ | 2000 | 1037 | +| PERF-06 | ElyTree history, press to first screen | 30 | 381 | 407 ✓ | 1000 | | +| PERF-06 | ElyTree query 'part 42', first results | 30 | 450 | 462 ✓ | 1000 | | -PERF-08, ElyDoc opening and closing a document 40 times (total memory MB, open files): +PERF-08, ElyDoc creating and closing a document 40 times (total memory MB / open files / kernel documents): -457/564 458/564 458/564 458/564 458/564 460/564 460/564 461/564 462/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 454/564 455/564 455/564 455/564 455/564 455/564 455/564 455/564 455/564 455/564 455/564 455/564 455/564 455/564 455/564 +before: 393/558/1 + +419/562/1 427/562/1 427/562/1 427/562/1 430/562/1 430/562/1 430/562/1 430/562/1 430/562/1 430/562/1 430/562/1 430/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 431/562/1 PERF-09 (Agent sessions) belongs to the second release. diff --git a/docs/perf/README.md b/docs/perf/README.md index 66c0e3a..9f2bec4 100644 --- a/docs/perf/README.md +++ b/docs/perf/README.md @@ -12,6 +12,6 @@ | repo | 10 万个提交 | PERF-06 | | notes.md | 1 MB | PERF-07 | -计时从启动进程起，到日志里出现标记为止（脚本每 10 毫秒读一次日志）：PERF-01 到首帧（`ELY_SMOKE=1` 打印 `ready`），首次运行（新的用户目录）与日常启动分记，每次等上一次的进程（含仍在启动的内核）退出后再测；Doc、Table、Show 另记空白文档就绪（`opened Untitled`），它要等内核启动；PERF-03、04 到视图收下的第一块图块（`lok: tile (x, y) shown`；其间有图块画失败即整次作废），PERF-03 之前先核对样本经内核排版恰为 100 页（`lok: 100 pages`）；PERF-05 到第一页的第一块（`pdf: a tile of page 0 drawn`）；PERF-06 的历史首屏从按下“历史”到显示（`history shows`），查询从按下回车到结果（`searched true`），性能要求的指标是后者；PERF-07 到可视编辑器显示（`mark: shown as visual`）。PERF-02 为 ElyDoc 每次按键到显示该编辑的图块（`lok: edit to tile`，每键须各有一条，缺即失败），并以 `ELY_STALLS=1` 记下主线程连续忙于 100 毫秒以上的次数（`main thread was busy`）。内存为应用及其全部子进程（内核 worker、CEF 辅助进程）的 RSS 之和。PERF-08 为 ElyDoc 新建再关闭文档 40 次：循环前记下基线（总内存、打开的文件数、内核中的文档数 `lok-worker: N documents open`），每次关闭后等内核回到基线文档数再记三者；最后的文档数不等于基线、或文件数不等于第一次之后的即失败（第一次打开模板对话框时，进程一次性载入两个系统字体与 AppKit 的两个本地化表，此后不再增加）。 +计时从启动进程起，到日志里出现标记为止（脚本每 10 毫秒读一次日志）：PERF-01 到首帧（`ELY_SMOKE=1` 打印 `ready`），首次运行（新的用户目录）与日常启动分记，每次等上一次的进程（含仍在启动的内核）退出后再测；Doc、Table、Show 另记空白文档就绪（`opened Untitled`），它要等内核启动；PERF-03、04 到第一块图块真正画到窗口上（`lok: first tile drawn`，在 `paint_image` 成功之后记；其间内核画图块失败或窗口画图块失败即整次作废），PERF-03 之前先核对样本经内核排版恰为 100 页（`lok: 100 pages`）；PERF-05 到第一页的第一块画到窗口上（`pdf: first tile drawn, page 0`；画失败即整次作废）；PERF-06 的历史首屏从按下“历史”到显示（`history shows`），查询从按下回车到结果（`searched true`），性能要求的指标是后者；PERF-07 到可视编辑器显示（`mark: shown as visual`）。PERF-02 为 ElyDoc 每次按键到显示该编辑的图块（`lok: edit to tile`，每键须各有一条，缺即失败），并以 `ELY_STALLS=1` 记下主线程连续忙于 100 毫秒以上的次数（`main thread was busy`）。内存为应用及其全部子进程（内核 worker、CEF 辅助进程）的 RSS 之和。PERF-08 为 ElyDoc 新建再关闭文档 40 次：循环前记下基线（总内存、全部句柄的类型与名称、内核中的文档数 `lok-worker: N documents open`），每次关闭后等内核回到基线文档数（等不到或没有这条日志即失败），再按身份比对句柄：比基线多出的只许是 `/System/Library/` 下的只读系统资源（第一次打开模板对话框时一次性载入两个系统字体与 AppKit 的两个本地化表），且此后每次都相同；多出任何别的句柄即失败。记录写基线与每次的内存、句柄数、文档数。 记录开头的 JSON 写机型、CPU、核数、内存、GPU、系统、系统字体文件数、各应用发行二进制的散列与样本散列。冷启动未清系统文件缓存（需要管理员权限），“日常启动”即文件缓存已热时的启动。 diff --git a/scripts/engines-key.sh b/scripts/engines-key.sh index f2c9c23..e536d3f 100755 --- a/scripts/engines-key.sh +++ b/scripts/engines-key.sh @@ -1,5 +1,5 @@ #!/usr/bin/env bash -# Prints the engines' key: a hash of every pin, patch and recipe. +# Prints the engines' key: a hash of pins and patches. set -euo pipefail root=$(cd "$(dirname "$0")/.." && pwd) cd "$root" diff --git a/tests/perf/__pycache__/bench.cpython-314.pyc b/tests/perf/__pycache__/bench.cpython-314.pyc index 45860c3..089db20 100644 Binary files a/tests/perf/__pycache__/bench.cpython-314.pyc and b/tests/perf/__pycache__/bench.cpython-314.pyc differ diff --git a/tests/perf/bench.py b/tests/perf/bench.py index 9b0c867..e025684 100644 --- a/tests/perf/bench.py +++ b/tests/perf/bench.py @@ -2,6 +2,7 @@ """PERF-01 to PERF-08 on release builds, written as a record.""" import argparse +import collections import datetime import hashlib import json @@ -98,8 +99,20 @@ class App: return self.family()[1] / 1024 def files(self): + return sum(self.handles().values()) + + def handles(self): + """Open handles of the app and its children, as type and name.""" ours, _ = self.family() - return sum(len(sh("lsof", "-p", str(pid)).splitlines()) for pid in ours) + found = collections.Counter() + for pid in ours: + kind = None + for line in sh("lsof", "-p", str(pid), "-F", "tn").splitlines(): + if line[:1] == "t": + kind = line[1:] + elif line[:1] == "n": + found[(kind, line[1:])] += 1 + return found 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') @@ -128,7 +141,7 @@ def percentile(values, p): # A page that failed to paint voids the run. -PAINT_FAILED = r"lok: tile \(.*\) failed|pdf: drawing a page failed" +PAINT_FAILED = r"lok: tile \(.*\) failed|lok: tile paint failed|pdf: drawing a page failed" def opened(slug, home, sample, marks, runs): @@ -232,21 +245,40 @@ def raise_main(app): time.sleep(0.3) +def documents_open(lines): + """The kernel's last document count; none logged fails.""" + counts = [int(m.group(1)) for line in lines if (m := re.search(r"lok-worker: (\d+) documents open", line))] + if not counts: + raise RuntimeError("ely-doc: the worker logged no document count") + return counts[-1] + + +def handles_kept(before, now, extra, cycle): + """Handles past the baseline: only system ones, the same each cycle.""" + grown = now - before + # Read-only system resources load once, on first use. + left = sorted(handle for handle in grown if not handle[1].startswith("/System/Library/")) + if left: + raise RuntimeError(f"ely-doc: cycle {cycle} leaves handles: {left}") + if extra is not None and grown != extra: + raise RuntimeError(f"ely-doc: cycle {cycle} changed the system handles: {sorted((grown - extra) + (extra - grown))}") + return grown + + 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 + return documents_open(app.lines()) try: app.wait("opened Untitled") app.front() time.sleep(2) - baseline = (app.memory_mb(), app.files(), open_docs()) - seen = [] + before = app.handles() + baseline = (app.memory_mb(), sum(before.values()), open_docs()) + seen, extra = [], None for n in range(cycles): keys('keystroke "n" using command down') for _ in range(40): @@ -277,15 +309,14 @@ def perf08(work, cycles=40): if open_docs() == baseline[2]: break time.sleep(0.05) + else: + raise RuntimeError(f"ely-doc: {open_docs()} documents after closing, not {baseline[2]}") time.sleep(0.5) - seen.append((app.memory_mb(), app.files(), open_docs())) + now = app.handles() + extra = handles_kept(before, now, extra, n + 1) + seen.append((app.memory_mb(), sum(now.values()), 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): @@ -342,9 +373,9 @@ def main(): 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"]), + cases = [("PERF-03", "ely-doc", "doc.docx", ["opened doc.docx", r"lok: first tile drawn"]), + ("PERF-04", "ely-table", "sheet.xlsx", ["opened sheet.xlsx", r"lok: first tile drawn"]), + ("PERF-05", "ely-pdf", "pages.pdf", ["opened pages.pdf", r"pdf: first tile drawn, page 0$"]), ("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) diff --git a/tests/perf/test_bench.py b/tests/perf/test_bench.py new file mode 100644 index 0000000..452bcf0 --- /dev/null +++ b/tests/perf/test_bench.py @@ -0,0 +1,40 @@ +#!/usr/bin/env python3 +# The bench's verdicts on made-up logs and handles. +import collections +import re +import unittest + +import bench + + +class Verdicts(unittest.TestCase): + def test_a_failed_draw_voids_the_run(self): + for line in ["lok: tile paint failed: atlas full", "lok: tile (0, 1) failed: kernel", + "pdf: drawing a page failed (Other)"]: + self.assertTrue(re.search(bench.PAINT_FAILED, line), line) + self.assertFalse(re.search(bench.PAINT_FAILED, "lok: first tile drawn")) + + def test_a_leak_on_the_first_close_fails(self): + before = collections.Counter({("REG", "/tmp/a"): 1}) + now = before + collections.Counter({("CHR", "/dev/null"): 1}) + with self.assertRaisesRegex(RuntimeError, "leaves handles"): + bench.handles_kept(before, now, None, 1) + + def test_system_resources_once_then_steady(self): + before = collections.Counter({("REG", "/tmp/a"): 1}) + font = collections.Counter({("REG", "/System/Library/Fonts/SFNSItalic.ttf"): 1}) + extra = bench.handles_kept(before, before + font, None, 1) + self.assertEqual(bench.handles_kept(before, before + font, extra, 2), font) + more = before + font + collections.Counter({("REG", "/System/Library/Fonts/More.ttf"): 1}) + with self.assertRaisesRegex(RuntimeError, "changed the system handles"): + bench.handles_kept(before, more, extra, 3) + + + def test_the_document_count_must_be_logged(self): + self.assertEqual(bench.documents_open(["x", "lok-worker: 2 documents open", "lok-worker: 1 documents open"]), 1) + with self.assertRaisesRegex(RuntimeError, "no document count"): + bench.documents_open(["office: closed Untitled 2"]) + + +if __name__ == "__main__": + unittest.main()