From df3bf37aef4011b20c14d268e9eb75bb1438785b Mon Sep 17 00:00:00 2001 From: Emil Ernerfeldt Date: Wed, 13 Apr 2022 16:46:27 +0200 Subject: [PATCH] Puffin profiler (#1) Add a button to profile the viewer. This is done via puffin_viewer --- .github/workflows/rust.yml | 27 +++++++++++++--- Cargo.toml | 7 +++-- check.sh | 2 ++ deny.toml | 4 +-- viewer/Cargo.toml | 7 +++++ viewer/src/app.rs | 19 ++++++++++++ viewer/src/lib.rs | 22 +++++++++++++ viewer/src/misc.rs | 2 ++ viewer/src/misc/clipboard.rs | 11 +++++++ viewer/src/misc/log_db.rs | 19 ++++++++++++ viewer/src/misc/profiler.rs | 55 +++++++++++++++++++++++++++++++++ viewer/src/misc/time_control.rs | 37 +++------------------- viewer/src/ui/context_panel.rs | 7 +++-- viewer/src/ui/log_table_view.rs | 6 ++++ viewer/src/ui/space_view.rs | 4 ++- viewer/src/ui/time_panel.rs | 21 +++++++++---- viewer/src/ui/view_2d.rs | 1 + viewer/src/ui/view_3d.rs | 6 ++++ 18 files changed, 206 insertions(+), 51 deletions(-) create mode 100644 viewer/src/misc/profiler.rs diff --git a/.github/workflows/rust.yml b/.github/workflows/rust.yml index 9f43fa1b5a30..73a80c244b30 100644 --- a/.github/workflows/rust.yml +++ b/.github/workflows/rust.yml @@ -10,8 +10,8 @@ env: RUSTDOCFLAGS: -D warnings jobs: - check: - name: Check + check_all_features: + name: Check --all-features runs-on: ubuntu-latest steps: - uses: actions/checkout@v2 @@ -20,11 +20,28 @@ jobs: profile: minimal toolchain: 1.60.0 override: true + - run: sudo apt-get update && sudo apt-get install libgtk-3-dev - uses: actions-rs/cargo@v1 with: command: check args: --all-features + check_no_features: + name: Check --no-default-features + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v2 + - uses: actions-rs/toolchain@v1 + with: + profile: minimal + toolchain: 1.60.0 + override: true + - run: sudo apt-get update && sudo apt-get install libgtk-3-dev + - uses: actions-rs/cargo@v1 + with: + command: check + args: --no-default-features --features __ci + check_wasm: name: Check wasm32 runs-on: ubuntu-latest @@ -35,6 +52,7 @@ jobs: profile: minimal toolchain: 1.60.0 override: true + - run: sudo apt-get update && sudo apt-get install libgtk-3-dev - run: rustup target add wasm32-unknown-unknown - uses: actions-rs/cargo@v1 with: @@ -51,7 +69,7 @@ jobs: profile: minimal toolchain: 1.60.0 override: true - - run: sudo apt-get install libxcb-render0-dev libxcb-shape0-dev libxcb-xfixes0-dev libspeechd-dev libxkbcommon-dev libssl-dev + - run: sudo apt-get install libgtk-3-dev libxcb-render0-dev libxcb-shape0-dev libxcb-xfixes0-dev libspeechd-dev libxkbcommon-dev libssl-dev - uses: actions-rs/cargo@v1 with: command: test @@ -67,7 +85,7 @@ jobs: profile: minimal toolchain: 1.60.0 override: true - - run: sudo apt-get install libxcb-render0-dev libxcb-shape0-dev libxcb-xfixes0-dev libspeechd-dev libxkbcommon-dev libssl-dev + - run: sudo apt-get install libgtk-3-dev libxcb-render0-dev libxcb-shape0-dev libxcb-xfixes0-dev libspeechd-dev libxkbcommon-dev libssl-dev - run: rustup component add rustfmt - uses: actions-rs/cargo@v1 with: @@ -84,6 +102,7 @@ jobs: profile: minimal toolchain: 1.60.0 override: true + - run: sudo apt-get update && sudo apt-get install libgtk-3-dev - run: rustup component add clippy - uses: actions-rs/cargo@v1 with: diff --git a/Cargo.toml b/Cargo.toml index 5fa27dbaa41c..be86c3411c56 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -9,9 +9,10 @@ opt-level = 1 # Speed up debug builds [patch.crates-io] # we use bleeding edge versions of some crates: -eframe = { git = "https://github.com/emilk/egui", rev = "08b208586a61c86c9968c4a466f17ce6e842389c" } # 2022-04-12 -egui_extras = { git = "https://github.com/emilk/egui", rev = "08b208586a61c86c9968c4a466f17ce6e842389c" } # 2022-04-12 -egui_glow = { git = "https://github.com/emilk/egui", rev = "08b208586a61c86c9968c4a466f17ce6e842389c" } # 2022-04-12 +eframe = { git = "https://github.com/emilk/egui", rev = "170b21b63e461dfeaa7597815b67f1dcd756ac80" } # 2022-04-13 +egui = { git = "https://github.com/emilk/egui", rev = "170b21b63e461dfeaa7597815b67f1dcd756ac80" } # 2022-04-13 +egui_extras = { git = "https://github.com/emilk/egui", rev = "170b21b63e461dfeaa7597815b67f1dcd756ac80" } # 2022-04-13 +egui_glow = { git = "https://github.com/emilk/egui", rev = "170b21b63e461dfeaa7597815b67f1dcd756ac80" } # 2022-04-13 # eframe = { path = "../../egui/eframe" } # egui = { path = "../../egui/egui" } # egui_extras = { path = "../../egui/egui_extras" } diff --git a/check.sh b/check.sh index cacf23fbd7fd..eadd29a6531f 100755 --- a/check.sh +++ b/check.sh @@ -12,6 +12,8 @@ cargo clippy --workspace --all-targets --all-features -- -D warnings -W clippy: cargo test --workspace --all-targets --all-features cargo test --workspace --doc --all-features +cargo check --no-default-features + cargo doc --lib --no-deps --all-features cargo doc --document-private-items --no-deps --all-features diff --git a/deny.toml b/deny.toml index bfb45427a92d..c399dfe8d052 100644 --- a/deny.toml +++ b/deny.toml @@ -52,8 +52,8 @@ allow = [ "ISC", # https://tldrlegal.com/license/-isc-license "MIT", # https://tldrlegal.com/license/mit-license "MPL-2.0", # https://www.mozilla.org/en-US/MPL/2.0/FAQ/ - see Q11. Used by webpki-roots on Linux. - # "OpenSSL", # https://www.openssl.org/source/license.html - "Zlib", # https://tldrlegal.com/license/zlib-libpng-license-(zlib) + "OpenSSL", # https://www.openssl.org/source/license.html - used on Linux + "Zlib", # https://tldrlegal.com/license/zlib-libpng-license-(zlib) ] [[licenses.clarify]] diff --git a/viewer/Cargo.toml b/viewer/Cargo.toml index d28637660137..31b263e05965 100644 --- a/viewer/Cargo.toml +++ b/viewer/Cargo.toml @@ -10,6 +10,11 @@ publish = false crate-type = ["cdylib", "rlib"] +[features] +default = ["puffin"] +puffin = ["dep:puffin", "dep:puffin_http", "eframe/puffin"] + + [dependencies] clap = { version = "3.1.6", features = ["derive"] } comms = { path = "../comms", features = ["client"] } @@ -43,6 +48,8 @@ vec1 = "1.8" arboard = { version = "2.1", default-features = false, features = [ "image-data", ] } +puffin = { version = "0.13", optional = true } +puffin_http = { version = "0.10", optional = true } tracing-subscriber = "0.3" tokio = { version = "1.16", features = ["macros", "rt-multi-thread"] } # TODO: consider using mimalloc diff --git a/viewer/src/app.rs b/viewer/src/app.rs index 4a6a85660b62..0cd935615d17 100644 --- a/viewer/src/app.rs +++ b/viewer/src/app.rs @@ -55,10 +55,16 @@ struct AppState { space_view: crate::space_view::SpaceView, context_panel: crate::context_panel::ContextPanel, time_panel: crate::time_panel::TimePanel, + + #[cfg(all(feature = "puffin", not(target_arch = "wasm32")))] + #[serde(skip)] + profiler: crate::misc::profiler::Profiler, } impl AppState { fn show(&mut self, egui_ctx: &egui::Context, frame: &mut eframe::Frame, log_db: &LogDb) { + crate::profile_function!(); + egui::TopBottomPanel::top("View").show(egui_ctx, |ui| { egui::menu::bar(ui, |ui| { ui.menu_button("File", |ui| { @@ -83,6 +89,17 @@ impl AppState { ui.close_menu(); } + + #[cfg(all(feature = "puffin", not(target_arch = "wasm32")))] + if ui + .button("Profile viewer") + .on_hover_text( + "Starts a profiler, showing what makes the viewer run slow", + ) + .clicked() + { + self.profiler.start(); + } }); if ui.button("Quit").clicked() { @@ -108,6 +125,8 @@ impl AppState { space_view, context_panel, time_panel, + #[cfg(all(feature = "puffin", not(target_arch = "wasm32")))] + profiler: _, } = self; egui::TopBottomPanel::bottom("time_panel") diff --git a/viewer/src/lib.rs b/viewer/src/lib.rs index 073069f442e6..9825546ccbdc 100644 --- a/viewer/src/lib.rs +++ b/viewer/src/lib.rs @@ -26,3 +26,25 @@ pub use native::run_native_viewer; mod web; #[cfg(target_arch = "wasm32")] pub use web::start; + +// --------------------------------------------------------------------------- + +/// Profiling macro for feature "puffin" +#[doc(hidden)] +#[macro_export] +macro_rules! profile_function { + ($($arg: tt)*) => { + #[cfg(all(feature = "puffin", not(target_arch = "wasm32")))] + puffin::profile_function!($($arg)*); + }; +} + +/// Profiling macro for feature "puffin" +#[doc(hidden)] +#[macro_export] +macro_rules! profile_scope { + ($($arg: tt)*) => { + #[cfg(all(feature = "puffin", not(target_arch = "wasm32")))] + puffin::profile_scope!($($arg)*); + }; +} diff --git a/viewer/src/misc.rs b/viewer/src/misc.rs index 339855f45488..e9c2da0b1911 100644 --- a/viewer/src/misc.rs +++ b/viewer/src/misc.rs @@ -3,6 +3,8 @@ mod clipboard; mod image_cache; pub(crate) mod log_db; pub(crate) mod mesh_loader; +#[cfg(all(feature = "puffin", not(target_arch = "wasm32")))] +pub(crate) mod profiler; pub(crate) mod time_axis; mod time_control; mod viewer_context; diff --git a/viewer/src/misc/clipboard.rs b/viewer/src/misc/clipboard.rs index da9e2bd04355..dcd4d1f1ed69 100644 --- a/viewer/src/misc/clipboard.rs +++ b/viewer/src/misc/clipboard.rs @@ -13,6 +13,17 @@ impl Clipboard { } } + #[cfg(all(feature = "puffin", not(target_arch = "wasm32")))] // only used sometimes + pub fn set_text(&mut self, text: String) { + if let Some(clipboard) = &mut self.arboard { + if let Err(err) = clipboard.set_text(text) { + tracing::error!("Failed to copy image to clipboard: {}", err); + } else { + tracing::info!("Image copied to clipboard"); + } + } + } + pub fn set_image(&mut self, size: [usize; 2], rgba_unmultiplied: &[u8]) { let [width, height] = size; assert_eq!(width * height * 4, rgba_unmultiplied.len()); diff --git a/viewer/src/misc/log_db.rs b/viewer/src/misc/log_db.rs index 49743f263c4a..6c186fccf769 100644 --- a/viewer/src/misc/log_db.rs +++ b/viewer/src/misc/log_db.rs @@ -15,6 +15,7 @@ pub(crate) struct LogDb { impl LogDb { pub fn add(&mut self, msg: LogMsg) { + crate::profile_function!(); santiy_check(&msg); self.time_points.insert(&msg.time_point); @@ -64,6 +65,24 @@ impl LogDb { self.messages.get(id) } + /// Grouped by [`ObjectPath`], find the latest [`LogMsg`] that matches + /// the given time source and is not after the given time. + pub fn latest_of_each_object( + &self, + time_source: &str, + no_later_than: TimeValue, + ) -> Vec<&LogMsg> { + crate::profile_function!(); + self.object_history + .values() + .filter_map(|history| { + history + .latest(time_source, no_later_than) + .and_then(|id| self.get_msg(&id)) + }) + .collect() + } + pub fn latest( &self, time_source: &str, diff --git a/viewer/src/misc/profiler.rs b/viewer/src/misc/profiler.rs new file mode 100644 index 000000000000..fdfa20b6c83b --- /dev/null +++ b/viewer/src/misc/profiler.rs @@ -0,0 +1,55 @@ +const PORT: u16 = puffin_http::DEFAULT_PORT; + +#[derive(Default)] +pub struct Profiler { + server: Option, +} + +impl Profiler { + pub fn start(&mut self) { + puffin::set_scopes_on(true); + + if self.server.is_none() { + self.start_server(); + } + start_puffin_viewer(); + } + + fn start_server(&mut self) { + let bind_addr = format!("0.0.0.0:{}", PORT); + self.server = match puffin_http::Server::new(&bind_addr) { + Ok(puffin_server) => { + tracing::info!( + "Started puffin profiling server. View with: cargo install puffin_viewer && puffin_viewer" + ); + Some(puffin_server) + } + Err(err) => { + tracing::warn!("Failed to start puffin profiling server: {}", err); + None + } + }; + } +} + +fn start_puffin_viewer() { + let url = format!("127.0.0.1:{PORT}"); + let child = std::process::Command::new("puffin_viewer") + .arg("--url") + .arg(&url) + .spawn(); + + if let Err(err) = child { + let cmd = format!("cargo install puffin_viewer && puffin_viewer --url {url}",); + crate::Clipboard::with(|cliboard| cliboard.set_text(cmd.clone())); + tracing::warn!( + "Failed to start puffin_viewer: {err}. Try connecting manually with: {cmd}" + ); + + rfd::MessageDialog::new() + .set_level(rfd::MessageLevel::Info) + .set_title("puffin_viewer required") + .set_description(&format!("To view the profiling data, run the following command:\n\n{cmd}\n\n(it has been copied to your clipboard)")) + .show(); + } +} diff --git a/viewer/src/misc/time_control.rs b/viewer/src/misc/time_control.rs index 00315e9d40b4..75ce6fd98c9b 100644 --- a/viewer/src/misc/time_control.rs +++ b/viewer/src/misc/time_control.rs @@ -190,7 +190,9 @@ impl TimeControl { pub fn latest_of_each_object<'db>( &self, log_db: &'db crate::log_db::LogDb, - ) -> BTreeMap { + ) -> Vec<&'db LogMsg> { + crate::profile_function!(); + let current_time = if let Some(current_time) = self.time() { current_time } else { @@ -198,38 +200,7 @@ impl TimeControl { }; let source = self.source(); - let mut latest: BTreeMap = BTreeMap::new(); - for (time_value, msg) in log_db - .messages - .values() - .filter_map(|msg| { - let time_value = *msg.time_point.0.get(source)?; - Some((time_value, msg)) - }) - .filter(|(time_value, _msg)| time_value <= ¤t_time) - { - if let Some(existing) = latest.get_mut(&msg.object_path) { - if existing.0 < time_value { - *existing = (time_value, msg); - } - } else { - latest.insert(msg.object_path.clone(), (time_value, msg)); - } - } - - latest - } - - /// Find the latest [`LogMsg`] of each unique [`ObjectPath`] that matches - /// the current time source and is not after the current time. - pub fn latest_of_each_object_vec<'db>( - &self, - log_db: &'db crate::log_db::LogDb, - ) -> Vec<&'db LogMsg> { - self.latest_of_each_object(log_db) - .values() - .map(|(_, msg)| *msg) - .collect() + log_db.latest_of_each_object(source, current_time) } } diff --git a/viewer/src/ui/context_panel.rs b/viewer/src/ui/context_panel.rs index 1b7d34631934..22d0e08cfa57 100644 --- a/viewer/src/ui/context_panel.rs +++ b/viewer/src/ui/context_panel.rs @@ -36,7 +36,7 @@ impl ContextPanel { ui.small("Showing latest versions of each object.") .on_hover_text("Latest by the current time, that is"); egui::ScrollArea::horizontal().show(ui, |ui| { - let mut messages = context.time_control.latest_of_each_object_vec(log_db); + let mut messages = context.time_control.latest_of_each_object(log_db); messages.retain(|msg| msg.space.as_ref() == Some(&space)); crate::log_table_view::message_table(log_db, context, ui, &messages); }); @@ -56,7 +56,7 @@ impl ContextPanel { ui.separator(); - let messages = context.time_control.latest_of_each_object_vec(log_db); + let messages = context.time_control.latest_of_each_object(log_db); let mut parent_path = msg.object_path.0.clone(); parent_path.pop(); @@ -133,6 +133,7 @@ pub(crate) fn show_detailed_log_msg(context: &mut ViewerContext, ui: &mut egui:: } } +#[cfg(not(target_arch = "wasm32"))] fn image_options(ui: &mut egui::Ui, image: &log_types::Image) { // TODO: support copying images on web #[cfg(not(target_arch = "wasm32"))] @@ -167,6 +168,7 @@ fn image_options(ui: &mut egui::Ui, image: &log_types::Image) { } } +#[cfg(not(target_arch = "wasm32"))] fn to_rgba_unultiplied(image: &log_types::Image) -> Vec { match image.format { log_types::ImageFormat::Luminance8 => { @@ -175,6 +177,7 @@ fn to_rgba_unultiplied(image: &log_types::Image) -> Vec { } } +#[cfg(not(target_arch = "wasm32"))] fn to_image_image(image: &log_types::Image) -> Option { let [w, h] = image.size; match image.format { diff --git a/viewer/src/ui/log_table_view.rs b/viewer/src/ui/log_table_view.rs index a60e89e94e08..034deed376d2 100644 --- a/viewer/src/ui/log_table_view.rs +++ b/viewer/src/ui/log_table_view.rs @@ -11,6 +11,8 @@ pub(crate) struct LogTableView {} impl LogTableView { #[allow(clippy::unused_self)] pub fn ui(&mut self, log_db: &LogDb, context: &mut ViewerContext, ui: &mut egui::Ui) { + crate::profile_function!(); + ui.label(format!("{} log lines", log_db.messages.len())); ui.separator(); @@ -31,6 +33,8 @@ pub(crate) fn message_table( ui: &mut egui::Ui, messages: &[&LogMsg], ) { + crate::profile_function!(); + use egui_extras::Size; egui_extras::TableBuilder::new(ui) @@ -93,6 +97,8 @@ fn table_row( msg: &LogMsg, row_height: f32, ) { + crate::profile_function!(); + let LogMsg { id, time_point, diff --git a/viewer/src/ui/space_view.rs b/viewer/src/ui/space_view.rs index 10ee78b31a84..37f4389bf92a 100644 --- a/viewer/src/ui/space_view.rs +++ b/viewer/src/ui/space_view.rs @@ -18,6 +18,8 @@ pub(crate) struct SpaceView { impl SpaceView { pub fn ui(&mut self, log_db: &LogDb, context: &mut ViewerContext, ui: &mut egui::Ui) { + crate::profile_function!(); + ui.small("Showing latest versions of each object.") .on_hover_text("Latest by the current time, that is"); @@ -201,7 +203,7 @@ impl SpaceView { // space_summary.messages.len() // )); - let latest = context.time_control.latest_of_each_object_vec(log_db); + let latest = context.time_control.latest_of_each_object(log_db); if latest.is_empty() { return; } diff --git a/viewer/src/ui/time_panel.rs b/viewer/src/ui/time_panel.rs index 22b73969129b..aad8c1e3d828 100644 --- a/viewer/src/ui/time_panel.rs +++ b/viewer/src/ui/time_panel.rs @@ -36,6 +36,8 @@ impl Default for TimePanel { impl TimePanel { pub fn ui(&mut self, log_db: &LogDb, context: &mut ViewerContext, ui: &mut egui::Ui) { + crate::profile_function!(); + self.next_col_right = ui.min_rect().left(); // this will expand during the call // Where the time will be shown. @@ -71,6 +73,7 @@ impl TimePanel { egui::ScrollArea::vertical() .auto_shrink([false; 2]) .show(ui, |ui| { + crate::profile_scope!("tree_ui"); self.tree_ui(log_db, context, ui); }); @@ -179,6 +182,7 @@ impl TimePanel { ui: &mut egui::Ui, time_x_range: RangeInclusive, ) { + crate::profile_function!(); let time_source_axes = TimeSourceAxes::new(&log_db.time_points); if let Some(segments) = time_source_axes.sources.get(context.time_control.source()) { self.time_segments_ui = TimeSegmentsUi::new(time_x_range, &segments.segments); @@ -313,6 +317,7 @@ impl TimePanel { // show the data in the time area: { + crate::profile_scope!("balls"); let pointer_pos = ui.input().pointer.hover_pos(); let source = if also_show_child_points { @@ -325,6 +330,14 @@ impl TimePanel { let mut scatter = BallScatterer::default(); + let hovered_color = ui.visuals().widgets.hovered.text_color(); + let inactive_color = ui + .visuals() + .widgets + .inactive + .text_color() + .linear_multiply(0.75); + for (time, log_id) in source { if let Some(time) = time.0.get(context.time_control.source()).copied() { if let Some(x) = self.time_segments_ui.x_from_time(time) { @@ -335,13 +348,9 @@ impl TimePanel { .map_or(false, |pointer_pos| pos.distance(pointer_pos) < 1.5 * r); let mut color = if is_hovered { - ui.visuals().widgets.hovered.text_color() + hovered_color } else { - ui.visuals() - .widgets - .inactive - .text_color() - .linear_multiply(0.75) + inactive_color }; if ui.visuals().dark_mode { color = color.additive(); diff --git a/viewer/src/ui/view_2d.rs b/viewer/src/ui/view_2d.rs index 2c66048ea30e..fc69782379bf 100644 --- a/viewer/src/ui/view_2d.rs +++ b/viewer/src/ui/view_2d.rs @@ -18,6 +18,7 @@ pub(crate) fn combined_view_2d( if space_summary.bbox2d.is_negative() { return; } + crate::profile_function!(); // Show images first (behind everything else), then bboxes, then points: messages.sort_by_key(|msg| match &msg.data { diff --git a/viewer/src/ui/view_3d.rs b/viewer/src/ui/view_3d.rs index ae650a9609ab..7962b00d4244 100644 --- a/viewer/src/ui/view_3d.rs +++ b/viewer/src/ui/view_3d.rs @@ -92,6 +92,7 @@ pub(crate) fn combined_view_3d( if space_summary.messages_3d.is_empty() { return; } + crate::profile_function!(); // TODO: show settings on top of 3D view. // Requires some egui work to handle interaction of overlapping widgets. @@ -335,6 +336,7 @@ impl MeshCache { object_path: &ObjectPath, mesh_data: &Mesh3D, ) -> Option> { + crate::profile_function!(); self.0 .entry(*log_id) .or_insert_with(|| { @@ -357,6 +359,7 @@ fn paint_with_three_d( info: &egui::PaintCallbackInfo, scene: &Scene, ) -> three_d::ThreeDResult<()> { + crate::profile_function!(); use three_d::*; let three_d = &rendering.three_d; @@ -427,6 +430,7 @@ fn paint_with_three_d( } } + crate::profile_scope!("render_pass"); render_pass(&camera, &objects, lights)?; Ok(()) @@ -437,6 +441,7 @@ fn point_to_three_d( sphere_mesh: &three_d::CpuMesh, point: &Point, ) -> three_d::Model { + crate::profile_function!(); use three_d::*; let [x, y, z] = point.pos; @@ -469,6 +474,7 @@ fn line_segments_to_three_d( three_d: &three_d::Context, line_segments: &LineSegments, ) -> three_d::InstancedModel { + crate::profile_function!(); use three_d::*; let LineSegments {