feat: use tracing crate to measure cpu time

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

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

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)

src/fixture.rs

@@ -1,5 +1,5 @@
+use crate::{InputType, OutputType};
 use std::fmt::Display;
-use crate::{OutputType, InputType};
 
 pub(crate) fn generate<S: AsRef<str>>(
     source_checksum: u64,

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 tracing::{info_span, span, Instrument};
-use crate::timings::Timings;
 
-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) {
+            let span = info_span!("exec");
-                eprintln!(
+            let timing_guard = span.enter();
-                    "\t\x1b[1;92mFinished\x1b[0m in {:?}",
+            let result = exec(file, debug, function, input, output, verbosity);
-                    Instant::now() - start
+            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 {
+                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!(
-                    "\n\t\x1b[1;92mFinished\x1b[0m in {:?}",
+                "\t\x1b[1;92mFinished\x1b[0m [{}] in {:?}",
+                "unoptimized",
                 Instant::now() - start
             );
         }
+        Arguments::Transpile {
+            file,
+            function,
+            verbosity,
+        } => {
+            println!("todo transpile the code")
         }
     }
 }
@@ -71,14 +89,10 @@ fn exec(
     output: Option<PathBuf>,
     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
+    command.arg("make").arg("--output").arg("/dev/null");
-        .arg("make")
-        .arg("--output")
-        .arg("/dev/null");
     //.stdin(Stdio::null());
     //.stdout(Stdio::null());
     // I am using the default inherit stderr behavior here.
@@ -89,11 +103,13 @@ fn exec(
     }
     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 {
@@ -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!(
+    drop(timing_guard);
-        "[{:?}] created generator Elm program",
-        Instant::now() - start
-    );
-    
 
     // 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 {
+    drop(timing_guard);
-        eprintln!(
-            "compiled {:?} in {:?}",
-            intermediate_file,
-            Instant::now() - start,
-        );
-    }
 
     // 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)})")
@@ -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));
@@ -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()
+        .unwrap();
-        .block_on(async move { runtime::xyz(worker, main_module, input).await })?;
+    drop(timing_guard);
-    eprintln!("eval javascript in {:?}", Instant::now() - start);
+
+    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,13 +475,12 @@ 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)) => {
+        Some(Ok(buffer)) => match output {
-            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))?;
@@ -472,8 +488,7 @@ fn exec(
                 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<HashMap<String, elmi::Interfa
                 Some(ext) if ext == "elmi" => {
                     // 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<HashMap<String, elmi::Interfa
                             .split('-')
                             .collect::<Vec<&str>>()
                             .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)]
@@ -716,13 +741,11 @@ fn setup_generator_project(verbosity: u64, elm_project_dir: PathBuf) -> Result<P
 
     let elm_json_path = elm_project_dir.join("elm.json");
 
-    let mut constraint = ChecksumConstraint::new(
+    let mut constraint =
-        &elm_json_path,
+        ChecksumConstraint::new(&elm_json_path, our_temp_dir.join("elm-json-checksum"))?;
-        our_temp_dir.join("elm-json-checksum"),
-    )?;
 
     if !constraint.dirty()? {
-        return Ok(our_temp_dir)
+        return Ok(our_temp_dir);
     }
 
     let mut data = fs::read(&elm_json_path)
@@ -791,7 +814,8 @@ fn elm_install<P: AsRef<Path>, S: AsRef<str>>(
     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<P: AsRef<Path>, S: AsRef<str>>(
     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")
@@ -862,7 +886,6 @@ mod runtime {
             todo!("Web workers are not supported in the example");
         });
 
-
         let options = WorkerOptions {
             bootstrap: BootstrapOptions {
                 args: vec![],
@@ -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
-        worker.run_event_loop(wait_for_inspector).await?;
+            .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(())
     }

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<elm_project_utils::RedoScriptError> 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))
             }

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<FxHashMap<(ThreadId, u64), Instant>>,
+    // 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<RwLock<FxHashMap<u64, Duration>>>,
+    span_names: Arc<RwLock<FxHashMap<u64, String>>>,
+}
+
+pub(crate) struct ReportHandle {
+    summary: Arc<RwLock<FxHashMap<u64, Duration>>>,
+    span_names: Arc<RwLock<FxHashMap<u64, String>>>,
+}
+
+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<Vec<(String, Duration)>> {
+        // 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<String, Duration> = 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");
+        }
+    }
+}

src/transpile.rs

@@ -0,0 +1 @@
+