Fix average write duration and extend server stats (#52)

* Fix avg write duration and extend server stats

The average duration that is taken by a miss or hit is interesting
when testing different cache types. This patch adds the average time
taken by a cache miss and hit to the server stats. This measurements
can be entirely done in the server and do not need any changes to the
cache implementations.
Furthermore the calculation of the average duration for cache writes is
fixed (wrong factor used, that produced micros instead of millis).

Author: flxo

src/compiler/compiler.rs

@@ -48,7 +48,10 @@ use std::path::Path;
 use std::process::{self,Stdio};
 use std::str;
 use std::thread;
-use std::time::Duration;
+use std::time::{
+    Duration,
+    Instant,
+};
 use tempdir::TempDir;
 
 /// Supported compilers.
@@ -171,12 +174,12 @@ pub enum CompileResult {
     /// An error made the compilation not possible.
     Error,
     /// Result was found in cache.
-    CacheHit,
+    CacheHit(Duration),
     /// Result was not found in cache.
     ///
     /// The `CacheWriteFuture` will resolve when the result is finished
     /// being stored in the cache.
-    CacheMiss(MissType, CacheWriteFuture),
+    CacheMiss(MissType, Duration, CacheWriteFuture),
     /// Not in cache, but the compilation result was determined to be not cacheable.
     NotCacheable,
     /// Not in cache, but compilation failed.
@@ -189,8 +192,8 @@ impl fmt::Debug for CompileResult {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
         match self {
             &CompileResult::Error => write!(f, "CompileResult::Error"),
-            &CompileResult::CacheHit => write!(f, "CompileResult::CacheHit"),
-            &CompileResult::CacheMiss(ref m, _) => write!(f, "CompileResult::CacheMiss({:?}, _)", m),
+            &CompileResult::CacheHit(ref d) => write!(f, "CompileResult::CacheHit({:?})", d),
+            &CompileResult::CacheMiss(ref m, ref d, _) => write!(f, "CompileResult::CacheMiss({:?}, {:?}, _)", d, m),
             &CompileResult::NotCacheable => write!(f, "CompileResult::NotCacheable"),
             &CompileResult::CompileFailed => write!(f, "CompileResult::CompileFailed"),
         }
@@ -202,8 +205,8 @@ impl PartialEq<CompileResult> for CompileResult {
     fn eq(&self, other: &CompileResult) -> bool {
         match (self, other) {
             (&CompileResult::Error, &CompileResult::Error) => true,
-            (&CompileResult::CacheHit, &CompileResult::CacheHit) => true,
-            (&CompileResult::CacheMiss(ref m, _), &CompileResult::CacheMiss(ref n, _)) => m == n,
+            (&CompileResult::CacheHit(_), &CompileResult::CacheHit(_)) => true,
+            (&CompileResult::CacheMiss(ref m, _, _), &CompileResult::CacheMiss(ref n, _, _)) => m == n,
             (&CompileResult::NotCacheable, &CompileResult::NotCacheable) => true,
             (&CompileResult::CompileFailed, &CompileResult::CompileFailed) => true,
             _ => false,
@@ -294,11 +297,13 @@ impl Compiler {
             .map(|(key, path)| (key, pwd.join(path)))
             .collect::<HashMap<_, _>>();
         // If `ForceRecache` is enabled, we won't check the cache.
+        let start = Instant::now();
         let cache_status = if cache_control == CacheControl::ForceRecache {
             Cache::Recache
         } else {
             storage.get(&key)
         };
+        let duration = start.elapsed();
         match cache_status {
             Cache::Hit(mut entry) => {
                 debug!("[{}]: Cache hit!", out_file);
@@ -310,7 +315,7 @@ impl Compiler {
                 let mut stderr = io::Cursor::new(vec!());
                 entry.get_object("stdout", &mut stdout).unwrap_or(());
                 entry.get_object("stderr", &mut stderr).unwrap_or(());
-                Ok((CompileResult::CacheHit,
+                Ok((CompileResult::CacheHit(duration),
                     process::Output {
                         status: exit_status(0),
                         stdout: stdout.into_inner(),
@@ -330,7 +335,9 @@ impl Compiler {
                     Cache::Hit(_) => MissType::Normal,
                 };
                 let process::Output { stdout, .. } = preprocessor_result;
+                let start = Instant::now();
                 let (cacheable, compiler_result) = try!(self.kind.compile(creator, self, stdout, parsed_args, cwd));
+                let duration = start.elapsed();
                 if compiler_result.status.success() {
                     if cacheable == Cacheable::Yes {
                         debug!("[{}]: Compiled, storing in cache", out_file);
@@ -363,7 +370,7 @@ impl Compiler {
                                     duration: duration,
                                 })
                             }).boxed();
-                        Ok((CompileResult::CacheMiss(miss_type, future), compiler_result))
+                        Ok((CompileResult::CacheMiss(miss_type, duration, future), compiler_result))
                     } else {
                         // Not cacheable
                         debug!("[{}]: Compiled but not cacheable", out_file);
@@ -507,6 +514,7 @@ mod test {
     use mock_command::*;
     use std::fs::{self,File};
     use std::io::Write;
+    use std::time::Duration;
     use std::usize;
     use test::utils::*;
 
@@ -614,7 +622,7 @@ mod test {
         // Ensure that the object file was created.
         assert_eq!(true, fs::metadata(&obj).and_then(|m| Ok(m.len() > 0)).unwrap());
         match cached {
-            CompileResult::CacheMiss(MissType::Normal, f) => {
+            CompileResult::CacheMiss(MissType::Normal, _, f) => {
                 // wait on cache write future so we don't race with it!
                 f.wait().unwrap().unwrap();
             }
@@ -631,7 +639,7 @@ mod test {
         let (cached, res) = c.get_cached_or_compile(creator.clone(), &storage, &arguments, &parsed_args, cwd, CacheControl::Default).unwrap();
         // Ensure that the object file was created.
         assert_eq!(true, fs::metadata(&obj).and_then(|m| Ok(m.len() > 0)).unwrap());
-        assert_eq!(CompileResult::CacheHit, cached);
+        assert_eq!(CompileResult::CacheHit(Duration::new(0, 0)), cached);
         assert_eq!(exit_status(0), res.status);
         assert_eq!(COMPILER_STDOUT, res.stdout.as_slice());
         assert_eq!(COMPILER_STDERR, res.stderr.as_slice());
@@ -676,7 +684,7 @@ mod test {
         // Ensure that the object file was created.
         assert_eq!(true, fs::metadata(&obj).and_then(|m| Ok(m.len() > 0)).unwrap());
         match cached {
-            CompileResult::CacheMiss(MissType::Normal, f) => {
+            CompileResult::CacheMiss(MissType::Normal, _, f) => {
                 // wait on cache write future so we don't race with it!
                 f.wait().unwrap().unwrap();
             }
@@ -694,7 +702,7 @@ mod test {
         let (cached, res) = c.get_cached_or_compile(creator.clone(), &storage, &arguments, &parsed_args, cwd, CacheControl::Default).unwrap();
         // Ensure that the object file was created.
         assert_eq!(true, fs::metadata(&obj).and_then(|m| Ok(m.len() > 0)).unwrap());
-        assert_eq!(CompileResult::CacheHit, cached);
+        assert_eq!(CompileResult::CacheHit(Duration::new(0, 0)), cached);
         assert_eq!(exit_status(0), res.status);
         assert_eq!(COMPILER_STDOUT, res.stdout.as_slice());
         assert_eq!(COMPILER_STDERR, res.stderr.as_slice());
@@ -743,7 +751,7 @@ mod test {
         // Ensure that the object file was created.
         assert_eq!(true, fs::metadata(&obj).and_then(|m| Ok(m.len() > 0)).unwrap());
         match cached {
-            CompileResult::CacheMiss(MissType::Normal, f) => {
+            CompileResult::CacheMiss(MissType::Normal, _, f) => {
                 // wait on cache write future so we don't race with it!
                 f.wait().unwrap().unwrap();
             }
@@ -758,7 +766,7 @@ mod test {
         // Ensure that the object file was created.
         assert_eq!(true, fs::metadata(&obj).and_then(|m| Ok(m.len() > 0)).unwrap());
         match cached {
-            CompileResult::CacheMiss(MissType::ForcedRecache, f) => {
+            CompileResult::CacheMiss(MissType::ForcedRecache, _, f) => {
                 // wait on cache write future so we don't race with it!
                 f.wait().unwrap().unwrap();
             }

src/server.rs

@@ -119,7 +119,6 @@ pub struct SccacheServer<C: CommandCreatorSync + 'static> {
 }
 
 /// Statistics about the cache.
-#[derive(Default)]
 struct ServerStats {
     /// The count of client compile requests.
     pub compile_requests: u64,
@@ -146,15 +145,41 @@ struct ServerStats {
     /// The count of errors writing to cache.
     pub cache_write_errors: u64,
     /// The number of successful cache writes.
-    pub cache_writes: u32,
-    /// The total seconds spent writing cache entries.
-    pub cache_write_duration_s: u64,
-    /// The total nanoseconds spent writing cache entries.
-    pub cache_write_duration_ns: u32,
+    pub cache_writes: u64,
+    /// The total time spent writing cache entries.
+    pub cache_write_duration: Duration,
+    /// The total time spent reading cache hits.
+    pub cache_read_hit_duration: Duration,
+    /// The total time spent reading cache misses.
+    pub cache_read_miss_duration: Duration,
     /// The count of compilation failures.
     pub compile_fails: u64,
 }
 
+impl Default for ServerStats {
+    fn default() -> ServerStats {
+        ServerStats {
+            compile_requests: u64::default(),
+            requests_unsupported_compiler: u64::default(),
+            requests_not_compile: u64::default(),
+            requests_not_cacheable: u64::default(),
+            requests_executed: u64::default(),
+            cache_errors: u64::default(),
+            cache_hits: u64::default(),
+            cache_misses: u64::default(),
+            non_cacheable_compilations: u64::default(),
+            forced_recaches: u64::default(),
+            cache_read_errors: u64::default(),
+            cache_write_errors: u64::default(),
+            cache_writes: u64::default(),
+            cache_write_duration: Duration::new(0, 0),
+            cache_read_hit_duration: Duration::new(0, 0),
+            cache_read_miss_duration: Duration::new(0, 0),
+            compile_fails: u64::default(),
+        }
+    }
+}
+
 impl ServerStats {
     fn to_cache_statistics(&self) -> Vec<CacheStatistic> {
         macro_rules! set_stat {
@@ -166,6 +191,20 @@ impl ServerStats {
             }};
         }
 
+        macro_rules! set_duration_stat {
+            ($vec:ident, $dur:expr, $num:expr, $name:expr) => {{
+                let mut stat = CacheStatistic::new();
+                stat.set_name(String::from($name));
+                if $num > 0 {
+                    let duration = $dur / $num as u32;
+                    stat.set_str(format!("{}.{:03} s", duration.as_secs(), duration.subsec_nanos() / 1000_000));
+                } else {
+                    stat.set_str("0.000 s".to_owned());
+                }
+                $vec.push(stat);
+            }};
+        }
+
         let mut stats_vec = vec!();
         set_stat!(stats_vec, self.compile_requests, "Compile requests");
         set_stat!(stats_vec, self.requests_executed, "Compile requests executed");
@@ -180,16 +219,9 @@ impl ServerStats {
         set_stat!(stats_vec, self.requests_not_cacheable, "Non-cacheable calls");
         set_stat!(stats_vec, self.requests_not_compile, "Non-compilation calls");
         set_stat!(stats_vec, self.requests_unsupported_compiler, "Unsupported compiler calls");
-        // Set this as a string so we can view subsecond values.
-        let mut stat = CacheStatistic::new();
-        stat.set_name(String::from("Average cache write"));
-        if self.cache_writes > 0 {
-            let avg_write_duration = Duration::new(self.cache_write_duration_s, self.cache_write_duration_ns) / self.cache_writes;
-            stat.set_str(format!("{}.{:03}s", avg_write_duration.as_secs(), avg_write_duration.subsec_nanos() / 1000));
-        } else {
-            stat.set_str(String::from("0s"));
-        }
-        stats_vec.push(stat);
+        set_duration_stat!(stats_vec, self.cache_write_duration, self.cache_writes, "Average cache write");
+        set_duration_stat!(stats_vec, self.cache_read_miss_duration, self.cache_misses, "Average cache read miss");
+        set_duration_stat!(stats_vec, self.cache_read_hit_duration, self.cache_hits, "Average cache read hit");
         stats_vec
     }
 }
@@ -450,8 +482,11 @@ impl<C : CommandCreatorSync + 'static> SccacheServer<C> {
             Some((compiled, out)) => {
                 match compiled {
                     CompileResult::Error => self.stats.cache_errors += 1,
-                    CompileResult::CacheHit => self.stats.cache_hits += 1,
-                    CompileResult::CacheMiss(miss_type, future) => {
+                    CompileResult::CacheHit(duration) => {
+                        self.stats.cache_hits += 1;
+                        self.stats.cache_read_hit_duration += duration;
+                    },
+                    CompileResult::CacheMiss(miss_type, duration, future) => {
                         match miss_type {
                             MissType::Normal => self.stats.cache_misses += 1,
                             MissType::CacheReadError => self.stats.cache_read_errors += 1,
@@ -460,6 +495,7 @@ impl<C : CommandCreatorSync + 'static> SccacheServer<C> {
                                 self.stats.forced_recaches += 1;
                             }
                         }
+                        self.stats.cache_read_miss_duration += duration;
                         self.await_cache_write(&mut event_loop, future)
                     }
                     CompileResult::NotCacheable => {
@@ -727,10 +763,9 @@ impl<C : CommandCreatorSync + 'static> Handler for SccacheServer<C> {
                     }
                     //TODO: save cache stats!
                     Ok(info) => {
-                        debug!("[{}]: Cache write finished in {}.{:03}s", info.object_file, info.duration.as_secs(), info.duration.subsec_nanos() / 1000);
+                        debug!("[{}]: Cache write finished in {}.{:03}s", info.object_file, info.duration.as_secs(), info.duration.subsec_nanos() / 1000_000);
                         self.stats.cache_writes += 1;
-                        self.stats.cache_write_duration_s += info.duration.as_secs();
-                        self.stats.cache_write_duration_ns += info.duration.subsec_nanos();
+                        self.stats.cache_write_duration += info.duration;
                     }
                 }
             }