Add rudimentary timing of parsing and formatting phases

Cargo.toml

@@ -44,6 +44,7 @@ env_logger = "0.4"
 getopts = "0.2"
 derive-new = "0.5"
 cargo_metadata = "0.4"
+time = "0.1"
 
 [target.'cfg(unix)'.dependencies]
 libc = "0.2.11"

src/lib.rs

@@ -23,6 +23,7 @@ extern crate serde_derive;
 extern crate serde_json;
 extern crate syntax;
 extern crate term;
+extern crate time;
 extern crate unicode_segmentation;
 
 use std::collections::HashMap;
@@ -616,6 +617,8 @@ pub fn format_input<T: Write>(
         }
     };
 
+    summary.mark_parse_time();
+
     if parse_session.span_diagnostic.has_errors() {
         summary.add_parsing_error();
     }
@@ -630,7 +633,7 @@ pub fn format_input<T: Write>(
 
     let mut report = FormatReport::new();
 
-    match format_ast(
+    let format_result = format_ast(
         &krate,
         &mut parse_session,
         &main_file,
@@ -647,7 +650,19 @@ pub fn format_input<T: Write>(
             }
             Ok(false)
         },
-    ) {
+    );
+
+    summary.mark_format_time();
+
+    if config.verbose() {
+        println!(
+            "Spent {} in the parsing phase, and {} in the formatting phase",
+            summary.get_parse_time().unwrap(),
+            summary.get_format_time().unwrap(),
+        );
+    }
+
+    match format_result {
         Ok((file_map, has_diff)) => {
             if report.has_warnings() {
                 summary.add_formatting_error();

src/summary.rs

@@ -1,3 +1,6 @@
+use time::{precise_time_ns, Duration};
+use std::default::Default;
+
 #[must_use]
 #[derive(Debug, Default, Clone, Copy)]
 pub struct Summary {
@@ -12,9 +15,42 @@ pub struct Summary {
 
     // Formatted code differs from existing code (write-mode diff only).
     pub has_diff: bool,
+
+    // Keeps track of time spent in parsing and formatting steps.
+    timer: Timer,
 }
 
 impl Summary {
+    pub fn mark_parse_time(&mut self) {
+        self.timer = self.timer.done_parsing();
+    }
+
+    pub fn mark_format_time(&mut self) {
+        self.timer = self.timer.done_formatting();
+    }
+
+    /// Returns the time it took to parse the source files in nanoseconds.
+    pub fn get_parse_time(&self) -> Option<Duration> {
+        match self.timer {
+            Timer::DoneParsing(init, parse_time) | Timer::DoneFormatting(init, parse_time, _) => {
+                // This should never underflow since `precise_time_ns()` guarantees monotonicity.
+                Some(Duration::nanoseconds((parse_time - init) as i64))
+            }
+            Timer::Initialized(..) => None,
+        }
+    }
+
+    /// Returns the time it took to go from the parsed AST to the formatted output. Parsing time is
+    /// not included.
+    pub fn get_format_time(&self) -> Option<Duration> {
+        match self.timer {
+            Timer::DoneFormatting(_init, parse_time, format_time) => {
+                Some(Duration::nanoseconds((format_time - parse_time) as i64))
+            }
+            Timer::DoneParsing(..) | Timer::Initialized(..) => None,
+        }
+    }
+
     pub fn has_operational_errors(&self) -> bool {
         self.has_operational_errors
     }
@@ -65,3 +101,34 @@ impl Summary {
         println!("{}", exit_codes);
     }
 }
+
+#[derive(Clone, Copy, Debug)]
+enum Timer {
+    Initialized(u64),
+    DoneParsing(u64, u64),
+    DoneFormatting(u64, u64, u64),
+}
+
+impl Default for Timer {
+    fn default() -> Self {
+        Timer::Initialized(precise_time_ns())
+    }
+}
+
+impl Timer {
+    fn done_parsing(self) -> Self {
+        match self {
+            Timer::Initialized(init_time) => Timer::DoneParsing(init_time, precise_time_ns()),
+            _ => panic!("Timer can only transition to DoneParsing from Initialized state"),
+        }
+    }
+
+    fn done_formatting(self) -> Self {
+        match self {
+            Timer::DoneParsing(init_time, parse_time) => {
+                Timer::DoneFormatting(init_time, parse_time, precise_time_ns())
+            }
+            _ => panic!("Timer can only transition to DoneFormatting from DoneParsing state"),
+        }
+    }
+}