Generate reports about profiling results of top-level sections of the application. (#3306)

This commit is contained in:
Kaz Wesley 2022-03-14 19:12:39 -07:00 committed by GitHub
parent 247b284316
commit 348abdb680
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
25 changed files with 645 additions and 139 deletions

22
Cargo.lock generated
View File

@ -1276,6 +1276,7 @@ dependencies = [
"enso-logger",
"enso-optics",
"enso-prelude",
"enso-profiler",
"enso-shapely",
"enso-shortcuts",
"enso-types",
@ -1425,6 +1426,26 @@ dependencies = [
"wasm-bindgen",
]
[[package]]
name = "ensogl-example-render-profile"
version = "0.1.0"
dependencies = [
"enso-frp",
"enso-profiler",
"enso-profiler-data",
"enso-profiler-flame-graph",
"enso-web",
"ensogl-core",
"ensogl-flame-graph",
"ensogl-hardcoded-theme",
"ensogl-text",
"ensogl-text-msdf-sys",
"futures 0.3.21",
"wasm-bindgen",
"wasm-bindgen-futures",
"web-sys",
]
[[package]]
name = "ensogl-example-scroll-area"
version = "0.1.0"
@ -1497,6 +1518,7 @@ dependencies = [
"ensogl-example-list-view",
"ensogl-example-mouse-events",
"ensogl-example-profiling-run-graph",
"ensogl-example-render-profile",
"ensogl-example-scroll-area",
"ensogl-example-shape-system",
"ensogl-example-slider",

View File

@ -120,48 +120,55 @@ impl API for Handle {
impl ManagingProjectAPI for Handle {
fn create_new_project(&self, template: Option<String>) -> BoxFuture<FallibleResult> {
async move {
use model::project::Synchronized as Project;
let list = self.project_manager.list_projects(&None).await?;
let existing_names: HashSet<_> =
list.projects.into_iter().map(|p| p.name.into()).collect();
let name = template.clone().unwrap_or_else(|| UNNAMED_PROJECT_NAME.to_owned());
let name = choose_new_project_name(&existing_names, &name);
let name = ProjectName::new_unchecked(name);
let version = Some(enso_config::engine_version_supported.to_string());
let action = MissingComponentAction::Install;
let create_result =
self.project_manager.create_project(&name, &template, &version, &action).await?;
let new_project_id = create_result.project_id;
let project_mgr = self.project_manager.clone_ref();
let new_project = Project::new_opened(&self.logger, project_mgr, new_project_id);
self.current_project.set(Some(new_project.await?));
executor::global::spawn(self.notifications.publish(Notification::NewProjectCreated));
Ok(())
}
.boxed_local()
self.create_new_project_internal(template).boxed_local()
}
fn list_projects(&self) -> BoxFuture<FallibleResult<Vec<ProjectMetadata>>> {
async move {
let pm_response = self.project_manager.list_projects(&None).await?;
Ok(pm_response.projects)
}
.boxed_local()
self.list_projects_internal().boxed_local()
}
fn open_project(&self, id: Uuid) -> BoxFuture<FallibleResult> {
async move {
let logger = &self.logger;
let project_mgr = self.project_manager.clone_ref();
let new_project = model::project::Synchronized::new_opened(logger, project_mgr, id);
self.current_project.set(Some(new_project.await?));
executor::global::spawn(self.notifications.publish(Notification::ProjectOpened));
Ok(())
}
.boxed_local()
self.open_project_internal(id).boxed_local()
}
}
impl Handle {
#[profile(Objective)]
async fn create_new_project_internal(&self, template: Option<String>) -> FallibleResult {
use model::project::Synchronized as Project;
let list = self.project_manager.list_projects(&None).await?;
let existing_names: HashSet<_> = list.projects.into_iter().map(|p| p.name.into()).collect();
let name = template.clone().unwrap_or_else(|| UNNAMED_PROJECT_NAME.to_owned());
let name = choose_new_project_name(&existing_names, &name);
let name = ProjectName::new_unchecked(name);
let version = Some(enso_config::engine_version_supported.to_string());
let action = MissingComponentAction::Install;
let create_result =
self.project_manager.create_project(&name, &template, &version, &action).await?;
let new_project_id = create_result.project_id;
let project_mgr = self.project_manager.clone_ref();
let new_project = Project::new_opened(&self.logger, project_mgr, new_project_id);
self.current_project.set(Some(new_project.await?));
let notify = self.notifications.publish(Notification::NewProjectCreated);
executor::global::spawn(notify);
Ok(())
}
#[profile(Task)]
async fn list_projects_internal(&self) -> FallibleResult<Vec<ProjectMetadata>> {
Ok(self.project_manager.list_projects(&None).await?.projects)
}
#[profile(Task)]
async fn open_project_internal(&self, id: Uuid) -> FallibleResult {
let logger = &self.logger;
let project_mgr = self.project_manager.clone_ref();
let new_project = model::project::Synchronized::new_opened(logger, project_mgr, id);
self.current_project.set(Some(new_project.await?));
executor::global::spawn(self.notifications.publish(Notification::ProjectOpened));
Ok(())
}
}

View File

@ -120,6 +120,7 @@ impl Project {
/// warning about unsupported engine version).
///
/// Returns the controllers of module and graph which should be displayed in the view.
#[profile(Task)]
pub async fn initialize(&self) -> FallibleResult<InitializationResult> {
let project = self.model.clone_ref();
let parser = self.model.parser();

View File

@ -59,19 +59,23 @@ impl Initializer {
/// Initialize all Ide objects and structures (executor, views, controllers, integration etc.)
/// and forget them to keep them alive.
#[profile(Task)]
pub fn start_and_forget(self) {
let executor = setup_global_executor();
executor::global::spawn(async move {
let ide = self.start().await;
#[profile(Task)]
async fn start_and_forget_internal(self_: Initializer) {
let ide = self_.start().await;
web::document
.get_element_by_id("loader")
.map(|t| t.parent_node().map(|p| p.remove_child(&t).unwrap()));
std::mem::forget(ide);
});
}
executor::global::spawn(start_and_forget_internal(self));
std::mem::forget(executor);
}
/// Initialize all Ide objects and structures (executor, views, controllers, integration etc.)
#[profile(Task)]
pub async fn start(self) -> Result<Ide, FailedIde> {
info!(self.logger, "Starting IDE with the following config: {self.config:?}");
@ -134,6 +138,7 @@ impl Initializer {
///
/// This will setup all required connections to backend properly, according to the
/// configuration.
#[profile(Task)]
pub async fn initialize_ide_controller(&self) -> FallibleResult<controller::Ide> {
use crate::config::BackendService::*;
match &self.config.backend {
@ -166,6 +171,7 @@ impl Initializer {
/// Create and configure a new project manager client and register it within the global
/// executor.
#[profile(Task)]
pub async fn setup_project_manager(
&self,
endpoint: &str,

View File

@ -95,6 +95,9 @@ pub mod prelude {
pub use crate::model;
pub use crate::model::traits::*;
pub use enso_profiler as profiler;
pub use enso_profiler::prelude::*;
pub use engine_protocol::prelude::BoxFuture;
pub use engine_protocol::prelude::StaticBoxFuture;
pub use engine_protocol::prelude::StaticBoxStream;
@ -124,7 +127,11 @@ mod examples {
#[allow(unused_imports)]
use examples::*;
use prelude::profiler;
use prelude::profiler::prelude::*;
/// IDE startup function.
#[profile(Objective)]
#[wasm_bindgen]
#[allow(dead_code)]
pub fn entry_point_ide() {

View File

@ -248,6 +248,7 @@ pub struct Project {
impl Project {
/// Create a new project model.
#[profile(Detail)]
pub async fn new(
parent: impl AnyLogger,
project_manager: Option<Rc<dyn project_manager::API>>,
@ -303,6 +304,7 @@ impl Project {
}
/// Initializes the json and binary connection to Language Server, and creates a Project Model
#[profile(Detail)]
pub async fn new_connected(
parent: impl AnyLogger,
project_manager: Option<Rc<dyn project_manager::API>>,
@ -337,6 +339,7 @@ impl Project {
/// Creates a project model by opening a given project in project_manager, and initializing
/// the received json and binary connections.
#[profile(Detail)]
pub async fn new_opened(
parent: &Logger,
project_manager: Rc<dyn project_manager::API>,

View File

@ -43,45 +43,44 @@ struct Model {
impl Model {
/// Instantiate a new project presenter, which will display current project in the view.
#[profile(Task)]
fn setup_and_display_new_project(self: Rc<Self>) {
// Remove the old integration first. We want to be sure the old and new integrations will
// not race for the view.
*self.current_project.borrow_mut() = None;
let project_model = match self.controller.current_project() {
Some(model) => model,
None => return,
};
self.view.switch_view_to_project();
// We know the name of new project before it loads. We set it right now to avoid
// displaying a placeholder on the scene during loading.
let project_view = self.view.project();
let status_bar = self.view.status_bar().clone_ref();
let breadcrumbs = &project_view.graph().model.breadcrumbs;
breadcrumbs.project_name(project_model.name().to_string());
if let Some(project_model) = self.controller.current_project() {
self.view.switch_view_to_project();
// We know the name of new project before it loads. We set it right now to avoid
// displaying placeholder on the scene during loading.
let project_view = self.view.project();
let status_bar = self.view.status_bar().clone_ref();
let breadcrumbs = &project_view.graph().model.breadcrumbs;
breadcrumbs.project_name(project_model.name().to_string());
let status_notifications = self.controller.status_notifications().clone_ref();
let ide_controller = self.controller.clone_ref();
let project_controller =
controller::Project::new(project_model, status_notifications.clone_ref());
executor::global::spawn(async move {
match presenter::Project::initialize(
ide_controller,
project_controller,
project_view,
status_bar,
)
.await
{
Ok(project) => {
*self.current_project.borrow_mut() = Some(project);
}
Err(err) => {
let err_msg = format!("Failed to initialize project: {}", err);
error!(self.logger, "{err_msg}");
status_notifications.publish_event(err_msg)
}
let status_notifications = self.controller.status_notifications().clone_ref();
let ide_controller = self.controller.clone_ref();
let project_controller = controller::Project::new(project_model, status_notifications);
let project_presenter = presenter::Project::initialize(
ide_controller,
project_controller,
project_view,
status_bar,
);
crate::executor::global::spawn(async move {
match project_presenter.await {
Ok(project) => {
*self.current_project.borrow_mut() = Some(project);
}
});
}
Err(err) => {
let err_msg = format!("Failed to initialize project: {}", err);
error!(self.logger, "{err_msg}");
self.controller.status_notifications().publish_event(err_msg);
}
}
});
}
/// Open a project by name. It makes two calls to Project Manager: one for listing projects and
@ -145,6 +144,7 @@ impl Presenter {
///
/// The returned presenter is working and does not require any initialization. The current
/// project will be displayed (if any).
#[profile(Task)]
pub fn new(controller: controller::Ide, view: ide_view::root::View) -> Self {
let logger = Logger::new("Presenter");
let current_project = default();
@ -164,11 +164,12 @@ impl Presenter {
Self { model, network }.init()
}
#[profile(Detail)]
fn init(self) -> Self {
self.setup_status_bar_notification_handler();
self.setup_controller_notification_handler();
self.set_projects_list_on_welcome_screen();
self.model.clone_ref().setup_and_display_new_project();
executor::global::spawn(self.clone_ref().set_projects_list_on_welcome_screen());
self
}
@ -216,23 +217,19 @@ impl Presenter {
});
}
fn set_projects_list_on_welcome_screen(&self) {
let controller = self.model.controller.clone_ref();
let welcome_view_frp = self.model.view.welcome_screen().frp.clone_ref();
let logger = self.model.logger.clone_ref();
crate::executor::global::spawn(async move {
if let Ok(project_manager) = controller.manage_projects() {
match project_manager.list_projects().await {
Ok(projects) => {
let names = projects.into_iter().map(|p| p.name.into()).collect::<Vec<_>>();
welcome_view_frp.set_projects_list(names);
}
Err(err) => {
error!(logger, "Unable to get list of projects: {err}.");
}
#[profile(Detail)]
async fn set_projects_list_on_welcome_screen(self) {
if let Ok(project_manager) = self.model.controller.manage_projects() {
match project_manager.list_projects().await {
Ok(projects) => {
let names = projects.into_iter().map(|p| p.name.into()).collect::<Vec<_>>();
self.model.view.welcome_screen().frp.set_projects_list(names);
}
Err(err) => {
error!(self.model.logger, "Unable to get list of projects: {err}.");
}
}
});
}
}
}

View File

@ -70,6 +70,7 @@ pub struct Code {
impl Code {
/// Constructor. The returned structure works right away and does not need any initialization.
#[profile(Task)]
pub fn new(controller: controller::Text, project_view: &view::project::View) -> Self {
let network = frp::Network::new("presenter::code");
let view = project_view.code_editor().clone_ref();

View File

@ -459,6 +459,7 @@ pub struct Graph {
impl Graph {
/// Create graph presenter. The returned structure is working and does not require any
/// initialization.
#[profile(Task)]
pub fn new(
project: model::Project,
controller: controller::ExecutedGraph,
@ -470,6 +471,7 @@ impl Graph {
Self { network, model }.init(project_view)
}
#[profile(Detail)]
fn init(self, project_view: &view::project::View) -> Self {
let logger = &self.model.logger;
let network = &self.network;

View File

@ -34,6 +34,7 @@ struct Model {
}
impl Model {
#[profile(Task)]
fn new(
ide_controller: controller::Ide,
controller: controller::Project,
@ -165,6 +166,7 @@ impl Project {
///
/// The returned presenter will be already working: it will display the initial main graph, and
/// react to all notifications.
#[profile(Task)]
pub fn new(
ide_controller: controller::Ide,
controller: controller::Project,
@ -177,6 +179,7 @@ impl Project {
Self { network, model: Rc::new(model) }.init()
}
#[profile(Detail)]
fn init(self) -> Self {
let model = &self.model;
let network = &self.network;
@ -271,6 +274,7 @@ impl Project {
///
/// This calls the [`controller::Project::initialize`] method and use the initialization result
/// to construct working presenter.
#[profile(Task)]
pub async fn initialize(
ide_controller: controller::Ide,
controller: controller::Project,

View File

@ -163,9 +163,25 @@ commands.build.rust = async function (argv) {
if (argv.dev) {
args.push('--dev')
}
if (cargoArgs) {
args.push('--')
}
args.push('--')
// Enable source-file and line number information in the data generated by the `#[profile]`
// macro.
//
// The `profiler` library requires use of a Rust unstable feature, `proc_macro_span`, to be
// able to obtain this information.
//
// The IntelliJ Rust plugin does not support the `proc_macro_span` Rust feature; using it causes
// JetBrains IDEs to become entirely unaware of the items produced by `#[profile]`.
// (See: https://github.com/intellij-rust/intellij-rust/issues/8655)
//
// In order to have line number information in actual usage, but keep everything understandable
// by JetBrains IDEs, we need IntelliJ/CLion to build crates differently from how they are
// built for the application to be run. This is accomplished by gating the use of the unstable
// functionality by a Cargo feature. Cargo features are disabled by default, so when a Rust IDE
// builds crates internally in order to determine macro expansions, it will do so without line
// numbers. When this script is used to build the application, it is not for the purpose of IDE
// macro expansion, so we can safely enable line numbers.
args.push('--features=enso-profiler/line-numbers')
await run_cargo('wasm-pack', args)
await patch_file(paths.wasm.glue, js_workaround_patcher)
await fs.rename(paths.wasm.mainRaw, paths.wasm.main)

View File

@ -21,6 +21,7 @@ enso-generics = { path = "../../generics"}
enso-logger = { path = "../../logger"}
enso-optics = { path = "../../optics"}
enso-prelude = { path = "../../prelude"}
enso-profiler = { path = "../../profiler"}
enso-shapely = { path = "../../shapely"}
enso-shortcuts = { path = "../../shortcuts" }
enso-types = { path = "../../types" }

View File

@ -247,6 +247,9 @@ impl WorldData {
display_mode.set(1)
} else if key == "Digit2" {
display_mode.set(2)
} else if key == "KeyP" {
let log = profiler::internal::take_log();
web_sys::console::log_1(&log.into());
}
}
});

View File

@ -66,6 +66,8 @@ pub mod prelude {
pub use enso_logger::DefaultWarningLogger as Logger;
pub use enso_logger::*;
pub use enso_prelude::*;
pub use enso_profiler as profiler;
pub use enso_profiler::prelude::*;
pub use enso_shapely::newtype_prim;
pub use enso_shapely::newtype_prim_no_default;
pub use enso_shapely::newtype_prim_no_default_no_display;

View File

@ -17,6 +17,7 @@ ensogl-example-glyph-system = { path = "glyph-system" }
ensogl-example-list-view = { path = "list-view" }
ensogl-example-mouse-events = { path = "mouse-events" }
ensogl-example-profiling-run-graph = { path = "profiling-run-graph" }
ensogl-example-render-profile = { path = "render-profile" }
ensogl-example-scroll-area = { path = "scroll-area" }
ensogl-example-shape-system = { path = "shape-system" }
ensogl-example-slider = { path = "slider" }

View File

@ -0,0 +1,35 @@
[package]
name = "ensogl-example-render-profile"
version = "0.1.0"
authors = ["Enso Team <contact@enso.org>"]
edition = "2021"
[lib]
crate-type = ["cdylib", "rlib"]
[dependencies]
enso-frp = { path = "../../../frp" }
enso-profiler = { path = "../../../profiler" }
enso-profiler-data = { path = "../../../profiler/data" }
enso-profiler-flame-graph = { path = "../../../profiler/flame-graph" }
enso-web = { path = "../../../web" }
ensogl-core = { path = "../../core" }
ensogl-flame-graph = { path = "../../component/flame-graph" }
ensogl-hardcoded-theme = { path = "../../app/theme/hardcoded" }
ensogl-text = { path = "../../component/text" }
ensogl-text-msdf-sys = { path = "../../component/text/msdf-sys" }
futures = "0.3"
wasm-bindgen = { version = "0.2.58", features = [ "nightly" ] }
wasm-bindgen-futures = "0.4"
[dependencies.web-sys]
version = "0.3"
features = [
'Headers',
'Request',
'RequestInit',
'RequestMode',
'Response',
'Window',
]

View File

@ -0,0 +1,86 @@
//! Renders profiling data, obtained from a file, as a flame graph.
#![warn(missing_copy_implementations)]
#![warn(missing_debug_implementations)]
#![warn(missing_docs)]
#![warn(trivial_casts)]
#![warn(trivial_numeric_casts)]
#![warn(unsafe_code)]
#![warn(unused_import_braces)]
#![warn(unused_qualifications)]
use ensogl_core::prelude::*;
use wasm_bindgen::prelude::*;
use enso_profiler_data as profiler_data;
use ensogl_core::application;
use ensogl_core::data::color;
use ensogl_core::display;
use ensogl_core::display::navigation::navigator;
use ensogl_core::display::style::theme;
use ensogl_flame_graph as flame_graph;
// ===================
// === Entry Point ===
// ===================
/// Render a graph of a profile file.
#[wasm_bindgen]
#[allow(dead_code)]
pub async fn entry_point_render_profile() {
use ensogl_core::display::object::ObjectOps;
let app = application::Application::new("root");
let world = &app.display;
let scene = &world.default_scene;
let navigator = navigator::Navigator::new(scene, &scene.camera());
init_theme(scene);
let data = get_data().await;
let measurements: profiler_data::Measurement<profiler_data::OpaqueMetadata> =
data.parse().unwrap();
let flame_graph = flame_graph::FlameGraph::from_data(measurements.into(), &app);
scene.add_child(&flame_graph);
scene.layers.main.add_exclusive(&flame_graph);
world.keep_alive_forever();
world
.on
.before_frame
.add(move |_time| {
let _keep_alive = &navigator;
let _keep_alive = &flame_graph;
})
.forget();
}
/// Read profile data from a file. The file must be located at `/profile.json` in the root of the
/// directory that will be made available by the webserver, i.e. `enso/dist/content`.
async fn get_data() -> String {
use wasm_bindgen::JsCast;
let url = "/profile.json";
let mut opts = web_sys::RequestInit::new();
opts.method("GET");
opts.mode(web_sys::RequestMode::Cors);
let request = web_sys::Request::new_with_str_and_init(url, &opts).unwrap();
request.headers().set("Accept", "application/json").unwrap();
let window = web_sys::window().unwrap();
let response = window.fetch_with_request(&request);
let response = wasm_bindgen_futures::JsFuture::from(response).await.unwrap();
assert!(response.is_instance_of::<web_sys::Response>());
let response: web_sys::Response = response.dyn_into().unwrap();
let data = response.text().unwrap();
let data = wasm_bindgen_futures::JsFuture::from(data).await.unwrap();
data.as_string().unwrap()
}
fn init_theme(scene: &display::Scene) {
let theme_manager = theme::Manager::from(&scene.style_sheet);
let theme = theme::Theme::new();
const COLOR_PATH: &str = "flame_graph_color";
theme.set(COLOR_PATH, color::Rgb::new(1.0, 45.0 / 255.0, 0.0));
theme_manager.register("theme", theme);
theme_manager.set_enabled(&["theme".to_string()]);
let style_watch = ensogl_core::display::shape::StyleWatch::new(&scene.style_sheet);
style_watch.get(COLOR_PATH);
}

View File

@ -37,6 +37,7 @@ pub use ensogl_example_glyph_system as glyph_system;
pub use ensogl_example_list_view as list_view;
pub use ensogl_example_mouse_events as mouse_events;
pub use ensogl_example_profiling_run_graph as profiling_run_graph;
pub use ensogl_example_render_profile as render_profile;
pub use ensogl_example_scroll_area as scroll_area;
pub use ensogl_example_shape_system as shape_system;
pub use ensogl_example_slider as slider;

View File

@ -13,3 +13,6 @@ enso-web = { path = "../web" }
[dev-dependencies]
futures = "0.3"
[features]
line-numbers = ["enso-profiler-macros/lineno"]

View File

@ -0,0 +1,66 @@
//! Tool that generates human-readable reports from profiling data.
//!
//! # Usage
//!
//! The tool reads a JSON-formatted event log from stdin, and writes a report to stdout.
//!
//! For example:
//!
//! ```console
//! ~/git/enso/data $ cargo run --bin measurements < profile.json | less
//! ```
#![feature(test)]
#![deny(unconditional_recursion)]
#![warn(missing_copy_implementations)]
#![warn(missing_debug_implementations)]
#![warn(missing_docs)]
#![warn(trivial_casts)]
#![warn(trivial_numeric_casts)]
#![warn(unsafe_code)]
#![warn(unused_import_braces)]
use enso_profiler_data as profiler_data;
use std::io::Read;
/// Format a [`profiler_data::Interval`] in an easy-to-read way.
fn fmt_interval(interval: profiler_data::Interval) -> String {
let start = interval.start.into_ms();
let end = interval.end.map(|x| format!("{:.1}", x.into_ms())).unwrap_or_default();
format!("{:.1}-{}", start, end)
}
/// Pretty-print a [`profiler_data::Measurement`], including all children, in a way that illustrates
/// the hierarchy of the data. Results will be written to stdout.
fn print_measurement(measurement: &enso_profiler_data::Measurement<()>, i: usize) {
let mut indent = String::new();
for _ in 0..i {
indent.push_str(" ");
}
println!("{}{}", indent, measurement.label);
match &measurement.lifetime {
profiler_data::Lifetime::Async(profiler_data::AsyncLifetime { active, .. }) => {
println!("{} intervals:", indent);
for active in active {
println!("{} interval: {}", indent, fmt_interval(*active));
}
}
profiler_data::Lifetime::NonAsync { active } => {
println!("{} interval: {}", indent, fmt_interval(*active));
}
}
println!("{} children:", indent);
for child in &measurement.children {
print_measurement(child, i + 2);
}
}
fn main() {
let mut log = String::new();
std::io::stdin().read_to_string(&mut log).unwrap();
let app_lifetime: profiler_data::Measurement<()> = log.parse().unwrap();
for root in app_lifetime.children {
print_measurement(&root, 0);
}
}

View File

@ -214,9 +214,9 @@ pub struct Measurement<M> {
pub lifetime: Lifetime,
/// Identifies the profiler's source and scope to the user.
pub label: Label,
/// Profilers started by this profiler.
/// Profilers started by this profiler, ordered by time created.
pub children: Vec<Self>,
/// Metadata attached to this profiler.
/// Metadata attached to this profiler, ordered by time logged.
pub metadata: Vec<Metadata<M>>,
}

View File

@ -67,7 +67,8 @@ pub(crate) fn interpret<M>(
// Build measurements from accumulated measurement data.
let mut measurements: collections::HashMap<_, _> =
builders.into_iter().map(|(k, v)| (k, v.build())).collect();
// Organize measurements into trees.
// Organize measurements into trees. Use reverse chronological order as a convenient topological
// sort (parents are always created before children).
let mut root = root_builder.build();
for (id, parent) in order.into_iter().rev() {
let child = measurements.remove(&id).unwrap();
@ -82,9 +83,18 @@ pub(crate) fn interpret<M>(
};
parent.push(child);
}
// Organize children by creation time. (Previous pass gathered them in reverse order.)
reverse_subtrees(&mut root);
Ok(root)
}
fn reverse_subtrees<M>(root: &mut crate::Measurement<M>) {
root.children.reverse();
for child in root.children.iter_mut() {
reverse_subtrees(child);
}
}
// =================

View File

@ -0,0 +1,20 @@
//! Build script for [`enso_profiler_macros`]. This is needed because `profiler_macros` has a
//! profiling level controlled by the value of an environment variable at compile time, and cargo
//! needs to be made aware that changes to the env can invalidate the result of compiling this
//! crate and any dependents.
#![warn(missing_copy_implementations)]
#![warn(missing_debug_implementations)]
#![warn(missing_docs)]
#![warn(trivial_casts)]
#![warn(trivial_numeric_casts)]
#![warn(unsafe_code)]
#![warn(unused_import_braces)]
#![warn(unused_qualifications)]
fn main() {
println!("cargo:rerun-if-env-changed=ENSO_MAX_PROFILING_LEVEL");
// This is a no-op assignment, except it makes cargo aware that the output depends on the env.
let value = std::env::var("ENSO_MAX_PROFILING_LEVEL").unwrap_or_default();
println!("cargo:rustc-env=ENSO_MAX_PROFILING_LEVEL={}", value);
}

View File

@ -271,33 +271,25 @@ pub fn profile(
func.into_token_stream().into()
}
fn profile_async(obj_ident: syn::Ident, label: String, func: &mut syn::ItemFn) {
let start_profiler = start_profiler(obj_ident, label, func.sig.asyncness.is_some());
for s in &mut func.block.stmts {
WrapAwait.visit_stmt_mut(s);
}
let block = &func.block;
let body = quote::quote! {{
#start_profiler
async move {
profiler::internal::Profiler::resume(&__profiler_scope.0);
let result = #block;
std::mem::drop(__profiler_scope);
result
}
}};
let output_ty = match &func.sig.output {
syn::ReturnType::Default => quote::quote! { () },
syn::ReturnType::Type(_, ty) => ty.to_token_stream(),
};
let output = quote::quote! {
-> impl std::future::Future<Output=#output_ty>
};
func.sig.asyncness = None;
func.sig.output = syn::parse2(output).unwrap();
func.block = syn::parse2(body).unwrap();
#[cfg(not(feature = "lineno"))]
/// Decorate the input with file:line info determined by the proc_macro's call site.
fn make_label(ident: &syn::Ident) -> String {
format!("{} (?:?)", ident)
}
#[cfg(feature = "lineno")]
/// Decorate the input with file:line info determined by the proc_macro's call site.
fn make_label(ident: &syn::Ident) -> String {
let span = proc_macro::Span::call_site();
let file = span.source_file().path();
let path = file.as_path().to_string_lossy();
let line = span.start().line;
format!("{} ({}:{})", ident, path, line)
}
// === profile_sync ===
fn profile_sync(obj_ident: syn::Ident, label: String, func: &mut syn::ItemFn) {
let start_profiler = start_profiler(obj_ident, label, func.sig.asyncness.is_some());
let block = &func.block;
@ -329,47 +321,217 @@ fn start_profiler(
}
}
#[cfg(not(feature = "lineno"))]
/// Decorate the input with file:line info determined by the proc_macro's call site.
fn make_label(ident: &syn::Ident) -> String {
format!("{} (?:?)", ident)
// === profile_async ===
fn profile_async(obj_ident: syn::Ident, label: String, func: &mut syn::ItemFn) {
for s in &mut func.block.stmts {
WrapAwait.visit_stmt_mut(s);
}
let before_async = start_profiler(obj_ident, label, func.sig.asyncness.is_some());
let start_async = quote::quote! {
profiler::internal::Profiler::resume(&__profiler_scope.0);
};
let end_async = quote::quote! {
std::mem::drop(__profiler_scope);
};
wrap_async_fn(func, before_async, start_async, end_async);
}
#[cfg(feature = "lineno")]
/// Decorate the input with file:line info determined by the proc_macro's call site.
fn make_label(ident: &syn::Ident) -> String {
let span = proc_macro::Span::call_site();
let file = span.source_file().path();
let path = file.as_path().to_string_lossy();
let line = span.start().line;
format!("{} ({}:{})", ident, path, line)
/// Convert an `async fn` into a `fn` returning a `Future`, implemented with an `async` block.
///
/// Supports inserting statements before the `async` block is entered, just after entering it, and
/// just before leaving it. (The latter two will be in the same scope).
///
/// If no statements are inserted, the output will be functionally equivalent to the input
/// (except the output won't `impl Send` even if the original `async fn` did).
fn wrap_async_fn(
func: &mut syn::ItemFn,
before_async: proc_macro2::TokenStream,
start_async: proc_macro2::TokenStream,
end_async: proc_macro2::TokenStream,
) {
let block = &func.block;
let ret_ty = match &func.sig.output {
syn::ReturnType::Default => quote::quote! { () },
syn::ReturnType::Type(_, ty) => ty.into_token_stream(),
};
let body = quote::quote! {{
#before_async
async move {
#start_async
let result: #ret_ty = #block;
#end_async
result
}
}};
let output_ty = match &func.sig.output {
syn::ReturnType::Default => quote::quote! { () },
syn::ReturnType::Type(_, ty) => ty.to_token_stream(),
};
let output_lifetime = syn::Lifetime::new("'__profiler_out", proc_macro2::Span::call_site());
let lifetimes = explicitize_lifetimes(&mut func.sig);
let output = if lifetimes.is_empty() {
quote::quote! {
-> impl std::future::Future<Output=#output_ty>
}
} else {
// Bound all input lifetimes on the output lifetime.
for param in &mut func.sig.generics.params {
if let syn::GenericParam::Lifetime(def) = param {
def.bounds.push(output_lifetime.clone());
}
}
// Add a definition for the output lifetime.
let lifetime_def = syn::LifetimeDef::new(output_lifetime.clone());
func.sig.generics.params.insert(0, syn::GenericParam::Lifetime(lifetime_def));
// Apply the output lifetime to the output.
quote::quote! {
-> impl std::future::Future<Output=#output_ty> + #output_lifetime
}
};
func.sig.asyncness = None;
func.sig.output = syn::parse2(output).unwrap();
func.block = syn::parse2(body).unwrap();
}
/// Make all lifetimes in function signature explicit.
///
/// Returns the lifetimes used in the function signature.
fn explicitize_lifetimes(sig: &mut syn::Signature) -> Vec<syn::Lifetime> {
// Go through the args; find:
// - anonymous lifetime: '_
// - implicit lifetimes: &foo
// - explicit lifetimes: &'a
// Make all input lifetimes explicit:
// - Use new lifetime explicitly in arg list.
// - Define new lifetime in generic params.
let mut input_transformer = ExplicitizeInputLifetimes::default();
for input in &mut sig.inputs {
input_transformer.visit_fn_arg_mut(input);
}
let ExplicitizeInputLifetimes { new_lifetimes, existing_lifetimes } = input_transformer;
let mut all_lifetimes = existing_lifetimes;
all_lifetimes.extend_from_slice(&new_lifetimes);
let new_lifetimes =
new_lifetimes.into_iter().map(|lt| syn::GenericParam::Lifetime(syn::LifetimeDef::new(lt)));
sig.generics.params.extend(new_lifetimes);
// There are two cases where output lifetimes may be elided:
// - There's exactly one lifetime in the inputs.
// - There's a receiver with a lifetime.
// If either case occurs, make any implicit output lifetimes explicit.
let default_lifetime = if all_lifetimes.len() == 1 {
Some(all_lifetimes[0].clone())
} else {
get_receiver_lifetime(sig).cloned()
};
if let Some(lifetime) = default_lifetime {
ExplicitizeOutputLifetimes { lifetime }.visit_return_type_mut(&mut sig.output);
}
all_lifetimes
}
#[derive(Default)]
struct ExplicitizeInputLifetimes {
new_lifetimes: Vec<syn::Lifetime>,
existing_lifetimes: Vec<syn::Lifetime>,
}
impl ExplicitizeInputLifetimes {
fn gen_lifetime(&mut self) -> syn::Lifetime {
let name = format!("'__profiler{}", self.new_lifetimes.len());
let new = syn::Lifetime::new(&name, proc_macro2::Span::call_site());
self.new_lifetimes.push(new.clone());
new
}
fn visit_elidable_lifetime(&mut self, lifetime: &mut Option<syn::Lifetime>) {
match lifetime {
Some(lifetime) => self.visit_lifetime_mut(lifetime),
None => *lifetime = Some(self.gen_lifetime()),
}
}
}
impl visit_mut::VisitMut for ExplicitizeInputLifetimes {
// Handles 'x in generic parameters in types of non-self arguments.
fn visit_lifetime_mut(&mut self, lifetime: &mut syn::Lifetime) {
let name = lifetime.ident.to_string();
if &name == "_" {
*lifetime = self.gen_lifetime();
} else {
self.existing_lifetimes.push(lifetime.clone());
}
}
// Handles &self.
fn visit_receiver_mut(&mut self, receiver: &mut syn::Receiver) {
if let Some((_, lifetime)) = &mut receiver.reference {
self.visit_elidable_lifetime(lifetime);
}
}
// Handles & in types of non-self arguments.
fn visit_type_reference_mut(&mut self, type_reference: &mut syn::TypeReference) {
self.visit_elidable_lifetime(&mut type_reference.lifetime);
}
}
struct ExplicitizeOutputLifetimes {
lifetime: syn::Lifetime,
}
impl visit_mut::VisitMut for ExplicitizeOutputLifetimes {
// Handles 'x in generic parameters in types.
fn visit_lifetime_mut(&mut self, lifetime: &mut syn::Lifetime) {
if &lifetime.ident.to_string() == "_" {
*lifetime = self.lifetime.clone();
}
}
// Handles & in types.
fn visit_type_reference_mut(&mut self, type_reference: &mut syn::TypeReference) {
if type_reference.lifetime.is_none() {
type_reference.lifetime = Some(self.lifetime.clone());
}
}
}
fn get_receiver_lifetime(sig: &syn::Signature) -> Option<&syn::Lifetime> {
match sig.inputs.first() {
Some(syn::FnArg::Receiver(syn::Receiver {
reference: Some((_, Some(lifetime))), ..
})) => Some(lifetime),
_ => None,
}
}
struct WrapAwait;
impl visit_mut::VisitMut for WrapAwait {
fn visit_expr_mut(&mut self, expr: &mut syn::Expr) {
if let syn::Expr::Await(await_) = expr {
let new_expr = wrap_await(await_);
*expr = new_expr;
match expr {
syn::Expr::Await(await_) => *expr = wrap_await(await_),
_ => syn::visit_mut::visit_expr_mut(self, expr),
}
}
}
fn wrap_await(await_: &syn::ExprAwait) -> syn::Expr {
let expr = &await_.base;
fn wrap_await(await_: &mut syn::ExprAwait) -> syn::Expr {
let expr = &mut await_.base;
WrapAwait.visit_expr_mut(expr);
assert!(
await_.attrs.is_empty(),
"#[profile] cannot wrap a function that applies attributes to an .await expression"
);
let wrapped = quote::quote! {
{
({
let future = #expr;
profiler::internal::Profiler::pause(&__profiler_scope.0);
let result = future.await;
profiler::internal::Profiler::resume(&__profiler_scope.0);
result
}
})
};
syn::parse2(wrapped).unwrap()
}

View File

@ -167,6 +167,17 @@ use internal::*;
// ===============
// === prelude ===
// ===============
/// Widely-used exports.
pub mod prelude {
pub use crate::profile;
}
// ======================
// === MetadataLogger ===
// ======================
@ -423,7 +434,7 @@ mod tests {
#[profile(Objective)]
async fn profiled() -> u32 {
let block = async { 4 };
block.await
block.await + 1
}
let future = profiled();
futures::executor::block_on(future);
@ -600,6 +611,45 @@ mod compile_tests {
#[profile(Objective)]
async fn profiled_async() {}
#[profile(Objective)]
async fn polymorphic_return() -> Box<dyn PartialEq<u32>> {
Box::new(23)
}
#[profile(Objective)]
async fn borrows_input_references_in_output(x: &u32) -> &u32 {
x
}
#[profile(Objective)]
#[allow(clippy::needless_lifetimes)]
async fn borrows_input_references_in_output_explicitly<'a>(x: &'a u32) -> &'a u32 {
x
}
#[profile(Objective)]
async fn borrows_input_doesnt_use(_: &u32) -> u32 {
4
}
#[profile(Objective)]
async fn borrows_input_uses(x: &u32) -> u32 {
*x
}
#[profile(Objective)]
async fn borrows_two_args(x: &u32, y: &u32) -> u32 {
*x + *y
}
struct Foo(u32);
impl Foo {
#[profile(Objective)]
async fn borrows_self_and_arg(&self, x: &u32) -> u32 {
self.0 + *x
}
}
#[profile(Detail)]
#[allow(unsafe_code)]
unsafe fn profiled_unsafe() {}