mirror of
https://github.com/storytold/photocraft.git
synced 2026-11-02 18:13:39 +00:00
Merge pull request #9943 from brennanMKE/perf/9328-slow-frames
Perf: every frame records its stages; slow frames are kept, logged and reported (#9328)
This commit is contained in:
aiongg
@@ -968,6 +968,70 @@ fn background_job_scenarios(b: &mut Bench, sz: &Sizes) {
|
||||
if b.wanted(frame) {
|
||||
frame_scenario(b, frame, w, h);
|
||||
}
|
||||
let full = "app frame: full CPU refresh of a 24 MP document";
|
||||
if b.wanted(full) {
|
||||
full_refresh_frame_scenario(b, full, w, h);
|
||||
}
|
||||
}
|
||||
|
||||
/// #9328: the whole app (kittest harness, CPU canvas) with a 24 MP document; each sample toggles
|
||||
/// a layer's visibility and steps one frame, and every frame recomposites all 24 MP on the CPU.
|
||||
/// Always 10 samples, whatever `--reps` says.
|
||||
///
|
||||
/// The stack is the photo plus three full-canvas copies in blend modes, and the top copy toggles.
|
||||
/// Toggling the photo's only layer (the first version) measured 3.4 ms: with it hidden no layer
|
||||
/// is visible, so the reduced composite's one-colour shortcut (`compose::uniform`) draws the whole
|
||||
/// canvas as one pixel. Here the photo stays visible in every frame, its noisy tiles are never one
|
||||
/// colour, and the toggled layer's damage is the whole canvas. Each frame checks that the canvas
|
||||
/// refresh it recorded was a CPU one covering the whole document (within the reduction's rounding).
|
||||
fn full_refresh_frame_scenario(b: &mut Bench, name: &str, w: u32, h: u32) {
|
||||
let mut s = match open_photo(w, h) {
|
||||
Ok(s) => s,
|
||||
Err(e) => return b.errors.push((name.into(), e)),
|
||||
};
|
||||
let built = (|| -> Res<u64> {
|
||||
let photo = active_layer(&s)?;
|
||||
for (blend, opacity) in [("Multiply", 0.7), ("Screen", 0.5), ("Overlay", 0.6)] {
|
||||
exec(&mut s, "layer.duplicate", json!({"layer": photo}))?;
|
||||
let copy = active_layer(&s)?;
|
||||
if copy == photo {
|
||||
return Err("layer.duplicate did not select the copy".into());
|
||||
}
|
||||
exec(&mut s, "layer.setProps", json!({"layer": copy, "blend": blend, "opacity": opacity}))?;
|
||||
}
|
||||
active_layer(&s)
|
||||
})();
|
||||
let top = match built {
|
||||
Ok(l) => l,
|
||||
Err(e) => return b.errors.push((name.into(), e)),
|
||||
};
|
||||
let mut harness = egui_kittest::Harness::builder().with_size(egui::vec2(1440.0, 900.0)).with_max_steps(4).build_eframe(move |cc| {
|
||||
photocraft_ui_egui::PhotocraftApp::setup_context(&cc.egui_ctx, Default::default());
|
||||
photocraft_ui_egui::PhotocraftApp::new(s, photocraft_ui_egui::Services::default())
|
||||
});
|
||||
harness.run_steps(6);
|
||||
b.current = Some(name.to_string());
|
||||
b.sampler.reset();
|
||||
let mut samples = Vec::new();
|
||||
let pixels = u64::from(w) * u64::from(h);
|
||||
let run = (|| -> Res<()> {
|
||||
for i in 0..10 {
|
||||
harness.state_mut().run("layer.setProps", json!({"layer": top, "visible": i % 2 == 1}))?;
|
||||
harness.state_mut().perf.last_refresh_px = 0;
|
||||
let t = Instant::now();
|
||||
harness.step();
|
||||
samples.push(ms(t));
|
||||
// A damage refresh counts its reduced texels times the factor squared, which can fall
|
||||
// a few rows and columns short of the document when the factor doesn't divide it.
|
||||
let perf = &harness.state().perf;
|
||||
if !matches!(perf.last_refresh, "full" | "rect") || perf.last_refresh_px.saturating_mul(100) < pixels.saturating_mul(95) {
|
||||
return Err(format!("frame {i} refreshed {} px ({}), not the whole {pixels} px on the CPU", perf.last_refresh_px, perf.last_refresh));
|
||||
}
|
||||
}
|
||||
Ok(())
|
||||
})();
|
||||
let st = std::mem::take(&mut harness.state_mut().session);
|
||||
b.record(name, &st, &samples, run);
|
||||
}
|
||||
|
||||
/// The whole app (kittest harness, CPU canvas) with a 24 MP document: frame times while a
|
||||
|
||||
@@ -122,6 +122,7 @@ impl PhotocraftApp {
|
||||
synthetic_reinject: false,
|
||||
synthetic_snapshot: None,
|
||||
automation_input: false,
|
||||
run_depth: 0,
|
||||
paused_playbacks: Default::default(),
|
||||
channel_thumbs: None,
|
||||
channel_views: HashMap::new(),
|
||||
@@ -174,6 +175,7 @@ impl PhotocraftApp {
|
||||
perf: Default::default(),
|
||||
stroke_trace: stroke_trace::StrokeTrace::from_env(),
|
||||
render_path: Default::default(),
|
||||
slow_frames: Default::default(),
|
||||
prefs_rt: Default::default(),
|
||||
updates_rt: Default::default(),
|
||||
discard: None,
|
||||
@@ -256,11 +258,9 @@ impl eframe::App for PhotocraftApp {
|
||||
if self.custom_titlebar {
|
||||
titlebar::release_after_os_resize(ctx, raw_input);
|
||||
}
|
||||
if self.stroke_trace.enabled() {
|
||||
// The OS's moves and the control channel's (injected just above).
|
||||
let moves = raw_input.events.iter().filter(|e| matches!(e, egui::Event::PointerMoved(_))).count();
|
||||
self.stroke_trace.begin_frame(frame_start, moves);
|
||||
}
|
||||
// The OS's moves and the control channel's (injected just above).
|
||||
let moves = raw_input.events.iter().filter(|e| matches!(e, egui::Event::PointerMoved(_))).count();
|
||||
self.perf.stage.start(frame_start, moves);
|
||||
}
|
||||
|
||||
fn ui(&mut self, ui: &mut egui::Ui, frame: &mut eframe::Frame) {
|
||||
|
||||
@@ -35,6 +35,13 @@ impl PhotocraftApp {
|
||||
}
|
||||
|
||||
pub(crate) fn run_command(&mut self, id: &str, params: Value) -> Result<Value, String> {
|
||||
self.run_depth += 1;
|
||||
let r = self.run_command_at_depth(id, params);
|
||||
self.run_depth -= 1;
|
||||
r
|
||||
}
|
||||
|
||||
fn run_command_at_depth(&mut self, id: &str, params: Value) -> Result<Value, String> {
|
||||
if !vector_ui::cancel_stale(self) {
|
||||
return Err(self.ui.status.clone());
|
||||
}
|
||||
@@ -121,6 +128,9 @@ impl PhotocraftApp {
|
||||
self.sync_command_side_effects(id, &r, creates_active_mask, creates_active_vector_mask, creates_adjustment_or_fill, path_mask);
|
||||
self.perf.last_command = id.to_string();
|
||||
self.perf.command_ms = gpu_canvas::now_ms() - t0;
|
||||
if self.run_depth == 1 {
|
||||
self.perf.stage.command(id, self.perf.command_ms);
|
||||
}
|
||||
match &r {
|
||||
Ok(_) => {
|
||||
if self.ui.status_error {
|
||||
|
||||
@@ -1,4 +1,4 @@
|
||||
use super::{ControlRequest, PhotocraftApp, Receiver};
|
||||
use super::{ControlRequest, PhotocraftApp, Receiver, gpu_canvas};
|
||||
|
||||
impl PhotocraftApp {
|
||||
/// Attach a control channel (requests arrive from a transport thread: TCP, stdin, tests).
|
||||
@@ -7,6 +7,19 @@ impl PhotocraftApp {
|
||||
self
|
||||
}
|
||||
|
||||
/// Close this frame's stage record (`frame_stages`): keep it if it was slow, and hand it to
|
||||
/// the stroke trace. `ui_ms` is the UI build's time.
|
||||
pub(crate) fn finish_frame(&mut self, ui_ms: f64) {
|
||||
let mut stages = std::mem::take(&mut self.perf.stage);
|
||||
stages.ui_ms = ui_ms;
|
||||
let stages = self.slow_frames.finish(stages, gpu_canvas::now_ms(), self.perf.gpu, self.perf.gpu_ms);
|
||||
let info = &self.perf.gpu_info;
|
||||
self.stroke_trace.frame(&stages, self.live_stroke.is_some(), || {
|
||||
let gpu = format!("{} {}", info.backend, info.adapter).trim().to_string();
|
||||
if info.present.is_empty() { gpu } else { format!("{gpu}, {}", info.present) }
|
||||
});
|
||||
}
|
||||
|
||||
pub(crate) fn drain_control(&mut self, ctx: &egui::Context) {
|
||||
let Some(rx) = self.control_rx.take() else { return };
|
||||
while let Ok(req) = rx.try_recv() {
|
||||
|
||||
@@ -167,13 +167,67 @@ impl PhotocraftApp {
|
||||
self.automation_input = false;
|
||||
// No editor was drawn this pass: end its IME context rather than keep a stale owner.
|
||||
type_tool::sync_ime(self, &ctx);
|
||||
// The frame's stage record was started with its input: close it here too.
|
||||
self.finish_frame(0.0);
|
||||
return;
|
||||
}
|
||||
let t0 = gpu_canvas::now_ms();
|
||||
self.perf.frame_refresh_ms = 0.0;
|
||||
self.perf.stage.ui_start(t0, frame.info().cpu_usage);
|
||||
// A software adapter or CPU mode chosen at startup is every document's reason.
|
||||
crate::render_path::frame(self);
|
||||
self.stroke_trace.cpu_prev(frame.info().cpu_usage);
|
||||
// Every frame that started its stage record closes it, whichever way `ui_body` returns.
|
||||
let drawn = self.ui_body(ui);
|
||||
let ui_ms = gpu_canvas::now_ms() - t0;
|
||||
// A GPU measurement lands a frame or two after the refresh it belongs to. Refreshes
|
||||
// carry them out, but the last refresh before the app settles has none following it, so
|
||||
// drain the timer here too or its number is never reported. Drain it either way: a
|
||||
// measurement left sitting would surface later against an unrelated refresh. Report it
|
||||
// only while the canvas is still on the GPU, since a CPU refresh clears `gpu_ms`
|
||||
// precisely so a GPU number is never shown as that refresh's.
|
||||
if let Some(gpu) = &self.gpu
|
||||
&& let Some(t) = gpu.take_gpu_timing()
|
||||
&& self.perf.last_refresh.starts_with("gpu")
|
||||
{
|
||||
self.perf.record_gpu(t);
|
||||
}
|
||||
self.perf.frame(ui_ms);
|
||||
self.finish_frame(ui_ms);
|
||||
if !drawn {
|
||||
return;
|
||||
}
|
||||
// This pass handled its input: the in-flight synthetic batch is delivered once and the
|
||||
// next step may be injected on the next frame.
|
||||
self.finish_synthetic_pass();
|
||||
// Synthetic input is injected one press/release step per frame: keep frames coming until
|
||||
// the queue is empty, then release control replies waiting on it.
|
||||
// Only a pass that reached the end of the UI and delivered the in-flight batch counts as
|
||||
// settled input; an early-returning pass keeps the batch (and the waiting replies).
|
||||
if !self.synthetic.is_empty() || self.synthetic_batch.is_some() {
|
||||
ctx.request_repaint();
|
||||
} else if !self.input_waiters.is_empty() {
|
||||
for w in self.input_waiters.drain(..) {
|
||||
let _ = w.send(serde_json::json!({"ok": true, "result": null}));
|
||||
}
|
||||
}
|
||||
// A menu or dialog can start a filter after `jobs_ui::tick` ran in this frame. Keep
|
||||
// polling it even when the platform would otherwise put the event loop to sleep.
|
||||
jobs_ui::keep_polling(self, &ctx);
|
||||
// Menus and buttons in this frame may have asked for a file dialog.
|
||||
self.poll_file_dialog(&ctx, Some(frame));
|
||||
// The Type tool's IME descriptor is the last writer of this pass: every panel and the
|
||||
// canvas have finished mutating the model, and an absent/focus-moved editor ends here.
|
||||
type_tool::sync_ime(self, &ctx);
|
||||
// Issue any due `ui.screenshot` now that this pass's state is settled: a queued request
|
||||
// that has waited its passes and animation delay captures exactly this frame.
|
||||
self.issue_captures(&ctx);
|
||||
// Last, after everything drawn this frame: a lost window device can't draw it (#3438).
|
||||
gpu_status::check_window(self, &ctx);
|
||||
}
|
||||
|
||||
/// The frame's UI, between `ui_start` and `finish_frame`. False when the screen picker's
|
||||
/// wait modal took the frame (its input, IME and window check already handled).
|
||||
fn ui_body(&mut self, ui: &mut egui::Ui) -> bool {
|
||||
let ctx = ui.ctx().clone();
|
||||
// A text field's right-click menu, before any field is drawn (text_field_menu.rs).
|
||||
text_field_menu::show(&ctx);
|
||||
// The wheel goes to a focused value field before the canvas or a panel sees it (#5473).
|
||||
@@ -204,7 +258,7 @@ impl PhotocraftApp {
|
||||
self.automation_input = false;
|
||||
type_tool::sync_ime(self, &ctx);
|
||||
gpu_status::check_window(self, &ctx);
|
||||
return;
|
||||
return false;
|
||||
}
|
||||
if screen_picker::busy(&ctx) {
|
||||
ui.disable();
|
||||
@@ -299,54 +353,6 @@ impl PhotocraftApp {
|
||||
egui::Modal::new(egui::Id::unique("screen-color-wait")).frame(egui::Frame::NONE).backdrop_color(egui::Color32::TRANSPARENT).show(&ctx, |_| {});
|
||||
ctx.set_cursor_icon(egui::CursorIcon::Wait);
|
||||
}
|
||||
let ui_ms = gpu_canvas::now_ms() - t0;
|
||||
// A GPU measurement lands a frame or two after the refresh it belongs to. Refreshes
|
||||
// carry them out, but the last refresh before the app settles has none following it, so
|
||||
// drain the timer here too or its number is never reported. Drain it either way: a
|
||||
// measurement left sitting would surface later against an unrelated refresh. Report it
|
||||
// only while the canvas is still on the GPU, since a CPU refresh clears `gpu_ms`
|
||||
// precisely so a GPU number is never shown as that refresh's.
|
||||
if let Some(gpu) = &self.gpu
|
||||
&& let Some(t) = gpu.take_gpu_timing()
|
||||
&& self.perf.last_refresh.starts_with("gpu")
|
||||
{
|
||||
self.perf.record_gpu(t);
|
||||
}
|
||||
self.perf.frame(ui_ms);
|
||||
if self.stroke_trace.enabled() {
|
||||
self.stroke_trace.canvas(self.perf.frame_refresh_ms);
|
||||
let info = &self.perf.gpu_info;
|
||||
self.stroke_trace.end_frame(ui_ms, self.live_stroke.is_some(), || {
|
||||
let gpu = format!("{} {}", info.backend, info.adapter).trim().to_string();
|
||||
if info.present.is_empty() { gpu } else { format!("{gpu}, {}", info.present) }
|
||||
});
|
||||
}
|
||||
// This pass handled its input: the in-flight synthetic batch is delivered once and the
|
||||
// next step may be injected on the next frame.
|
||||
self.finish_synthetic_pass();
|
||||
// Synthetic input is injected one press/release step per frame: keep frames coming until
|
||||
// the queue is empty, then release control replies waiting on it.
|
||||
// Only a pass that reached the end of the UI and delivered the in-flight batch counts as
|
||||
// settled input; an early-returning pass keeps the batch (and the waiting replies).
|
||||
if !self.synthetic.is_empty() || self.synthetic_batch.is_some() {
|
||||
ctx.request_repaint();
|
||||
} else if !self.input_waiters.is_empty() {
|
||||
for w in self.input_waiters.drain(..) {
|
||||
let _ = w.send(serde_json::json!({"ok": true, "result": null}));
|
||||
}
|
||||
}
|
||||
// A menu or dialog can start a filter after `jobs_ui::tick` ran in this frame. Keep
|
||||
// polling it even when the platform would otherwise put the event loop to sleep.
|
||||
jobs_ui::keep_polling(self, &ctx);
|
||||
// Menus and buttons in this frame may have asked for a file dialog.
|
||||
self.poll_file_dialog(&ctx, Some(frame));
|
||||
// The Type tool's IME descriptor is the last writer of this pass: every panel and the
|
||||
// canvas have finished mutating the model, and an absent/focus-moved editor ends here.
|
||||
type_tool::sync_ime(self, &ctx);
|
||||
// Issue any due `ui.screenshot` now that this pass's state is settled: a queued request
|
||||
// that has waited its passes and animation delay captures exactly this frame.
|
||||
self.issue_captures(&ctx);
|
||||
// Last, after everything drawn this frame: a lost window device can't draw it (#3438).
|
||||
gpu_status::check_window(self, &ctx);
|
||||
true
|
||||
}
|
||||
}
|
||||
|
||||
@@ -68,9 +68,9 @@ pub struct Perf {
|
||||
pub spans: std::collections::BTreeMap<&'static str, f64>,
|
||||
#[serde(skip)]
|
||||
max_decay: f64,
|
||||
/// Composite and upload time of this frame's canvas refreshes, in ms (the stroke trace).
|
||||
/// This frame's stages, gathered as it runs (see `frame_stages`).
|
||||
#[serde(skip)]
|
||||
pub(crate) frame_refresh_ms: f64,
|
||||
pub(crate) stage: crate::frame_stages::FrameStages,
|
||||
}
|
||||
|
||||
/// What the app renders with and why (Help › System Info, Preferences › Performance, the `perf`
|
||||
@@ -214,7 +214,7 @@ pub fn backend_name(b: wgpu::Backend) -> &'static str {
|
||||
|
||||
impl Perf {
|
||||
pub fn record(&mut self, kind: &'static str, px: u64, composite_ms: f64, upload_ms: f64) {
|
||||
self.frame_refresh_ms += composite_ms + upload_ms;
|
||||
self.stage.refresh(kind, px, composite_ms, upload_ms);
|
||||
self.last_refresh = kind;
|
||||
self.last_refresh_px = px;
|
||||
self.composite_ms = composite_ms;
|
||||
|
||||
@@ -406,7 +406,7 @@ pub(super) fn feed_live_stroke(app: &mut PhotocraftApp) {
|
||||
}
|
||||
}
|
||||
}
|
||||
app.stroke_trace.stroke(crate::gpu_canvas::now_ms() - started);
|
||||
app.perf.stage.stroke_ms += crate::gpu_canvas::now_ms() - started;
|
||||
}
|
||||
|
||||
/// The points the live retouching stroke has rendered.
|
||||
@@ -603,7 +603,7 @@ pub(super) fn commit_brush_stroke(app: &mut PhotocraftApp, d: &Drag) {
|
||||
}
|
||||
let started = crate::gpu_canvas::now_ms();
|
||||
let result = app.run(stroke_command(app, d.tool), p);
|
||||
app.stroke_trace.stroke(crate::gpu_canvas::now_ms() - started);
|
||||
app.perf.stage.stroke_ms += crate::gpu_canvas::now_ms() - started;
|
||||
app.session.clear_live_stroke();
|
||||
let Ok(r) = result else { return };
|
||||
let after = app.session.documents().iter().find(|st| st.doc.id == doc).map(|st| (st.revision, st.doc.clone()));
|
||||
|
||||
@@ -175,15 +175,15 @@ fn inline_filter_preview_is_composited_and_recorded_once() {
|
||||
app.background_jobs = false;
|
||||
app.run("file.new", json!({"width": 320, "height": 240})).unwrap();
|
||||
crate::filter_dialog::open(&mut app, "filter.stylize.solarize").unwrap();
|
||||
app.perf.frame_refresh_ms = 0.0;
|
||||
app.perf.stage = Default::default();
|
||||
let (_, _, size) = ensure_filter_preview(&mut app, 0, &egui::Context::default()).expect("a preview");
|
||||
assert_eq!(size, [320, 240]);
|
||||
assert_eq!(app.perf.last_refresh, "filter-preview");
|
||||
assert_eq!(app.perf.last_refresh_px, 320 * 240);
|
||||
assert_eq!(app.perf.frame_refresh_ms, app.perf.composite_ms + app.perf.upload_ms, "one record per preview");
|
||||
assert_eq!(app.perf.stage.composite_ms + app.perf.stage.upload_ms, app.perf.composite_ms + app.perf.upload_ms, "one record per preview");
|
||||
// Unchanged request: nothing is recomputed or recorded again.
|
||||
ensure_filter_preview(&mut app, 0, &egui::Context::default()).expect("the same preview");
|
||||
assert_eq!(app.perf.frame_refresh_ms, app.perf.composite_ms + app.perf.upload_ms);
|
||||
assert_eq!(app.perf.stage.composite_ms + app.perf.stage.upload_ms, app.perf.composite_ms + app.perf.upload_ms);
|
||||
}
|
||||
|
||||
/// #6326: a filter's live preview is never coarser than the screen. On a document big enough
|
||||
|
||||
@@ -466,10 +466,12 @@ pub(super) fn ensure_gpu(app: &mut PhotocraftApp, ctx: &egui::Context, idx: usiz
|
||||
// The texture is shared by every display: only what it stores counts, not the monitor.
|
||||
let display_key = texture_key(display.as_deref());
|
||||
let seen = app.canvases.get(&(id, GPU_OUTPUT)).map(|c| (c.revision, c.preview_key));
|
||||
let damage_start = crate::gpu_canvas::now_ms();
|
||||
let mut damage = seen.and_then(|seen| damage_since(app, idx, seen, (revision, raw_key), display_key, last_damage));
|
||||
if let Some(region) = damage {
|
||||
damage = Some(crate::blend_preview::clip_damage(app, id, revision, raw_key, region, blend_visible));
|
||||
}
|
||||
app.perf.stage.damage_ms += crate::gpu_canvas::now_ms() - damage_start;
|
||||
// To an adjustment dialog's preview: only what the view shows now (the rest as it moves there).
|
||||
if damage.is_some()
|
||||
&& let Some(r) = seen.filter(|s| s.0 == revision).and_then(|s| crate::adjust_preview::switch_region(app, id, revision, s.1 ^ display_key, raw_key))
|
||||
@@ -551,7 +553,9 @@ pub(super) fn ensure_gpu(app: &mut PhotocraftApp, ctx: &egui::Context, idx: usiz
|
||||
return false;
|
||||
}
|
||||
let partial = present && damage.is_some();
|
||||
let budget_start = crate::gpu_canvas::now_ms();
|
||||
gpu_budget(app, &gpu, idx, partial, visible);
|
||||
app.perf.stage.damage_ms += crate::gpu_canvas::now_ms() - budget_start;
|
||||
let defer = crate::background_redraw::enabled(app);
|
||||
let r = gpu.refresh_with(id.0, &doc, if partial { damage } else { None }, display.as_deref(), defer);
|
||||
app.perf.gpu_layer_fit = gpu.layer_fit();
|
||||
|
||||
@@ -88,7 +88,13 @@ pub fn inspect(app: &PhotocraftApp, ctx: &egui::Context) -> Value {
|
||||
"frame": app.frame,
|
||||
"session": photocraft_engine::inspect::session(&app.session),
|
||||
"document": app.session.active().map(photocraft_engine::inspect::document),
|
||||
"perf": {"fps": app.fps, "timings": app.perf, "strokeTrace": app.stroke_trace.last, "renderPath": crate::render_path::inspect(app)},
|
||||
"perf": {
|
||||
"fps": app.fps,
|
||||
"timings": app.perf,
|
||||
"strokeTrace": app.stroke_trace.last,
|
||||
"renderPath": crate::render_path::inspect(app),
|
||||
"slowFrames": app.slow_frames,
|
||||
},
|
||||
"brush": {"size": app.session.tools.brush.size, "hardness": app.session.tools.brush.hardness, "opacity": app.session.tools.brush.opacity},
|
||||
"distort": app.distort.describe(),
|
||||
"jobs": crate::jobs_ui::inspect(app),
|
||||
|
||||
@@ -28,6 +28,39 @@ fn ui_set_turns_the_stroke_trace_on_and_off_at_runtime() {
|
||||
assert!(!app.stroke_trace.enabled() && app.ui.tool != crate::state::Tool::Pencil, "a rejected call applies nothing");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn perf_output_includes_slow_frames() {
|
||||
let mut app = PhotocraftApp::new(photocraft_engine::Session::new(), crate::Services::default());
|
||||
let ctx = egui::Context::default();
|
||||
assert_eq!(call(&mut app, &ctx, "ui.inspect", json!({}))["result"]["perf"]["slowFrames"], json!([]));
|
||||
app.slow_frames.set_threshold_ms(0.0);
|
||||
app.run("file.new", json!({"width": 64, "height": 32})).unwrap();
|
||||
app.finish_frame(1.0);
|
||||
let frames = call(&mut app, &ctx, "ui.inspect", json!({}))["result"]["perf"]["slowFrames"].clone();
|
||||
let last = frames.as_array().and_then(|f| f.last()).expect("a slow frame").clone();
|
||||
assert_eq!(last["command"], "file.new", "{last}");
|
||||
for key in ["t", "frameMs", "inputMs", "commandMs", "damageMs", "compositeMs", "uploadMs", "gpuMs", "presentMs", "refresh", "refreshPx", "path"] {
|
||||
assert!(last.get(key).is_some(), "{key} in {last}");
|
||||
}
|
||||
// A nested run (`actions.play` → its view steps through `App::run`) is inside the outer
|
||||
// call's time: the frame counts the outer command once, not the steps again.
|
||||
app.session.actions.list.push(photocraft_engine::actions_cmds::Action {
|
||||
name: "Zoom".into(),
|
||||
steps: vec![("view.zoomIn".into(), json!({})), ("view.zoomOut".into(), json!({}))],
|
||||
disabled: Default::default(),
|
||||
..Default::default()
|
||||
});
|
||||
let played = app.run("actions.play", json!({"action": "Zoom"})).unwrap();
|
||||
assert_eq!(played["ran"], 2, "{played}");
|
||||
let outer_ms = app.perf.command_ms;
|
||||
app.finish_frame(1.0);
|
||||
let frames = call(&mut app, &ctx, "ui.inspect", json!({}))["result"]["perf"]["slowFrames"].clone();
|
||||
let last = frames.as_array().and_then(|f| f.last()).expect("a slow frame").clone();
|
||||
assert_eq!(last["command"], "actions.play", "{last}");
|
||||
let command_ms = last["commandMs"].as_f64().unwrap();
|
||||
assert!((command_ms - outer_ms).abs() < 1e-9, "the outer run's {outer_ms} ms, once: {last}");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn camera_raw_control_updates_and_commits_or_cancels_an_open_raw() {
|
||||
use photocraft_raw::testgen::{DngSpec, mosaic, scene};
|
||||
|
||||
@@ -0,0 +1,323 @@
|
||||
//! Where each frame's time goes (#9328), gathered every frame, and the slow ones kept.
|
||||
//!
|
||||
//! [`FrameStages`] is one frame's record. Each stage has one writer: the raw input hook starts
|
||||
//! the frame, `App::run` adds commands, the GPU canvas path adds damage tracking and budgeting,
|
||||
//! [`crate::gpu_canvas::Perf::record`] adds composites and uploads, and the canvas adds stroke
|
||||
//! rendering. `App::ui` closes it ([`SlowFrames::finish`]). A frame over [`SLOW_FRAME_MS`] goes
|
||||
//! into [`SlowFrames`], the last [`SLOW_FRAMES`] of them, which the control channel's `perf`
|
||||
//! output lists as `slowFrames`; one `info` log line per second names them. The stroke trace
|
||||
//! (`stroke_trace`) reads the same record, so the app times a frame in one place.
|
||||
//!
|
||||
//! On the web `now_ms()` is 0, so no frame is ever slow and the ring stays empty.
|
||||
|
||||
use std::collections::VecDeque;
|
||||
|
||||
/// A frame slower than this (ms) is kept and logged.
|
||||
pub const SLOW_FRAME_MS: f64 = 50.0;
|
||||
/// How many slow frames are kept.
|
||||
pub const SLOW_FRAMES: usize = 64;
|
||||
/// At most one slow-frame log line per this many ms.
|
||||
const LOG_EVERY_MS: f64 = 1000.0;
|
||||
|
||||
/// One frame's stages. Times in ms.
|
||||
#[derive(Clone, Debug, Default, PartialEq, serde::Serialize)]
|
||||
#[serde(rename_all = "camelCase")]
|
||||
pub struct FrameStages {
|
||||
/// Frame start (the raw input hook), from [`crate::gpu_canvas::now_ms`].
|
||||
pub t: f64,
|
||||
/// The whole frame: from its start until its UI is built. Never less than the stages below
|
||||
/// (a command run between frames counts toward the next one).
|
||||
pub frame_ms: f64,
|
||||
/// From the raw input hook to the start of the UI build (input handling, minus commands).
|
||||
pub input_ms: f64,
|
||||
/// Commands run through the app since the previous frame ended.
|
||||
pub command_ms: f64,
|
||||
/// The last of those commands ("" for none).
|
||||
pub command: String,
|
||||
/// Damage tracking and GPU memory budgeting on the GPU canvas path.
|
||||
pub damage_ms: f64,
|
||||
/// Canvas composites, CPU side (on the GPU path: encoding and submitting them).
|
||||
pub composite_ms: f64,
|
||||
/// Canvas conversions and uploads.
|
||||
pub upload_ms: f64,
|
||||
/// The GPU's own time for a recent composite, when the canvas is on the GPU and it reports one.
|
||||
pub gpu_ms: Option<f64>,
|
||||
/// eframe's CPU time for the previous frame minus that frame's UI build: tessellation and
|
||||
/// GPU submission (the previous frame's, so it isn't part of `frame_ms`).
|
||||
pub present_ms: Option<f64>,
|
||||
/// The last canvas refresh's kind ("full", "rect", "gpu-full", …; "" for none).
|
||||
pub refresh: &'static str,
|
||||
/// Pixels the frame's canvas refreshes covered.
|
||||
pub refresh_px: u64,
|
||||
/// "gpu" or "cpu": who drew the canvas.
|
||||
pub path: &'static str,
|
||||
/// Building the UI (`App::ui`), the canvas refresh included.
|
||||
#[serde(skip)]
|
||||
pub ui_ms: f64,
|
||||
/// Rendering stroke points (the stroke trace's `stroke`).
|
||||
#[serde(skip)]
|
||||
pub stroke_ms: f64,
|
||||
/// Pointer moves the frame delivered.
|
||||
#[serde(skip)]
|
||||
pub moves: usize,
|
||||
/// eframe's CPU time for the previous frame.
|
||||
#[serde(skip)]
|
||||
pub cpu_prev_ms: Option<f64>,
|
||||
/// The raw input hook ran for this frame.
|
||||
#[serde(skip)]
|
||||
started: bool,
|
||||
}
|
||||
|
||||
impl FrameStages {
|
||||
/// The raw input hook: the frame starts at `now` with `moves` pointer moves.
|
||||
pub fn start(&mut self, now: f64, moves: usize) {
|
||||
self.t = now;
|
||||
self.moves = moves;
|
||||
self.started = true;
|
||||
}
|
||||
|
||||
/// The UI build starts at `now`; `cpu_prev` is eframe's CPU time for the previous frame, in s.
|
||||
pub fn ui_start(&mut self, now: f64, cpu_prev: Option<f32>) {
|
||||
if !self.started {
|
||||
self.start(now, 0);
|
||||
}
|
||||
self.input_ms = (now - self.t - self.command_ms).max(0.0);
|
||||
self.cpu_prev_ms = cpu_prev.map(|s| f64::from(s) * 1000.0);
|
||||
}
|
||||
|
||||
/// A command `id` ran for `ms`.
|
||||
pub fn command(&mut self, id: &str, ms: f64) {
|
||||
self.command_ms += ms;
|
||||
id.clone_into(&mut self.command);
|
||||
}
|
||||
|
||||
/// A canvas refresh of kind `kind` and `px` pixels.
|
||||
pub fn refresh(&mut self, kind: &'static str, px: u64, composite_ms: f64, upload_ms: f64) {
|
||||
self.composite_ms += composite_ms;
|
||||
self.upload_ms += upload_ms;
|
||||
self.refresh = kind;
|
||||
self.refresh_px += px;
|
||||
}
|
||||
|
||||
/// The stages that make up `frame_ms` (`present_ms` belongs to the previous frame).
|
||||
pub fn stage_ms(&self) -> f64 {
|
||||
self.input_ms + self.command_ms + self.damage_ms + self.composite_ms + self.upload_ms
|
||||
}
|
||||
|
||||
/// The frame ends at `now`.
|
||||
fn end(&mut self, now: f64) {
|
||||
if !self.started {
|
||||
self.t = now;
|
||||
}
|
||||
self.frame_ms = (now - self.t).max(self.stage_ms());
|
||||
}
|
||||
|
||||
/// One line for the log.
|
||||
pub fn line(&self) -> String {
|
||||
let opt = |v: Option<f64>| v.map_or("-".to_string(), |v| format!("{v:.1}"));
|
||||
let command = if self.command.is_empty() { String::new() } else { format!(" ({})", self.command) };
|
||||
format!(
|
||||
"slow frame: {:.1} ms on the {} path: input {:.1}, command {:.1}{command}, damage {:.1}, composite {:.1}, upload {:.1}, gpu {}, present {}; refresh {} {} px",
|
||||
self.frame_ms,
|
||||
self.path,
|
||||
self.input_ms,
|
||||
self.command_ms,
|
||||
self.damage_ms,
|
||||
self.composite_ms,
|
||||
self.upload_ms,
|
||||
opt(self.gpu_ms),
|
||||
opt(self.present_ms),
|
||||
if self.refresh.is_empty() { "none" } else { self.refresh },
|
||||
self.refresh_px,
|
||||
)
|
||||
}
|
||||
}
|
||||
|
||||
/// The last [`SLOW_FRAMES`] frames over the threshold.
|
||||
#[derive(Debug)]
|
||||
pub struct SlowFrames {
|
||||
frames: VecDeque<FrameStages>,
|
||||
threshold_ms: f64,
|
||||
/// The previous frame's UI build (for its `present_ms`).
|
||||
prev_ui_ms: Option<f64>,
|
||||
/// When the last log line went out, and the slow frames since that weren't logged.
|
||||
logged_at: Option<f64>,
|
||||
unlogged: usize,
|
||||
}
|
||||
|
||||
impl Default for SlowFrames {
|
||||
fn default() -> Self {
|
||||
Self { frames: VecDeque::with_capacity(SLOW_FRAMES), threshold_ms: SLOW_FRAME_MS, prev_ui_ms: None, logged_at: None, unlogged: 0 }
|
||||
}
|
||||
}
|
||||
|
||||
impl SlowFrames {
|
||||
/// The kept frames, oldest first.
|
||||
pub fn frames(&self) -> impl DoubleEndedIterator<Item = &FrameStages> {
|
||||
self.frames.iter()
|
||||
}
|
||||
|
||||
/// Keep frames slower than `ms` instead of [`SLOW_FRAME_MS`] (tests).
|
||||
#[cfg(test)]
|
||||
pub(crate) fn set_threshold_ms(&mut self, ms: f64) {
|
||||
self.threshold_ms = ms;
|
||||
}
|
||||
|
||||
/// Close frame `s` at `now`: `gpu` says the canvas is on the GPU, `gpu_ms` is the GPU's
|
||||
/// latest composite time. A slow frame is kept, and logged at most once a second.
|
||||
pub fn finish(&mut self, mut s: FrameStages, now: f64, gpu: bool, gpu_ms: Option<f64>) -> FrameStages {
|
||||
s.end(now);
|
||||
let on_gpu = if s.refresh.is_empty() { gpu } else { s.refresh.starts_with("gpu") };
|
||||
s.path = if on_gpu { "gpu" } else { "cpu" };
|
||||
s.gpu_ms = gpu_ms.filter(|_| on_gpu);
|
||||
s.present_ms = s.cpu_prev_ms.zip(self.prev_ui_ms).map(|(cpu, ui)| (cpu - ui).max(0.0));
|
||||
self.prev_ui_ms = Some(s.ui_ms);
|
||||
if let Some(line) = self.push(&s) {
|
||||
log::info!("{line}");
|
||||
}
|
||||
s
|
||||
}
|
||||
|
||||
/// Keep `s` if it's slow; the log line to write, if one is due.
|
||||
fn push(&mut self, s: &FrameStages) -> Option<String> {
|
||||
if s.frame_ms.is_nan() || s.frame_ms <= self.threshold_ms {
|
||||
return None;
|
||||
}
|
||||
if self.frames.len() == SLOW_FRAMES {
|
||||
self.frames.pop_front();
|
||||
}
|
||||
self.frames.push_back(s.clone());
|
||||
if self.logged_at.is_some_and(|at| s.t - at < LOG_EVERY_MS) {
|
||||
self.unlogged += 1;
|
||||
return None;
|
||||
}
|
||||
let mut line = s.line();
|
||||
if self.unlogged > 0 {
|
||||
line.push_str(&format!(" ({} more slow frames)", self.unlogged));
|
||||
}
|
||||
self.logged_at = Some(s.t);
|
||||
self.unlogged = 0;
|
||||
Some(line)
|
||||
}
|
||||
}
|
||||
|
||||
impl serde::Serialize for SlowFrames {
|
||||
fn serialize<S: serde::Serializer>(&self, ser: S) -> Result<S::Ok, S::Error> {
|
||||
ser.collect_seq(self.frames.iter())
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(test)]
|
||||
mod tests {
|
||||
use super::*;
|
||||
|
||||
fn frame(t: f64, ms: f64) -> FrameStages {
|
||||
let mut s = FrameStages::default();
|
||||
s.start(t, 0);
|
||||
s.ui_start(t + 1.0, None);
|
||||
s.refresh("full", 100, ms / 2.0, 1.0);
|
||||
s
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn slow_frames_keep_the_last_64_over_the_threshold() {
|
||||
let mut r = SlowFrames::default();
|
||||
for k in 0..100 {
|
||||
let t = f64::from(k) * 100.0;
|
||||
r.finish(frame(t, 0.0), t + 60.0 + f64::from(k), false, None);
|
||||
}
|
||||
assert_eq!(r.frames().count(), SLOW_FRAMES);
|
||||
let first = r.frames().next().unwrap();
|
||||
assert_eq!(first.t, 3600.0, "the oldest are dropped");
|
||||
assert_eq!(r.frames().last().unwrap().frame_ms, 159.0);
|
||||
assert!(r.frames().all(|f| f.path == "cpu" && f.refresh_px == 100));
|
||||
let json = serde_json::to_value(&r).unwrap();
|
||||
assert_eq!(json.as_array().map(Vec::len), Some(SLOW_FRAMES));
|
||||
assert_eq!(json[0]["frameMs"], 96.0);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn a_fast_frame_is_not_recorded() {
|
||||
let mut r = SlowFrames::default();
|
||||
let s = r.finish(frame(0.0, 0.0), 49.0, true, Some(3.0));
|
||||
assert_eq!(s.frame_ms, 49.0);
|
||||
assert_eq!(s.path, "cpu", "the refresh says who drew it");
|
||||
assert_eq!(s.gpu_ms, None, "no GPU time for a CPU refresh");
|
||||
r.finish(frame(100.0, 0.0), 150.0, false, None);
|
||||
assert_eq!(r.frames().count(), 0, "exactly 50 ms isn't over");
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn stages_never_exceed_the_frame() {
|
||||
let mut r = SlowFrames::default();
|
||||
// A command run between frames (before the hook) makes the stages longer than the clock.
|
||||
let mut s = FrameStages::default();
|
||||
s.command("layer.setProps", 80.0);
|
||||
s.start(1000.0, 2);
|
||||
s.ui_start(1005.0, Some(0.004));
|
||||
s.damage_ms = 2.0;
|
||||
s.refresh("gpu-full", 12, 30.0, 10.0);
|
||||
s.ui_ms = 40.0;
|
||||
let s = r.finish(s, 1050.0, true, Some(7.0));
|
||||
assert!(s.stage_ms() <= s.frame_ms, "{s:?}");
|
||||
assert_eq!((s.input_ms, s.frame_ms, s.path, s.gpu_ms), (0.0, 122.0, "gpu", Some(7.0)));
|
||||
assert_eq!(s.present_ms, None, "no previous frame");
|
||||
let mut next = frame(1100.0, 4.0);
|
||||
next.cpu_prev_ms = Some(45.0);
|
||||
let next = r.finish(next, 1110.0, true, None);
|
||||
assert_eq!(next.present_ms, Some(5.0), "the previous frame's CPU time minus its UI build");
|
||||
assert!(next.stage_ms() <= next.frame_ms);
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn slow_frame_log_is_rate_limited() {
|
||||
let mut r = SlowFrames::default();
|
||||
let lines: Vec<String> = (0..10)
|
||||
.filter_map(|k| {
|
||||
let mut s = frame(f64::from(k) * 100.0, 0.0);
|
||||
s.end(s.t + 60.0);
|
||||
r.push(&s)
|
||||
})
|
||||
.collect();
|
||||
assert_eq!(lines.len(), 1, "{lines:?}");
|
||||
assert!(lines[0].starts_with("slow frame: 60.0 ms") && !lines[0].contains("more"), "{}", lines[0]);
|
||||
let mut s = frame(1000.0, 0.0);
|
||||
s.end(1070.0);
|
||||
let line = r.push(&s).expect("a second later, the next line");
|
||||
assert!(line.ends_with("(9 more slow frames)"), "{line}");
|
||||
assert_eq!(r.frames().count(), 11);
|
||||
}
|
||||
}
|
||||
|
||||
#[cfg(all(test, not(target_arch = "wasm32")))]
|
||||
mod app_tests {
|
||||
use serde_json::json;
|
||||
|
||||
use crate::PhotocraftApp;
|
||||
|
||||
#[test]
|
||||
fn an_app_frame_with_a_full_refresh_records_its_stages() {
|
||||
let (w, h) = (4000u64, 3000u64);
|
||||
let mut s = photocraft_engine::Session::new();
|
||||
s.execute("file.new", json!({"width": w, "height": h, "background": "white"})).unwrap();
|
||||
let layer = s.active().and_then(|d| d.active_layer).expect("the background").0;
|
||||
let mut harness = egui_kittest::Harness::builder().with_size(egui::vec2(1440.0, 900.0)).with_max_steps(4).build_eframe(move |cc| {
|
||||
PhotocraftApp::setup_context(&cc.egui_ctx, Default::default());
|
||||
PhotocraftApp::new(s, crate::Services::default())
|
||||
});
|
||||
harness.run_steps(6);
|
||||
// Every frame counts as slow, so the test doesn't depend on the machine's speed.
|
||||
harness.state_mut().slow_frames.set_threshold_ms(0.0);
|
||||
harness.state_mut().run("layer.setProps", json!({"layer": layer, "visible": false})).unwrap();
|
||||
harness.step();
|
||||
let app = harness.state();
|
||||
let f = app.slow_frames.frames().rev().find(|f| f.command == "layer.setProps").expect("the toggle's frame is kept").clone();
|
||||
// The CPU canvas (kittest has no wgpu) redraws the whole document. A damage refresh counts
|
||||
// reduced texels times the factor squared, which can fall a few rows short (see P80).
|
||||
assert_eq!(f.path, "cpu", "{f:?}");
|
||||
assert!(matches!(f.refresh, "full" | "rect"), "{f:?}");
|
||||
assert!(f.refresh_px * 100 >= w * h * 95 && f.refresh_px <= w * h, "{f:?}");
|
||||
assert!(f.composite_ms > 0.0 && f.command_ms > 0.0, "{f:?}");
|
||||
assert!(f.stage_ms() <= f.frame_ms, "{f:?}");
|
||||
}
|
||||
}
|
||||
@@ -19,6 +19,7 @@ pub mod dialogs;
|
||||
pub mod dock;
|
||||
pub mod file_dialog;
|
||||
pub mod file_open;
|
||||
pub mod frame_stages;
|
||||
pub mod gpu_status;
|
||||
pub mod i18n;
|
||||
mod icon_data;
|
||||
@@ -504,6 +505,10 @@ pub struct PhotocraftApp {
|
||||
/// makes shortcut- and dialog-triggered commands pass the same policy as
|
||||
/// direct control calls.
|
||||
pub(crate) automation_input: bool,
|
||||
/// How many `run_command` calls are on the stack. Only the outermost one writes the frame's
|
||||
/// command stage: a nested run (`file.save` → `layer.smartObjects.saveContents`,
|
||||
/// `actions.play` → its steps) is already inside the outer call's time.
|
||||
run_depth: u32,
|
||||
/// Action playbacks paused at a step dialog, by the token in that dialog's fields
|
||||
/// ([`actions::RESUME`]): what to play next and the automation gate it paused under.
|
||||
pub(crate) paused_playbacks: actions::PausedPlaybacks,
|
||||
@@ -618,6 +623,8 @@ pub struct PhotocraftApp {
|
||||
pub stroke_trace: stroke_trace::StrokeTrace,
|
||||
/// Why each document's view is drawn on the CPU, and the history of changes (`render_path`).
|
||||
pub render_path: render_path::RenderPath,
|
||||
/// The last slow frames and their stages (`perf.slowFrames`, see `frame_stages`).
|
||||
pub slow_frames: frame_stages::SlowFrames,
|
||||
/// Preferences, autosave and snapping runtime state (see `prefs_ui`, `snap_ui`).
|
||||
pub(crate) prefs_rt: prefs_ui::Runtime,
|
||||
pub(crate) updates_rt: updates_ui::Runtime,
|
||||
|
||||
@@ -387,11 +387,10 @@ fn the_stroke_trace_times_each_frame_of_a_stroke_and_ends_on_release() {
|
||||
}
|
||||
let t0 = crate::gpu_canvas::now_ms();
|
||||
let moves = ctx.input(|i| i.raw.events.iter().filter(|e| matches!(e, egui::Event::PointerMoved(_))).count());
|
||||
app.stroke_trace.begin_frame(t0, moves);
|
||||
app.stroke_trace.cpu_prev(Some(0.004));
|
||||
app.perf.stage.start(t0, moves);
|
||||
app.perf.stage.ui_start(t0, Some(0.004));
|
||||
egui::CentralPanel::default().show(ui, |ui| crate::canvas::document_area(app, ui));
|
||||
let stroking = app.live_stroke.is_some();
|
||||
app.stroke_trace.end_frame(crate::gpu_canvas::now_ms() - t0, stroking, || "test".into());
|
||||
app.finish_frame(crate::gpu_canvas::now_ms() - t0);
|
||||
},
|
||||
app,
|
||||
);
|
||||
@@ -409,7 +408,7 @@ fn the_stroke_trace_times_each_frame_of_a_stroke_and_ends_on_release() {
|
||||
assert!(s.frames >= 6, "{s:?}");
|
||||
assert!(s.stroke[1] > 0.0 && s.ui[0] >= s.stroke[0], "{s:?}");
|
||||
assert_eq!(s.moves[1], 1.0, "one move per test frame: {s:?}");
|
||||
assert_eq!(s.backend, "test");
|
||||
assert_eq!(s.backend, "", "the app's adapter (none in a test)");
|
||||
}
|
||||
|
||||
/// A Clone Stamp stroke through the canvas renders the points its commit gets (position and
|
||||
|
||||
@@ -11,9 +11,14 @@
|
||||
//! submission, without the vsync wait). What the app can't see (the OS input queue before a frame
|
||||
//! starts, frames queued for the display, the compositor) is the rest of the input-to-photon time;
|
||||
//! the summary names the GPU backend because GL ignores the frame-latency setting.
|
||||
//!
|
||||
//! The trace keeps no clock of its own: each row is the frame's `frame_stages::FrameStages`,
|
||||
//! which the app gathers every frame (the slow-frame ring reads the same record).
|
||||
|
||||
use std::fmt::Write as _;
|
||||
|
||||
use crate::frame_stages::FrameStages;
|
||||
|
||||
/// One frame of a stroke. Times in ms.
|
||||
#[derive(Clone, Debug, Default, PartialEq)]
|
||||
pub(crate) struct Row {
|
||||
@@ -33,6 +38,13 @@ pub(crate) struct Row {
|
||||
pub cpu_prev: Option<f64>,
|
||||
}
|
||||
|
||||
impl Row {
|
||||
/// The trace's row for a frame's stages.
|
||||
pub(crate) fn from_stages(s: &FrameStages, interval: f64) -> Self {
|
||||
Self { t: s.t, interval, moves: s.moves, stroke: s.stroke_ms, canvas: s.composite_ms + s.upload_ms, ui: s.ui_ms, cpu_prev: s.cpu_prev_ms }
|
||||
}
|
||||
}
|
||||
|
||||
/// Percentiles of a stroke's frames, for the summary line and the control channel.
|
||||
#[derive(Clone, Debug, Default, PartialEq, serde::Serialize)]
|
||||
#[serde(rename_all = "camelCase")]
|
||||
@@ -86,8 +98,6 @@ pub(crate) enum Output {
|
||||
#[derive(Debug, Default)]
|
||||
pub struct StrokeTrace {
|
||||
pub(crate) output: Output,
|
||||
/// The frame being built (started by `begin_frame`).
|
||||
frame: Option<Row>,
|
||||
last_start: Option<f64>,
|
||||
/// The current stroke's frames.
|
||||
rows: Vec<Row>,
|
||||
@@ -143,49 +153,20 @@ impl StrokeTrace {
|
||||
self.output != Output::Off
|
||||
}
|
||||
|
||||
/// A frame starts (the raw input hook) with `moves` pointer moves.
|
||||
pub fn begin_frame(&mut self, now: f64, moves: usize) {
|
||||
/// A frame ended, with the stages the app gathered for it (`frame_stages`; the trace keeps
|
||||
/// no clock of its own). `stroking`: a stroke is being drawn (a frame that rendered stroke
|
||||
/// points counts too, such as the release's commit). A stroke's frames are kept until the
|
||||
/// first frame without one, which ends it.
|
||||
pub fn frame(&mut self, s: &FrameStages, stroking: bool, backend: impl FnOnce() -> String) {
|
||||
if !self.enabled() {
|
||||
return;
|
||||
}
|
||||
let interval = self.last_start.map_or(0.0, |t| now - t);
|
||||
self.last_start = Some(now);
|
||||
self.frame = Some(Row { t: now, interval, moves, ..Default::default() });
|
||||
}
|
||||
|
||||
/// eframe's CPU time for the previous frame, in seconds (`Frame::info().cpu_usage`).
|
||||
pub fn cpu_prev(&mut self, secs: Option<f32>) {
|
||||
if let Some(f) = self.frame.as_mut() {
|
||||
f.cpu_prev = secs.map(|s| f64::from(s) * 1000.0);
|
||||
}
|
||||
}
|
||||
|
||||
/// Time spent rendering stroke points this frame.
|
||||
pub fn stroke(&mut self, ms: f64) {
|
||||
if let Some(f) = self.frame.as_mut() {
|
||||
f.stroke += ms;
|
||||
}
|
||||
}
|
||||
|
||||
/// Time spent refreshing the canvas this frame.
|
||||
pub fn canvas(&mut self, ms: f64) {
|
||||
if let Some(f) = self.frame.as_mut() {
|
||||
f.canvas += ms;
|
||||
}
|
||||
}
|
||||
|
||||
/// The frame's UI is built (`ui` ms). `stroking`: a stroke is being drawn (a frame that
|
||||
/// rendered stroke points counts too, such as the release's commit). A stroke's frames are
|
||||
/// kept until the first frame without one, which ends it.
|
||||
pub fn end_frame(&mut self, ui: f64, stroking: bool, backend: impl FnOnce() -> String) {
|
||||
let Some(mut f) = self.frame.take() else { return };
|
||||
if stroking || f.stroke > 0.0 {
|
||||
f.ui = ui;
|
||||
let interval = self.last_start.map_or(0.0, |t| s.t - t);
|
||||
self.last_start = Some(s.t);
|
||||
if stroking || s.stroke_ms > 0.0 {
|
||||
// The first frame of a stroke doesn't follow a stroke frame: its interval is idle time.
|
||||
if self.rows.is_empty() {
|
||||
f.interval = 0.0;
|
||||
}
|
||||
self.rows.push(f);
|
||||
let interval = if self.rows.is_empty() { 0.0 } else { interval };
|
||||
self.rows.push(Row::from_stages(s, interval));
|
||||
} else if !self.rows.is_empty() {
|
||||
self.finish(backend());
|
||||
}
|
||||
@@ -251,14 +232,38 @@ mod tests {
|
||||
StrokeTrace { output: Output::Stderr, ..Default::default() }
|
||||
}
|
||||
|
||||
fn frame(t: &mut StrokeTrace, now: f64, cpu: f32, stroking: bool) {
|
||||
t.begin_frame(now, 3);
|
||||
t.cpu_prev(Some(cpu / 1000.0));
|
||||
fn stages(now: f64, cpu: f32, stroking: bool) -> FrameStages {
|
||||
let mut s = FrameStages::default();
|
||||
s.start(now, 3);
|
||||
s.ui_start(now, Some(cpu / 1000.0));
|
||||
if stroking {
|
||||
t.stroke(1.0);
|
||||
t.canvas(2.0);
|
||||
s.stroke_ms = 1.0;
|
||||
s.refresh("rect", 10, 1.5, 0.5);
|
||||
}
|
||||
t.end_frame(4.0, stroking, || "vulkan Test GPU".into());
|
||||
s.ui_ms = 4.0;
|
||||
s
|
||||
}
|
||||
|
||||
fn frame(t: &mut StrokeTrace, now: f64, cpu: f32, stroking: bool) {
|
||||
t.frame(&stages(now, cpu, stroking), stroking, || "vulkan Test GPU".into());
|
||||
}
|
||||
|
||||
#[test]
|
||||
fn stroke_trace_reads_the_shared_frame_stages() {
|
||||
let mut t = on();
|
||||
let mut ring = crate::frame_stages::SlowFrames::default();
|
||||
let mut last = None;
|
||||
for (k, now) in [100.0, 116.0, 132.0].into_iter().enumerate() {
|
||||
let s = ring.finish(stages(now, 6.0, true), now + 5.0, false, None);
|
||||
t.frame(&s, true, || "test".into());
|
||||
let interval = if k == 0 { 0.0 } else { 16.0 };
|
||||
let row = t.rows.last().expect("a stroke frame").clone();
|
||||
assert_eq!((row.t, row.interval, row.moves, row.stroke, row.canvas, row.ui), (s.t, interval, 3, 1.0, 2.0, 4.0));
|
||||
assert_eq!(row.cpu_prev, s.cpu_prev_ms);
|
||||
assert_eq!(t.rows.last(), Some(&Row::from_stages(&s, interval)), "the row is the frame's stages");
|
||||
last = Some(s);
|
||||
}
|
||||
assert_eq!(last.map(|s| s.composite_ms + s.upload_ms), Some(2.0));
|
||||
}
|
||||
|
||||
#[test]
|
||||
|
||||
@@ -46,7 +46,7 @@ The transport is `apps/photocraft/src/control_server.rs`, and the handlers are i
|
||||
|
||||
- `engine.execute {command, params}`: run any engine or UI command by id. Engine commands run directly with their default params and never open a dialog. Use `ui.menu.invoke` for menu-click behaviour, which opens a command's dialog when no params are given. `params` must be a JSON object (omit it or pass `null` for none); an array, string, number or boolean is an error naming the command, in every transport (control channel, `serve`, MCP and the CLI)
|
||||
- `engine.commands`: list commands with enablement; the `result` is a JSON array of command objects (see [Command list replies](#command-list-replies))
|
||||
- `ui.inspect`: full UI state (tool, panels, views, dialogs, windows, window size). The menu tree is not included; use `ui.menu.list`. `brushPicker` is `null` while closed and `{pos: [x, y], size: [w, h]?, list: {collapsed, filter, renaming, showName, showStroke, showTip, scale}}` while the Brush Preset picker is open (coordinates in screen points; `size` is the picker's content size once its corner grip was dragged, `null` before that, and the drag remembers both dimensions; the three `show*` flags pick the parts of each preset's card — at least one is always on; `scale` is the footer slider, 0.15–2 with 1 the standard, multiplying the cards' width and height — the heights stop at half size and the name and tip-size text hold their 1.0 size — and dropping the tips' size numbers at 0.40 and below; the parts and the scale are remembered across restarts, while the search, collapsed groups and a rename in progress are not). `view` holds the View/Window/Type preferences: `screen_mode`, `extras`, `show` and `snap_to` flags, `flip_horizontal`, `arrange` (Window › Arrange layout), pixel aspect, font preview size, language options. `perf.timings.gpuInfo` holds the graphics adapter, backend, driver, the backend chosen at launch and why, the canvas renderer (`gpu`/`cpu`) and, after a device loss, `lost` (`help.systemInfo` returns the same as `info`). `perf.renderPath` says why the active document is drawn on the CPU: `current` is `null` on the GPU, else `{doc, kind, detail}` (`kind` is one of `overBudget`, `canvasTooLarge`, `compositorBuild`, `deviceLost`, `gpuError`, `unsupported`, `adjustPreview`, `viewTransform`, `softwareAdapter`, `cpuMode`; `detail` is the English reason, with the working set and budget for `overBudget`), and `history` holds the last 32 changes, oldest first (`{t, doc, kind, detail}`, `kind` `null` for back on the GPU, `doc` the changed document's id, or 0 for a change to every document). An adjustment dialog's CPU proxy preview has its own slot: `current` reports it (`adjustPreview`) only when neither the window nor the canvas has a reason, it isn't recorded while the whole window is off the GPU, and its history entries always have `kind` `adjustPreview`, with `detail` `null` when the preview stops using the proxy (never read as back on the GPU). `perf.timings.gpuFallback` is `current`'s `detail` as text
|
||||
- `ui.inspect`: full UI state (tool, panels, views, dialogs, windows, window size). The menu tree is not included; use `ui.menu.list`. `brushPicker` is `null` while closed and `{pos: [x, y], size: [w, h]?, list: {collapsed, filter, renaming, showName, showStroke, showTip, scale}}` while the Brush Preset picker is open (coordinates in screen points; `size` is the picker's content size once its corner grip was dragged, `null` before that, and the drag remembers both dimensions; the three `show*` flags pick the parts of each preset's card — at least one is always on; `scale` is the footer slider, 0.15–2 with 1 the standard, multiplying the cards' width and height — the heights stop at half size and the name and tip-size text hold their 1.0 size — and dropping the tips' size numbers at 0.40 and below; the parts and the scale are remembered across restarts, while the search, collapsed groups and a rename in progress are not). `view` holds the View/Window/Type preferences: `screen_mode`, `extras`, `show` and `snap_to` flags, `flip_horizontal`, `arrange` (Window › Arrange layout), pixel aspect, font preview size, language options. `perf.timings.gpuInfo` holds the graphics adapter, backend, driver, the backend chosen at launch and why, the canvas renderer (`gpu`/`cpu`) and, after a device loss, `lost` (`help.systemInfo` returns the same as `info`). `perf.renderPath` says why the active document is drawn on the CPU: `current` is `null` on the GPU, else `{doc, kind, detail}` (`kind` is one of `overBudget`, `canvasTooLarge`, `compositorBuild`, `deviceLost`, `gpuError`, `unsupported`, `adjustPreview`, `viewTransform`, `softwareAdapter`, `cpuMode`; `detail` is the English reason, with the working set and budget for `overBudget`), and `history` holds the last 32 changes, oldest first (`{t, doc, kind, detail}`, `kind` `null` for back on the GPU, `doc` the changed document's id, or 0 for a change to every document). An adjustment dialog's CPU proxy preview has its own slot: `current` reports it (`adjustPreview`) only when neither the window nor the canvas has a reason, it isn't recorded while the whole window is off the GPU, and its history entries always have `kind` `adjustPreview`, with `detail` `null` when the preview stops using the proxy (never read as back on the GPU). `perf.timings.gpuFallback` is `current`'s `detail` as text. `perf.slowFrames` lists the last 64 frames over 50 ms, oldest first, each with its stages in ms: `t` (start), `frameMs`, `inputMs` (raw input to the UI build, commands excluded), `commandMs` and `command` (the last command run since the previous frame), `damageMs` (damage tracking and GPU memory budgeting), `compositeMs`, `uploadMs`, `gpuMs` (the GPU's own composite time, or `null`), `presentMs` (the previous frame's tessellation and submission, or `null`), `refresh` and `refreshPx` (the canvas redraw's kind and pixels) and `path` (`gpu` or `cpu`). It stays empty on the web, which has no clock
|
||||
- `ui.set {tool?, panels?, dockTabs?, dock?, dockWidth?, colorPanel?, maskTarget?, vectorMaskTarget?, filterMaskTarget?, selectionMode?, zoom?, center?, rotation?, fit?, theme?, brushSize?, brushSection?, brushTab?, brushesView?, brushPicker?, brushPickerName?, brushPickerStroke?, brushPickerTip?, brushPickerScale?, gradientBlendMode?, gradientClassic?, shapeStroke?}`: change UI state; any other field is an error, checked before anything changes (`zoom` is the canvas zoom where 1 = 100%, one document pixel per physical display pixel, so a scaled display doesn't magnify the image; `theme` is `pro`, `proMedium`, `studio`, `studioLight` or `classic`; `selectionMode` is the selection tools' options-bar mode, 0 New, 1 Add, 2 Subtract, 3 Intersect; `brushSection` indexes the Brush Settings sections, `brushTab` 0 = Brush Settings, 1 = Brushes; `brushesView` is `list` or `grid` for the Brushes panel; `brushPickerName`, `brushPickerStroke` and `brushPickerTip` are the Brush Preset picker's card parts (booleans, at least one on), and `brushPickerScale` its footer card-scale slider (0.15 to 2, 1 the standard); `brushPicker` is `[x, y]` in screen points to open the Brush Preset picker there (as a right-click with a painting tool does) or `null` to close it, and picking a preset in it is `tools.setBrush {"preset": name}`; `dock` is `{order: ["layers", …], heights: {"properties": 180}, collapsed: ["color"], tabOrder: {"layers": ["Paths", "Layers", "Channels"]}}`, the right-dock groups top to bottom, their heights in points, the groups collapsed to their tab strip and each group's tab order left to right by panel name (a group left out keeps its default order, unknown names are ignored and tabs not listed follow in their default order; `dockTabs` keeps indexing tabs in their default order); `dockWidth` sets the right dock width in points, clamped to 250..520; `colorPanel` is `{background?, mode?, ramp?, webSafeRamp?}`, merged into the Color panel's state: `background` is whether it edits the background colour, `mode` its panel-menu display (`hueCube`, `brightnessCube`, `colorWheel`, `grayscaleSlider`, `rgbSliders`, `hsbSliders`, `cmykSliders`, `labSliders` or `webColorSliders`), `ramp` the colour ramp under the sliders (`rgbSpectrum`, `cmykSpectrum`, `grayscaleRamp` or `currentColors`) and `webSafeRamp` Make Ramp Web Safe; `maskTarget` targets the active layer's mask, which, like Photoshop, swaps in the foreground/background pair kept for masks (white/black until one is picked) and swaps the pixels' pair back when the pixels are targeted again; `filterMaskTarget` targets the active smart object's filter mask (an error without smart filters), so painting, fills, filters and adjustments edit it (`"target":"filterMask"`) while Move and Edit › Transform still act on the smart object)
|
||||
- `typeTransform` is `null` outside a temporary Ctrl/Cmd Type-tool drag. During a drag it reports its source document/revision, original affine, oriented `frame` (layer, local bounds, document-space corners and pivot), and captured `gesture`. Drive it with `ui.pointer` and `command: true` at `down`; `move`/`up` may release the modifier. The document/history remain unchanged during preview, and `up` applies one `type.edit` within `textEdit`'s session. Pressing Escape during the drag cancels only the preview. This pointer state is never restored from saved UI state.
|
||||
- `ui.menu.invoke {id, params?, wait?}` / `ui.menu.list`: activate a menu item by id; list the menu tree. A menu item that starts a background job (a filter without a dialog, such as Blur More) replies with the job's result once it has been applied; with `"wait": false` the reply is `{job, pending: true}` at once. Window ends with the open documents as `window.document.<index>` (tab order, the active one checked, #2991); invoking one brings that document to the front and replies `{document: index}`. Camera Raw and the full-window workspaces (Liquify, Content-Aware Fill, Filter Gallery, Adaptive Wide Angle) are modal: while one is open, `ui.menu.invoke` refuses every other menu item ("menu command is unavailable while a modal dialog is open") and accepts only that workspace's own `{"ui": {...}}` requests (`filter.liquify`, `edit.contentAwareFill`, `filter.filterGallery`, `filter.adaptiveWideAngle`, `filter.cameraRaw`; `params` must hold only the `ui` object), so finish it with `{"ui":{"commit":true}}` or `{"ui":{"cancel":true}}` first. Those requests are refused too while a dialog, an unsaved-changes prompt or a crop that blocks the command is open: resolve that first, then commit or cancel the workspace. `ui.menu.list` reports the same gate: an item the modal state refuses is listed with `enabled: false`. `engine.execute` is not a menu click and is not gated
|
||||
|
||||
@@ -200,6 +200,8 @@ stroke trace: 62 frames on vulkan NVIDIA GeForce RTX 5090 (p50/p95 ms): interval
|
||||
|
||||
What the app can't time is the rest of input-to-photon: the OS input queue before a frame starts (up to one `interval`), frames queued for the display (the surface keeps up to two; the GL backend ignores that setting), and the compositor. So the first line names the backend and how frames are presented. To compare presentation settings without rebuilding, launch with `PHOTOCRAFT_PRESENT_MODE` and `PHOTOCRAFT_FRAME_LATENCY` (see [Environment variables](#environment-variables)): with `novsync` the app no longer waits on vsync (`wait` near 0): each refresh shows the newest frame, and where the driver only offers Immediate, the screen may tear. The last summary is also in the control channel's `perf.strokeTrace` (`ui.inspect`). The code is `crates/ui-egui/src/stroke_trace.rs`.
|
||||
|
||||
The trace has no clock of its own: it reads the per-frame stage record the app gathers every frame (`crates/ui-egui/src/frame_stages.rs`). The same record feeds the slow-frame ring: any frame over 50 ms is kept (the last 64, in `perf.slowFrames`) and logged at `info`, at most one line a second with a count of the slow frames in between, naming its input, command, damage, composite, upload, GPU and present times and the canvas redraw's kind and pixels.
|
||||
|
||||
## Driving the app programmatically
|
||||
|
||||
Start the app with a private token file. It then accepts authenticated JSON lines on `127.0.0.1:7878`:
|
||||
|
||||
+2
-1
@@ -6,7 +6,7 @@ Generated by `cargo xtask scorecard` from `perf/budgets.toml`, `perf/baseline.js
|
||||
|
||||
| Area | Done | Partial | Missing | Key numbers |
|
||||
|---|---:|---:|---:|---|
|
||||
| [Performance](#performance) | 3 | 22 | 44 | 78 scenarios: 3 within budget, 22 over budget or failing, 9 tracked only, 40 not run, 4 not measurable yet (baseline 2026-10-05) |
|
||||
| [Performance](#performance) | 3 | 22 | 45 | 79 scenarios: 3 within budget, 22 over budget or failing, 9 tracked only, 41 not run, 4 not measurable yet (baseline 2026-10-05) |
|
||||
| [File compatibility](#file-compatibility) | 11 | 14 | 2 | io corpus: oracle ≥ 148/170, round trip ≥ 169/170; psd-tools corpus: oracle ≥ 249/309, round trip ≥ 308/309; photoshop oracles: oracle ≥ 190/258, round trip ≥ 258/258 |
|
||||
| [Tools](#tools) | 36 | 9 | 0 | |
|
||||
| [Workspace and UI](#workspace-and-ui) | 15 | 6 | 2 | settings that do nothing: 12 of 181 (target 0) |
|
||||
@@ -98,6 +98,7 @@ Baseline: 2026-10-05, 1 run, commit `f5d2bcb54a`, Apple M4 Pro (48 GB), GPU Appl
|
||||
| P77 | Toggle an adjustment layer's visibility | ≤ 10 ms p95 | – | – | – | – | – | not run | [#6535](https://github.com/storytold/photocraft/issues/6535) |
|
||||
| P78 | Hide the top adjustment layer among 150 full-canvas layers, 6 MP, GPU budget forced to 512 MB (CPU fallback) | ≤ 30 ms p95 | – | – | – | – | – | not run | [#6533](https://github.com/storytold/photocraft/issues/6533) |
|
||||
| P79 | Zoomed-out reduced composite of a 30000x30000 document with one painted layer (#9330 target: 60000x60000) | track only | – | – | – | – | – | not run | [#1015](https://github.com/storytold/photocraft/issues/1015) |
|
||||
| P80 | App frame: full CPU refresh of a 24 MP document | ≤ 50 ms p95 | – | – | – | – | – | not run | [#9328](https://github.com/storytold/photocraft/issues/9328) |
|
||||
| P81 | Undo a brush dab on a full-canvas 16-bit 15000 x 10000 layer + refresh | track only | – | – | – | – | – | not run | [#9329](https://github.com/storytold/photocraft/issues/9329) |
|
||||
| P82 | Fill a 2 % selection on a full-canvas 24 MP layer + refresh | track only | – | – | – | – | – | not run | [#9329](https://github.com/storytold/photocraft/issues/9329) |
|
||||
|
||||
|
||||
@@ -752,6 +752,15 @@ bench = "perf_scenarios"
|
||||
row = "zoomed-out reduced composite of the huge document with one painted layer"
|
||||
enforce = false # tracked only
|
||||
|
||||
[[scenario]]
|
||||
id = "P80"
|
||||
title = "App frame: full CPU refresh of a 24 MP document"
|
||||
issue = 9328
|
||||
bench = "perf_scenarios"
|
||||
row = "app frame: full CPU refresh of a 24 MP document"
|
||||
budget_ms = 50
|
||||
enforce = false # track only: the worst case for the slow-frame ring (#9328 PR B)
|
||||
|
||||
# ---- #9329: redraw area of edits on full-canvas layers (track only) ---------------------------
|
||||
#
|
||||
# Each row checks it hits the path it claims (a full-canvas layer; a non-empty edit; a small
|
||||
|
||||
Reference in New Issue
Block a user