From 946e5cf835fa29f866096c51ab444bd87fb3ae64 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E9=9B=B7=E7=94=B5=E8=8A=BD=E8=A1=A3?= Date: Thu, 8 Oct 2026 21:59:06 -0400 Subject: [PATCH] Bench: first screen is a drawn tile; handles checked by identity; clean record --- apps/ely-pdf/src/pages.rs | 21 +++++- apps/ely-pdf/src/view.rs | 3 + crates/ely-lok/src/view.rs | 3 + crates/ely-lok/src/view/render.rs | 10 ++- docs/perf/2026-10-08-Mac16,10.md | 64 ++++++++++--------- docs/perf/README.md | 2 +- scripts/engines-key.sh | 2 +- tests/perf/__pycache__/bench.cpython-314.pyc | Bin 31680 -> 33352 bytes tests/perf/bench.py | 63 +++++++++++++----- tests/perf/test_bench.py | 40 ++++++++++++ 10 files changed, 154 insertions(+), 54 deletions(-) create mode 100644 tests/perf/test_bench.py 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 45860c3aed27fa14417b3ebadda08db2a55284ed..089db20b55dcce2355b5cc1283e36d83fb270c44 100644 GIT binary patch delta 5686 zcmZu!4Rl+@m7bBFer(CIWJ|Uj+1B$tE2f9?;pUY#HeU$}>COI(lN~S(}?)J6nD%eSk=` z-4?a=8+og5olg6>xSl#GHn{kLFI(52&E2$M#wqC~K{7~2$t0PjG$~!ONLDFBveg=+ zE-6#8OOAnIDND+hobYo&Jx9uw+)`exDVig#$tBTT$ph$iks>1H=Mt%)UWY0X63vqe zfwM;P0(vAdnlBXrRUj1u7D^?6-g~4{_=wV4z#^#(uvjVwERog$mP$2JMJ@@_=vt`~ z>Saw7Q7VzBZlE-(&mm#x5EWp>I&DIOq=!k2uwH{!H%SgYWUR@8#!Sf;wfjia zAqgd1ciI%Zyfmw({nzD|CCzoo%ADIVL*4(9`yq+kJfY>&Ob=$AP*HZJNJS@v!stMsZV@lub#irzJ~X-^Gy8`tAwyY5US9#C*YGX zjrl{vL0L%{kNbm@vcjH$Rt06tm=^^MBLQTmwMHT}8Y!bdKEN!wl9_d;{@j+cTX@Um z>~-&EuZw3_#xtu_a}_HBfuUt>2(c0~wCI7jv6u2s@{9R91t$KcP{3a@r#D3OK58dz zCkcrN5{(%8OdzZkNhj(1(o!{_kXi;BT)lx8l@!lF$9Cvw^cf{%^_r9@A(BZuS}Ptc z@XV`u5kn^|;ZJ&`VUJPJGM{u-6Vkis)_xmx&G5H+q=6Y)ov||Mq<&IY2G!0^LefYf z>6}h}eR??O^y%h35ji9-?YS5p5u;%`(`t zC}3%w0mE2YkS2!%&60o5$~jkcwu-NR$TTNhv3oAtOMY!HiQCuC8Q#y%o!h<$u;Yq* z&HU!`^)F;E?7!%Kss2@G+}(27-Ttn-{WtE;GXluW>z-(sSN`hGMUVHq?wN+icPzT{ z=8K=W>wNaNk1RU#&O6T!7X7VTT~m44S+#KNlC$oTv+70~$?Kw@8i><<%|`65Ii6w7 zkG<$^qI5F$Ut$ZTFY@x@3OW_rS3F1Qy*yF!g7FQ|x+068F70{-Hdsqp$I^m8T3JV4s+y zDnnTF8jfO22q(g9oLz=W!VvL~!hOBM8)~ZzA4ALYv9a2xbQ!-vNi+KpKI}bi->}v2 z2OwXL9o+DVf<U(GaFz@s}I=EZXYsL$SBHr?FrYPQiu|@QQ1CCk&%3JQ-msG*noY z#zf{7gzp3J@y23$jX&C0WcvcDIEL~7-20n6QtRaZwl6J~X#CtrFK~71PWoG()B5;~ zHg6XW(2dZ8AR@eoAR(abFvB0(mb(ZAO0c*OQZxu_qcjx`37pNw@+7G5Pe?XCs zOu!j23-tb!|6=E%3Luutl7ka&EJD*Pcwjp@NGEkQWK!4G!k@jXv__&nntIuqX+&4P z)OX3_loHZsNDb%H@z?8|e0Foej6Onr`ej)wdZ!haDCtrzaSWs+{c7J-0#ke87oh=C zAxzgF0B18UvydDtSHz%SiHgJFp~(q36cvZiIW&u*a7Y$|;n7ifSRC;Of=bP_$lJQb zndxddIJF+c!B$}uG((xCBtzj_24epK%cwBiVomG@w6Z9&1U7&)It=z1!bbp#0Dvwg z`SRFO$|*;}GvGE^2HF+M-3>5Hu2$B@Gr||vo-h4b*3a{PlBaGTQOAPu#tF54;-%Jj z{lw|;>7g@4=gQBP&lmB^M?rM9P0a{@U~ycrtx-Mgaa)IK?pU-q&J;h=qzbMtubYT1 zLKO^$zFE{-E?g`G7(%Vk$!Z08@IDAP5D|_F0-}|gKih59n6^GiUeSG66;*hUwPb$zT9H5!eQv^PpdmgMpCTB!)x5DN&hHqVfdLvQn+_6?m9L z**`QU4owXO%#y!U;F^(WYD1PcBl+wW!?R3J zl39b7bgoOjoszDEY|;lPcu{=frtP)+H9cy(0)x!YrfPfG|3Q0&j*Y-4VO)BRbWkZv z+7dg84DS--$hbTciPmfhhKKw?rKM)es2q|{Mp%mg2Bv@lga!Va^CmqZLhRn zuHXG`{cg4W@a6ixb7ha0JvaHKg17yCZyo)+^g247xqLaaZ4jp&Vo>%UmzC60-y}{K zz}xN*;l+ZDok?xwl1fb?X#dYJWb%3#6UIS#B+TT5J`_HYFvusP%%3o5gKIwdLZ|?gW8S)oqyc6o?5xTLJMMz5&eGa-fWC(ZGA3Sl2&~By}8%~j*$C1 zof{%T4Ur5??#o-2ST;60*{N%TwMuHJ`;aq_a6S# zKpM|$cj(P4%dG25-2xaPrG}TR(lK+Tb!o>0$qobZ_A1z)d+yQpCm&v%w51oP6jqSd zSDjL9Zw-H=!=-om(s*WvXIEN}t`lx1MyQc=kgG_^N!dQrfNr@PG=oFR@uf>1$v}Z# z?UwrT__2<>OtVk7k~jGT{$z)T-p;S?D(cQ%QMwa$6lYsClY4bPm?h6Az|5-x_&=Tv zN6c8WG9v8Wl38qvSo&^DEugo#cNE-BstVtFAz6V8!LWDZD#jA|=S<47+N6psdy>k7 zgQNczA>C5w>^gA)0eIcBBo#@z_K;atsKuiD}RCjMC0rnIyG43HYr z>LmfvtS=zo=kocDu6@-*sgd!EYsiM*jm-dC=;~B&|5B>AHnlgY6i=tUn8}wm9lZej zzGlG5DMJ<`s=SNJZuBMdRz9)6!u+-`xLA`i|`$U zClJ1ea38|k2wKP|B6Ukth_RREB$MkJMiDJuMPHYU8CQpdM)a8z5GQ+(odu9Eryey1 zX(M4yWPBf~2N1>p5`y9n46|(HV9=;wf`>jfRkkK06k|kYBXtd|7zC~GQ(l5MXF2jU ze=bl%)iq-^|JO!0w@TJJhx450tcMrO85f8IK}fh3-YUuR}RLV&2u{!L8|ki&iU-`7Cc$-l=p>_ zg`poFy>RqmFkadG<3m3^th(DTTRT48MM;+TS_dU**2l~b+03WY7cJRyEvk@r^Rp^m zaiCSoPqNI9q<^JshrNll>AMTbFK;jG@(90jgZHX3#gY6fRyQDMw+D@yVTz?CW9(z3Fh5M_C;TUw35I3Gyl`Bk+xea2g$E^U(01uVl>9cr z?-BkR`xpj;{?PbJR>VF>*8ga%Aqe>t2B%M0D*|RS45MB4KL62pt04%D2V*zK72W!K z)Ox?_7+lQq%pYE;RvWw2o)NWSRCSDD)1d{6x_P(SF|KY3s*Z`+d?;#2tAgGMx}H^Y zSM)RbGEbkp9~{ghlYPbLomdp0hy5kY1}OqYbL@SD=MdVt<#-+a4&QQo2aWLij^6?J z^W#mfI5M>@L-S#n9I#<-JCVP39Ea3)vP$Od(Wa8y;&i+ZjX(A2Eix06T)vh1E^`+Eg7q#fzr1 zXEYb5>3s=Vc#g>v)oegJW$i>YXNPHz7RhOThM|EoJOoWi_9phl4NJOh3{n#2EfeA4 z$)McA9t1h~C(1g&YkErQRkHOz4J7k@lEp7hU&uc~Y5u1K@%j#6576so9c`u8ti;~O YBd3b2*KG!xbKRas9iO>5Kehh<0rMGGVE_OC delta 4106 zcmZ8k4RBM(5x#prk}UaOHnJ_rdbYqu_!s{$#(;mYAr$Zr&$ciin+RlMV`GUYIbZ{^ z$)t^wLSu3yK+`s4NP-Epfzb^4Y17g+4e5lmqD}@!Lz~jjOq(_-giHfzr*!wp!X|I5 z@9o|0?cVL)+g-o&D0ks28lM**rzh}SEP7{qf6bxzGYeRQb`t(EhZvc%eaWfK$@Hh zoOIa+m?296vz!H#Ma~Aa%67m^c`l$$o(Cw&Ie=MmzMN|!{WOp*&xf&Hb^y+m7XZ%d z$dU6Z+6nQ%p)4e=V{R5Ho8G;R$keX>90frO7thg*V4iTA(oA+m?5XGnF*g|{9V9?y z65u-R0e%kg!h(Px$IF~*QIvVGqLCA1Q5|dLM7B#)7#m1%l0c#?*oh-4_^RgH0?i37 zGkn0&(x5TER-iSkE%_>49xO3xDXk1vrhLWIRl$<9Wjx)?eCA)$wqS{+jZ!xovo6uE zhOLYeCuydvHZEgi7kEoacJb5aATlu#Cr!L}ureCqfN{EYnpS5pu%+<3wHF|p*g$D3 zSy@7ekGk&3&DJYZm#D4;aMEeLJSpSZIU$3MSL;}Fo6fzPjEXk02K*XBGKtLDNjcw3 z9eh~m_j|j)<_dg`4k66KXc`~6nq-zd7m<2KF37*fcqJ|e?fg&RuVB^^-v7CE%Sc6A! z@9q!U=8jS7WfSwxXkG^qM-tnZ(~)=*rGJcY7U4X*l+&WI1L?14^KuI{oVbpDp<^An zTMRFwz-fSCiN$A2?9<#r@hun*G3)%lrYJ8U`zZkMy5=Ew{~$Qc=*SV@g{gh4%CVf5 zu>Fp-;91AJ96itW=I;@&0P8!!|K`UD8Rv1KCM@joDt*fDVGtI5?rmLu<$Y#fm?wS& zGv5!kEPR%W`yEQ^l&kPkF0=oX)`-`EJQ=Jh`&^_yV?~u-I?SG{bZt^kwI9WBm#Wj1 zPNdc%_z?mKXj<_gbRpmo!s0f?JLpr-VLeFVU6PV_4fu8hSTcaRqw>9 z`v?n4m(QzQM&1g9zu*$F+dDYmQSXtuN0wZ_OuP%6OTpIq$2d(ScI?{9(}IJ7PsblH ziyVA!*V)+zHn6(+M!j(B4Gm-)z1zTY3fD4QV~j~J^In5f?=+NhvH-b7=i|(zMbB#2 zrN)WTFWiPR-ttT~)L20E?9bX1{3wMMeX|iW#cC%vlkQ4+A74m(f-4nvrat$+Xp%@) za4X>x@QE%{lq+jythiFy=B9M5M%IGrbX3ibHPulwTWDX((whwiYjhRt=d3H0N+4ro z7wlTLxj6xL2D|2Cog#azxygFZekUKbkVsap0_&Q{X^LI=4X96xJ}P1(v$mEnGdt}R z6BXHpb$PtLITyE=m`K{RgIpmQ@nokbItwQ$#FNbSypsow88a#?*nk|% zUTVrtO^Ysr^jRF)jw_apB--rhGaRSTTrjgZN`b4s8E*EA7PA5F5oTeCQxUtl$T}j( zw%N9QG0vDyI(r7j_wBBfbMkV=Y>A3pP(L9g7Bb6EW+w&DSe!BU%fg&>_IkD0g4^z0 zrXIS!tQ1OwL|hP<$fF^ig{U4Xa`L?kwyf0b@Yx36g@vqv&APOa8LWkHqf=O4g>{7U5hoXwjdU4KPQK5hktSo1vw>M3>BZ{v z1JKl{gaI95Brke^p2>mArx8{U&i)hOPY7xT6g=Loe!mD~Ns{O&8*IxTxd9_Tv^nH9 z)U3jVuk@bkJ<~UtwDDBmanD;N7Z?9(@jI=dmi3c$?V+mn*W8m;?T3pF+sEBUwjJ7b z)Xla(Q*^3tOcP4l_>t8<_R#p2gTobgf+e{rMtL7i3br><39r}&K>sh5^LO)p>VYR-vTEV-q7W; zjqP(YQ%px14mGf*<1HsQJip<@rgM&9UdUKArkhGg8WVy)Y44yTIue)kE6H2SQ5?g<>nk3t9ET<$U_DS92x&!(t zL&7+Buwt}+N*6n}?x1!&W!(L=DWpw5+J1b?4_)tT9arNsj&7cCPOLh+>b2Gj*>ASL zwmP)(!H~N*w7vfW_YPC&!GVz3I~nf_>3mZL<5*QlNWcB1gB{&iE2m7`IjH~IUk8VM zb%morN8ZlLTq_E1SI+_ZVydly*IZnzL9AZB0H!X9iyDab(h>pbY6|pwLl!>?Ut}@l8Pmd;@&mDUh>w)eu%m-4=J|^ zyXAd4;RMjbTKphDwQ_ z>vNU0)$ND=uN>DGAcTO*3(Vwv%Sjz^Y&GyVz(P<>hRhq8xfk= z@IK2tC#qDvnun8W4#2~O1w3fV;54 zu7+1lWSCMEyw?iGLEWSB2D>?GO;cbDf5dMFyunjSuaTOMNdj~1KV@m5)N+#`e$mfS c+6n($aI}`*h$V?D*ysDRxG&?G`H_PE0}~asDF6Tf 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()