From 0a5e25e4f0369ced8ba0f1840629c82ff25e693e Mon Sep 17 00:00:00 2001 From: YetAnotherMinion Date: Fri, 10 Dec 2021 00:18:01 +0000 Subject: [PATCH] feat: use tracing crate to measure cpu time --- Cargo.toml | 6 +- .../single-page/script/generate_test_file | 4 + examples/single-page/src/Main.elm | 2 +- src/fixture.rs | 2 +- src/main.rs | 224 ++++++++++-------- src/reporting.rs | 14 +- src/timings.rs | 140 +++++++++++ src/transpile.rs | 1 + 8 files changed, 289 insertions(+), 104 deletions(-) create mode 100755 examples/single-page/script/generate_test_file create mode 100644 src/timings.rs create mode 100644 src/transpile.rs diff --git a/Cargo.toml b/Cargo.toml index 442f2dc..a2a5d2f 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -19,7 +19,11 @@ serde = { version = "1.0", features = [ "derive" ] } serde_json = { version ="1.0", features = [] } structopt = { version = "0.3" } elm-project-utils = { path = "../../../infra/rust-elm-project-utils" } -tracing = "0.1" +tracing = { version = "0.1", features = [] } +rustc-hash = "1.1" + +# Required to transpile view functions to Rust +genco = "0.15" # All of these are required for deno's javascript runtime. We need to keep the # same versions as other projects in our cargo workspace. Multiple different diff --git a/examples/single-page/script/generate_test_file b/examples/single-page/script/generate_test_file new file mode 100755 index 0000000..337e569 --- /dev/null +++ b/examples/single-page/script/generate_test_file @@ -0,0 +1,4 @@ +#!/usr/bin/env bash + +# generate a 10MB test file +< /dev/urandom tr -dc "[:alnum:]" | head -c10000000 > file.txt diff --git a/examples/single-page/src/Main.elm b/examples/single-page/src/Main.elm index 79cacd8..7c82fa7 100644 --- a/examples/single-page/src/Main.elm +++ b/examples/single-page/src/Main.elm @@ -1,4 +1,4 @@ -module Main exposing (view, view2, view3) +module Main exposing (view, view2, view3, badReturnType) import Html exposing (Html, div, text) import Svg exposing (Svg, svg) diff --git a/src/fixture.rs b/src/fixture.rs index c78c19b..1769988 100644 --- a/src/fixture.rs +++ b/src/fixture.rs @@ -1,5 +1,5 @@ +use crate::{InputType, OutputType}; use std::fmt::Display; -use crate::{OutputType, InputType}; pub(crate) fn generate>( source_checksum: u64, diff --git a/src/main.rs b/src/main.rs index 7ae6435..77664ae 100644 --- a/src/main.rs +++ b/src/main.rs @@ -1,5 +1,7 @@ extern crate naive_wadler_prettier as pretty; use crate::reporting::{CompilerError, InterpreterError, Problem, SetupError, TypeError}; +use crate::timings::Timings; +use elm_project_utils::ChecksumConstraint; use elmi::DataBinary; use os_pipe::dup_stderr; use pretty::pretty; @@ -14,19 +16,18 @@ use std::process::{Command, Stdio}; use std::sync::Arc; use std::time::Instant; use structopt::StructOpt; -use elm_project_utils::ChecksumConstraint; use tokio; -use tracing::{span, info_span}; -use crate::timings::Timings; +use tracing::{info_span, span, Instrument}; -mod reporting; mod fixture; +mod reporting; mod timings; +mod transpile; fn main() { let args = Arguments::from_args(); - - let span_subscriber = Timings::new(); + + let (span_subscriber, timing_report) = Timings::new(); tracing::subscriber::set_global_default(span_subscriber).unwrap(); match args { @@ -39,26 +40,43 @@ fn main() { output, verbosity, } => { - let run_program = info_span!("run_program_span"); - run_program.enter(); let start = Instant::now(); - if let Err(problem) = exec(file, debug, function, input, output, verbosity) { - eprintln!( - "\t\x1b[1;92mFinished\x1b[0m in {:?}", - Instant::now() - start - ); + let span = info_span!("exec"); + let timing_guard = span.enter(); + let result = exec(file, debug, function, input, output, verbosity); + drop(timing_guard); + if let Err(problem) = result { + let span = info_span!("pretty print problem"); + let timing_guard = span.enter(); eprintln!("{}", pretty(80, problem.to_doc())); - } else { - { - let stdout = io::stdout(); - let mut handle = stdout.lock(); - handle.flush().unwrap(); - } - eprintln!( - "\n\t\x1b[1;92mFinished\x1b[0m in {:?}", - Instant::now() - start - ); + drop(timing_guard); } + { + let stdout = io::stdout(); + let mut handle = stdout.lock(); + handle.flush().unwrap(); + } + + if verbosity > 1 { + let mut report = timing_report.dump().unwrap(); + report.sort_by(|(_, a), (_, b)| b.partial_cmp(a).unwrap()); + + for (step, duration) in report.iter() { + eprintln!("[{:>10.3?}] {}", duration, step); + } + } + eprintln!( + "\t\x1b[1;92mFinished\x1b[0m [{}] in {:?}", + "unoptimized", + Instant::now() - start + ); + } + Arguments::Transpile { + file, + function, + verbosity, + } => { + println!("todo transpile the code") } } } @@ -71,31 +89,29 @@ fn exec( output: Option, verbosity: u64, ) -> Result<(), Problem> { - info_span!("another_span").enter(); // Our first elm make call is where we build the users program. There is a pretty good chance // this won't work. let mut command = Command::new("elm"); - command - .arg("make") - .arg("--output") - .arg("/dev/null"); - //.stdin(Stdio::null()); - //.stdout(Stdio::null()); - // I am using the default inherit stderr behavior here. - //.stderr(Stdio::piped()); + command.arg("make").arg("--output").arg("/dev/null"); + //.stdin(Stdio::null()); + //.stdout(Stdio::null()); + // I am using the default inherit stderr behavior here. + //.stderr(Stdio::piped()); if debug { command.arg("--debug"); } command.arg(&file); - let start = Instant::now(); + let span = info_span!("elm make target file"); + let timing_guard = span.enter(); match command.output() { Ok(output) => { if !output.status.success() { io::stderr().write_all(&output.stderr).unwrap(); + io::stderr().write_all(&output.stdout).unwrap(); return Err(CompilerError::FailedBuildingFixture.into()); - } + } if verbosity > 0 { io::stderr().write_all(&output.stderr).unwrap(); } @@ -105,7 +121,7 @@ fn exec( return Err(Problem::Wildcard("elm failed".into())); } } - eprintln!("[{:?}] compiled {:?}", Instant::now() - start, file); + drop(timing_guard); // Step 2, find the elm.json and elm-stuff directory let elm_project_dir = @@ -155,7 +171,8 @@ fn exec( let interfaces = load_interfaces(&elm_cache_dir)?; // Step 5, check for the desired function - let start = Instant::now(); + let span = info_span!("resolved target function"); + let timing_guard = span.enter(); let (input_type, output_type) = match interfaces.get(&target_module) { Some(interface) => match interface.values.get(&elmi::Name::from(&function)) { Some(annotation) => { @@ -163,17 +180,18 @@ fn exec( resolve_function_type(tipe)? } - None => return Err(CompilerError::BadImport(function).into()), + None => return Err(CompilerError::BadImport(target_module, function).into()), }, None => return Err(CompilerError::MissingModuleTypeInformation(target_module).into()), }; - eprintln!("[{:?}] resolved target function", Instant::now() - start); + drop(timing_guard); // step 6 create our private project let generator_dir = setup_generator_project(verbosity, elm_project_dir.clone())?; // step 7 create an Elm fixture file to run our function - let start = Instant::now(); + let span = info_span!("create Elm fixture files"); + let timing_guard = span.enter(); let (gen_module_name, source) = fixture::generate( source_checksum, target_module, @@ -189,11 +207,7 @@ fn exec( .map_err(|io_err| CompilerError::WriteOutputFailed(io_err, source_filename.clone()))? .write_all(source.as_bytes()) .map_err(|io_err| CompilerError::WriteOutputFailed(io_err, source_filename.clone()))?; - eprintln!( - "[{:?}] created generator Elm program", - Instant::now() - start - ); - + drop(timing_guard); // step 8 compile the fixture let mut intermediate_file = generator_dir.join("obj").join(&gen_module_name); @@ -221,7 +235,8 @@ fn exec( } command.arg(&source_filename); - let start = Instant::now(); + let span = info_span!("elm make fixture file"); + let timing_guard = span.enter(); match command.output() { Ok(output) => { if !output.status.success() { @@ -232,13 +247,7 @@ fn exec( return Err(CompilerError::FailedBuildingFixture.into()); } } - if verbosity > 1 { - eprintln!( - "compiled {:?} in {:?}", - intermediate_file, - Instant::now() - start, - ); - } + drop(timing_guard); // Step 9 fixup the compiled script to run in Deno @@ -251,7 +260,7 @@ fn exec( // `"REPLACE_ME" + "abc" * 2000` we would have over 6k bytes to write out the new code. We // will have to do some extra book keeping to make sure the buffer space is big enough // for the replacement code. - let mut final_script = ( || { + let mut final_script = (|| { let mut final_script = data .replace("'REPLACE_ME_WITH_JSON_STRINGIFY'", "JSON.stringify(x)") //.replace("setTimeout", "(function(x, y) { globalThis.__bootstrap.timers.setTimeout(x, y)})") @@ -264,7 +273,7 @@ fn exec( });"#, ) .replace(";}(this));", ";}(globalThis));"); - + final_script.push_str("\n\n"); // I think that when I set this script to be the main module, I am skipping the // deno/runtime/js/99_main.js script that sets up a bunch of global variables. If I @@ -273,7 +282,9 @@ fn exec( // scope. Figure out if I need to include all of them. For example, starmelon does not need // to perform http calls right now, but I eventually want to. final_script.push_str("const { setTimeout } = globalThis.__bootstrap.timers;"); - final_script.push_str("Deno.core.setMacrotaskCallback(globalThis.__bootstrap.timers.handleTimerMacrotask);\n"); + final_script.push_str( + "Deno.core.setMacrotaskCallback(globalThis.__bootstrap.timers.handleTimerMacrotask);\n", + ); final_script.push_str("globalThis.setTimeout = setTimeout;"); final_script.push_str(&format!("var worker = Elm.{}.init();\n", &gen_module_name)); @@ -421,7 +432,7 @@ fn exec( Some(path) => { let buffer = std::fs::read(&path) .map_err(|io_err| CompilerError::ReadInputFailed(io_err, path.clone()))?; - + buffer } }; @@ -445,12 +456,18 @@ fn exec( }; let start = Instant::now(); - tokio::runtime::Builder::new_current_thread() + let span = info_span!("create tokio runtime"); + let timing_guard = span.enter(); + let sys = tokio::runtime::Builder::new_current_thread() .enable_all() .build() - .unwrap() - .block_on(async move { runtime::xyz(worker, main_module, input).await })?; - eprintln!("eval javascript in {:?}", Instant::now() - start); + .unwrap(); + drop(timing_guard); + + let span = info_span!("eval javascript"); + let timing_guard = span.enter(); + sys.block_on(async move { runtime::xyz(worker, main_module, input).await })?; + drop(timing_guard); // step 13 receive the callback // If I understood which combination of run_event_loop was required to execute @@ -458,22 +475,20 @@ fn exec( // now. Another way to do this would be with an Arc. This will panic if the // mailbox is currently borrowed match mailbox.replace(None) { - Some(Ok(buffer)) => { - match output { - None => { - io::stdout() - .write_all(&buffer) - .map_err(|io_err| CompilerError::WriteOutputFailed(io_err, "stdout".into()))?; - }, - Some(filename) => { - let mut f = fs::File::create(&filename) - .map_err(|io_err| CompilerError::WriteOutputFailed(io_err, filename))?; - - f.write_all(&buffer) - .map_err(|io_err| CompilerError::WriteOutputFailed(io_err, "stdout".into()))?; - } + Some(Ok(buffer)) => match output { + None => { + io::stdout() + .write_all(&buffer) + .map_err(|io_err| CompilerError::WriteOutputFailed(io_err, "stdout".into()))?; } - } + Some(filename) => { + let mut f = fs::File::create(&filename) + .map_err(|io_err| CompilerError::WriteOutputFailed(io_err, filename))?; + + f.write_all(&buffer) + .map_err(|io_err| CompilerError::WriteOutputFailed(io_err, "stdout".into()))?; + } + }, Some(Err(problem)) => { println!("had a problem {}", problem); } @@ -499,9 +514,14 @@ fn load_interfaces(elm_cache_dir: &Path) -> Result { // step 4 load all the modules let start = Instant::now(); + let parse_span = info_span!("parse elmi"); + let parse_guard = parse_span.enter(); + + let load_span = info_span!("file reads"); + let load_guard = load_span.enter(); let data = std::fs::read(&path) .map_err(|io_err| CompilerError::ReadInputFailed(io_err, path.clone()))?; - eprintln!("[{:?}] loaded {:?}", Instant::now() - start, path); + drop(load_guard); let start = Instant::now(); let (_remaining, i) = elmi::Interface::get(&data).map_err(|_err| { @@ -516,7 +536,6 @@ fn load_interfaces(elm_cache_dir: &Path) -> Result>() .join("."); - eprintln!("[{:?}] parsed {:?}", Instant::now() - start, module_name); interfaces.insert(module_name, i); } } @@ -571,7 +590,6 @@ enum Arguments { Exec { #[structopt(parse(from_os_str))] file: PathBuf, - function: String, #[structopt(long)] debug: bool, @@ -582,6 +600,13 @@ enum Arguments { #[structopt(short = "v", parse(from_occurrences))] verbosity: u64, }, + Transpile { + #[structopt(parse(from_os_str))] + file: PathBuf, + function: String, + #[structopt(short = "v", parse(from_occurrences))] + verbosity: u64, + }, } #[derive(Debug, Copy, Clone)] @@ -715,14 +740,12 @@ fn setup_generator_project(verbosity: u64, elm_project_dir: PathBuf) -> Result

