From f9fd557a272c6d5e5e34c19b1ef377ea6e39a6a8 Mon Sep 17 00:00:00 2001
From: Brandon Thomas <echelon@gmail.com>
Date: Mon, 10 Oct 2016 04:02:38 -0400
Subject: [PATCH] log timing

---
 config.toml                         | 5 +++--
 src/config.rs                       | 4 ++++
 src/handlers/audio_synth_handler.rs | 9 ++++++---
 src/logger.rs                       | 1 +
 4 files changed, 14 insertions(+), 5 deletions(-)

diff --git a/config.toml b/config.toml
index 09a7354d6c..5081d32410 100644
--- a/config.toml
+++ b/config.toml
@@ -9,16 +9,17 @@
   abbreviation_file = "./dictionary/abbreviations.dict"
 
   # Logging verbosity
+  log_handler = false
   log_parsing = false
   log_synthesis = false
-  log_handler = false
+  log_timing  = true
 
 [x16] # Local Development
   use_caching_headers = false
   sound_path = "/home/bt/Dropbox/jungle.horse/sounds"
 
   # Logging verbosity
+  log_handler = false
   log_parsing = true
   log_synthesis = false
-  log_handler = false
 
diff --git a/src/config.rs b/src/config.rs
index 3359bb7ff0..27d59d7afc 100644
--- a/src/config.rs
+++ b/src/config.rs
@@ -28,6 +28,7 @@ pub struct Config {
   pub log_handler: Option<bool>,
   pub log_parsing: Option<bool>,
   pub log_synthesis: Option<bool>,
+  pub log_timing: Option<bool>,
 }
 
 #[derive(Debug)]
@@ -113,6 +114,9 @@ impl Config {
       log_synthesis: self.log_synthesis
           .clone()
           .or(other.log_synthesis.clone()),
+      log_timing: self.log_timing
+          .clone()
+          .or(other.log_timing.clone()),
     }
   }
 }
diff --git a/src/handlers/audio_synth_handler.rs b/src/handlers/audio_synth_handler.rs
index 3b46f82f7f..b8a389349e 100644
--- a/src/handlers/audio_synth_handler.rs
+++ b/src/handlers/audio_synth_handler.rs
@@ -23,6 +23,7 @@ use std::sync::Arc;
 use std::sync::RwLock;
 use super::error_filter::build_error;
 use synthesizer::Synthesizer;
+use time::PreciseTime;
 use urlencoded::UrlEncodedQuery;
 
 const SENTENCE_PARAM : &'static str = "s";
@@ -315,8 +316,12 @@ impl Handler for AudioSynthHandler {
       }
     }
 
+    let start = PreciseTime::now();
     let result = self.create_audio(request);
 
+    info!(target: "timing",
+          "Total parsing and synthesis took: {}", start.to(PreciseTime::now()));
+
     let mime_type = "audio/wav".parse::<Mime>().unwrap();
 
     let mut response = Response::with((mime_type, status::Ok, result));
@@ -357,7 +362,7 @@ impl AudioSynthHandler {
                                        request.word_padding_end);
         match generated {
           Err(e) => {
-            println!("Error synthesizing: {:?}", e);
+            warn!("Error synthesizing: {:?}", e);
             Vec::new() // TODO FIXME
           },
           Ok(wav) => wav,
@@ -391,8 +396,6 @@ impl AudioSynthHandler {
     if request.use_words { use_byte |= 1 << 3; }
     if request.use_ends { use_byte |= 1 << 4; }
 
-    println!("Use byte: {}", use_byte);
-
     hasher.input(&[use_byte]);
 
     hasher.result_str().to_string()
diff --git a/src/logger.rs b/src/logger.rs
index 443f4866f1..d42886e727 100644
--- a/src/logger.rs
+++ b/src/logger.rs
@@ -35,6 +35,7 @@ impl log::Log for SimpleLogger {
       "handler" => self.config.log_handler.unwrap_or(false),
       "parsing" => self.config.log_parsing.unwrap_or(false),
       "synthesis" => self.config.log_synthesis.unwrap_or(false),
+      "timing" => self.config.log_timing.unwrap_or(false),
       _ => metadata.level() <= LogLevel::Info,
     }
   }