Skip to content

Fix average write duration and extend server stats #52

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 2 commits into from
Dec 19, 2016
Merged

Fix average write duration and extend server stats #52

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
e0dffe5
Fix avg write duration and extend server stats
Dec 18, 2016
6b41b3c
Fixed wrong comment for cache_write_duration
Dec 19, 2016
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
38 changes: 23 additions & 15 deletions src/compiler/compiler.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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.
Expand All @@ -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"),
}
Expand All @@ -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,
Expand Down Expand Up @@ -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);
Expand All @@ -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(),
Expand All @@ -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);
Expand Down Expand Up @@ -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);
Expand Down Expand Up @@ -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::*;

Expand Down Expand Up @@ -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();
}
Expand All @@ -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());
Expand Down Expand Up @@ -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();
}
Expand All @@ -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());
Expand Down Expand Up @@ -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();
}
Expand All @@ -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();
}
Expand Down
77 changes: 56 additions & 21 deletions src/server.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand All @@ -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,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there a reason you're changing this to u64? You're just doing a conversion in the set_duration_stat macro below anyway...

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I changed it to u64 because all other counters are u64 and it looked odd. That's it.
I thought you just use u32 because of the division for the time calculation.
Shall I revert that one?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I can't say I have strong feelings either way. I was mostly just curious to make sure I wasn't missing something important about the patch.

/// 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),
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I avoided doing this because I was too lazy to spell all this out, and Duration didn't have a Default implementation. That'll be fixed in Rust 1.15, but for now this is a reasonable thing to do.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did not think a second about Default for Duration until rustc told me some facts and I wrote this bloaty method.

compile_fails: u64::default(),
}
}
}

impl ServerStats {
fn to_cache_statistics(&self) -> Vec<CacheStatistic> {
macro_rules! set_stat {
Expand All @@ -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));
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I really wish Duration had an as_fractional_secs method or something like that. I filed an issue on that. Also: oops on the conversion bug. I wish there was at least a constant in the stdlib we could use for it!

} else {
stat.set_str("0.000 s".to_owned());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if there'd be any value in adding a Duration case to the CacheStatistic enum? We don't currently do anything interesting with it, although I'd like to add a way to have --show-stats output a JSON representation of the stats for consumption by other programs. (Granted you're just duplicating what I previously implemented here...)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The Duration in CacheStatistic came to my mind when thinking about #12 in order to have a two column display with value and unit (like in the ccache output):


max cache size            5.0 GB
some duration             433 ms
other duration          0.324 s

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah. We can fix that later, it would make fixing that nicer certainly.

}
$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");
Expand All @@ -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
}
}
Expand Down Expand Up @@ -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,
Expand All @@ -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 => {
Expand Down Expand Up @@ -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;
}
}
}
Expand Down