Result

, S: AsRef>( our_temp_dir: P, package: S, ) -> Result<(), Problem> { - info_span!("elm_install").enter(); + let span = info_span!("elm_install"); + let _ = span.enter(); let mut command = Command::new("elm"); command @@ -830,7 +854,6 @@ fn elm_install, S: AsRef>( Ok(()) } - mod runtime { use crate::reporting::InterpreterError; use crate::ValidatedInput; @@ -850,6 +873,7 @@ mod runtime { use std::rc::Rc; use std::sync::Arc; use std::time::Instant; + use tracing::{info_span, Instrument}; fn get_error_class_name(e: &AnyError) -> &'static str { deno_runtime::errors::get_error_class_name(e).unwrap_or("Error") @@ -861,7 +885,6 @@ mod runtime { let create_web_worker_cb = Arc::new(|_| { todo!("Web workers are not supported in the example"); }); - let options = WorkerOptions { bootstrap: BootstrapOptions { @@ -912,8 +935,14 @@ mod runtime { ) -> Result<(), InterpreterError> { let wait_for_inspector = false; // step 10 load the module into our v8 isolate - worker.execute_main_module(&main_module).await?; - worker.run_event_loop(wait_for_inspector).await?; + worker + .execute_main_module(&main_module) + .instrument(info_span!("execute main module")) + .await?; + worker + .run_event_loop(wait_for_inspector) + .instrument(info_span!("run v8 event loop")) + .await?; { let scope = &mut worker.js_runtime.handle_scope(); @@ -935,6 +964,8 @@ mod runtime { let this = v8::undefined(scope).into(); let start = Instant::now(); + let span = info_span!("dispatch v8 call"); + let timing_guard = span.enter(); match input { None => { function.call(scope, this, &[]); @@ -973,10 +1004,13 @@ mod runtime { function.call(scope, this, &[arg2]); } } - eprintln!("\tcall dispatched {:?}", Instant::now() - start); + drop(timing_guard) } - worker.run_event_loop(wait_for_inspector).await?; - eprintln!("finished waiting on runtime"); + + worker + .run_event_loop(wait_for_inspector) + .instrument(info_span!("run v8 event loop")) + .await?; Ok(()) } diff --git a/src/reporting.rs b/src/reporting.rs index c67b7ac..1862809 100644 --- a/src/reporting.rs +++ b/src/reporting.rs @@ -1,4 +1,5 @@ use deno_core::error::AnyError; +use elm_project_utils::RedoScriptError; use elmi; use pretty::{self, cyan, vcat, Doc}; use rusty_v8; @@ -6,7 +7,6 @@ use serde_json; use std::cmp::max; use std::io; use std::path::PathBuf; -use elm_project_utils::RedoScriptError; #[derive(Debug)] pub enum Problem { @@ -69,7 +69,6 @@ impl From for Problem { } } - #[derive(Debug)] pub enum TypeError { CantEvalRecord, @@ -91,7 +90,7 @@ pub enum CompilerError { CantParseModule(String), // first line EmptyModule, MissingModuleTypeInformation(String), - BadImport(String), + BadImport(String, String), FailedBuildingFixture, ReadInputFailed(io::Error, PathBuf), WriteOutputFailed(io::Error, PathBuf), @@ -148,9 +147,12 @@ impl CompilerError { CantParseModule(_first_line_prefix) => Doc::text("todo could not parse module"), EmptyModule => Doc::text("I did not expect the module file to be empty"), MissingModuleTypeInformation(_) => Doc::text("todo missing module type information"), - BadImport(_) => { + BadImport(module, symbol) => { // TODO suggest alternatives using edit distance - Doc::text("The `Html` module does not expose `view5`") + Doc::text(format!( + "The `{}` module does not expose `{}`", + module, symbol + )) // TODO // Doc::text("These names seem close though") //Doc::group( @@ -161,7 +163,7 @@ impl CompilerError { ReadInputFailed(_io_err, _path) => { title = "IO ERROR"; Doc::text("TODO read file failed") - }, + } WriteOutputFailed(io_err, path) => { Doc::text(format!("TODO write file failed {:?} {:?}", io_err, path)) } diff --git a/src/timings.rs b/src/timings.rs new file mode 100644 index 0000000..4f79e12 --- /dev/null +++ b/src/timings.rs @@ -0,0 +1,140 @@ +//! This module provides a crude system for timing how long various steps of the program take to +//! execute using the tracing framework. I seek absolution for suboptimal code. For example I want +//! to throw a span around all clones and see exactly how long I spend copying data. If I see that +//! I only spend a few milliseconds overall then that could be a price worth paying for development +//! velocity. +//! +//! This is quite a different use case then flame graphs. +use rustc_hash::FxHashMap; +use std::collections::hash_map::Entry; +use std::collections::HashMap; +use std::sync::atomic::{AtomicUsize, Ordering}; +use std::sync::{Arc, RwLock}; +use std::thread::{self, ThreadId}; +use std::time::{Duration, Instant}; +use tracing::info_span; +use tracing::span::{Attributes, Record}; +use tracing::{Event, Id, Metadata, Subscriber}; + +// +// Each step will be described with a less than 100 char string. Steps will overlap. +// +// I am not tracking the relationship between +// the spans. I assume that in each thread that if enter is called then exit will be called before +// enter is called again. +pub(crate) struct Timings { + ids: AtomicUsize, + started: RwLock>, + // This setup of having separate locks creates a risk of deadlocks when generating a report. + // What if the reading thread takes a lock + summary: Arc>>, + span_names: Arc>>, +} + +pub(crate) struct ReportHandle { + summary: Arc>>, + span_names: Arc>>, +} + +impl Timings { + pub fn new() -> (Timings, ReportHandle) { + let summary = Arc::new(RwLock::new(FxHashMap::default())); + let span_names = Arc::new(RwLock::new(FxHashMap::default())); + + let report_handle = ReportHandle { + summary: Arc::clone(&summary), + span_names: Arc::clone(&span_names), + }; + + let subscriber = Timings { + ids: AtomicUsize::new(1), + started: RwLock::new(FxHashMap::default()), + summary, + span_names, + }; + + (subscriber, report_handle) + } +} + +impl ReportHandle { + pub fn dump(&self) -> Option> { + // Now it might take a long time (relatively speaking) to copy many megabytes of report + // data. I went with this design because my target use case is for batch programs that + // print out a report at the end of processing. Also my target use case won't have + // megabytes of timing information. It should only have a few kilobytes. + let summary = self.summary.try_read().ok()?.clone(); + let span_names = self.span_names.try_read().ok()?.clone(); + + let mut accumulator: HashMap = HashMap::new(); + + for (id, duration) in summary.into_iter() { + if let Some(name) = span_names.get(&id) { + let entry = accumulator + .entry(name.clone()) + .or_insert_with(|| Default::default()); + *entry += duration; + } + } + + Some(accumulator.into_iter().collect()) + } +} + +impl tracing::Subscriber for Timings { + fn enabled(&self, metadata: &Metadata<'_>) -> bool { + true + } + + fn new_span(&self, span: &Attributes<'_>) -> Id { + //println!("got new span {:?}", span); + let x = self.ids.fetch_add(1, Ordering::SeqCst); + let id = Id::from_u64(x as u64); + let name = span.metadata().name().to_owned(); + if let Ok(mut guard) = self.span_names.write() { + guard.insert(x as u64, name); + } + + id + } + + fn record(&self, _span: &Id, _values: &Record<'_>) {} + + fn record_follows_from(&self, _span: &Id, _follows: &Id) {} + + fn event(&self, _event: &Event<'_>) {} + + fn enter(&self, span: &Id) { + let mut lock = self.started.write().unwrap(); + match lock.entry((thread::current().id(), span.into_u64())) { + Entry::Vacant(vacant) => { + vacant.insert(Instant::now()); + } + _ => { + // We already started this span in the current thread so this is a logic error. + // This subscriber is only listening to how long each span is executing. + () + } + } + } + + fn exit(&self, span: &Id) { + let stopped = Instant::now(); + // I unwrap the read lock because the mutex should not be poisoned in the simple single + // threaded code of starmelon. + let key = (thread::current().id(), span.into_u64()); + if let Some(started) = self.started.write().unwrap().remove(&key) { + let mut lock = self.summary.write().unwrap(); + match lock.entry(span.into_u64()) { + Entry::Vacant(vacant) => { + vacant.insert(stopped - started); + } + Entry::Occupied(mut occupied) => { + *occupied.get_mut() += stopped - started; + } + } + } else { + println!("failed to find span when exiting"); + } + } +} diff --git a/src/transpile.rs b/src/transpile.rs new file mode 100644 index 0000000..8b13789 --- /dev/null +++ b/src/transpile.rs @@ -0,0 +1 @@ +