diff --git a/src/compiler/compiler.rs b/src/compiler/compiler.rs index 2e5126eb..dbc079ab 100644 --- a/src/compiler/compiler.rs +++ b/src/compiler/compiler.rs @@ -262,10 +262,13 @@ where // Set a maximum time limit for the cache to respond before we forge // ahead ourselves with a compilation. let timeout = Duration::new(60, 0); - let cache_status = tokio::time::timeout(timeout, cache_status); + let cache_status = async { + let res = tokio::time::timeout(timeout, cache_status).await; + let duration = start.elapsed(); + (res, duration) + }; // Check the result of the cache lookup. - let duration = start.elapsed(); let outputs = compilation .outputs() .map(|output| FileObjectSource { @@ -275,7 +278,7 @@ where .collect::>(); let lookup = match cache_status.await { - Ok(Ok(Cache::Hit(mut entry))) => { + (Ok(Ok(Cache::Hit(mut entry))), duration) => { debug!( "[{}]: Cache hit in {}", out_pretty, @@ -301,7 +304,7 @@ where } } } - Ok(Ok(Cache::Miss)) => { + (Ok(Ok(Cache::Miss)), duration) => { debug!( "[{}]: Cache miss in {}", out_pretty, @@ -309,7 +312,7 @@ where ); Ok(CacheLookupResult::Miss(MissType::Normal)) } - Ok(Ok(Cache::Recache)) => { + (Ok(Ok(Cache::Recache)), duration) => { debug!( "[{}]: Cache recache in {}", out_pretty, @@ -317,11 +320,11 @@ where ); Ok(CacheLookupResult::Miss(MissType::ForcedRecache)) } - Ok(Err(err)) => { - error!("[{}]: Cache read error: {:?}", out_pretty, err); + (Ok(Err(err)), duration) => { + error!("[{}]: Cache read error: {:?} in {}", out_pretty, err, fmt_duration_as_secs(&duration)); Ok(CacheLookupResult::Miss(MissType::CacheReadError)) } - Err(_elapsed) => { + (Err(_), duration) => { debug!( "[{}]: Cache timed out {}", out_pretty, @@ -1262,12 +1265,13 @@ where #[cfg(test)] mod test { use super::*; + use crate::cache::CacheRead; use crate::cache::disk::DiskCache; use crate::mock_command::*; use crate::test::mock_storage::MockStorage; use crate::test::utils::*; use fs::File; - use std::io::Write; + use std::io::{Write, Cursor}; use std::sync::Arc; use std::time::Duration; use std::u64; @@ -1803,7 +1807,7 @@ LLVM version: 6.0", let f = TestFixture::new(); let runtime = Runtime::new().unwrap(); let pool = runtime.handle().clone(); - let storage = MockStorage::new(); + let storage = MockStorage::new(None); let storage: Arc = Arc::new(storage); // Pretend to be GCC. next_command(&creator, Ok(MockChild::new(exit_status(0), "gcc", ""))); @@ -1874,6 +1878,76 @@ LLVM version: 6.0", assert_eq!(COMPILER_STDERR, res.stderr.as_slice()); } + #[test] + /// Test that cache read timing is recorded. + fn test_compiler_get_cached_or_compile_cache_get_timing() { + drop(env_logger::try_init()); + let creator = new_creator(); + let f = TestFixture::new(); + let runtime = Runtime::new().unwrap(); + let pool = runtime.handle().clone(); + // Make our storage wait 2ms for each get/put operation. + let storage_delay = Duration::from_millis(2); + let storage = MockStorage::new(Some(storage_delay)); + let storage: Arc = Arc::new(storage); + // Pretend to be GCC. + next_command(&creator, Ok(MockChild::new(exit_status(0), "gcc", ""))); + let c = get_compiler_info( + creator.clone(), + &f.bins[0], + f.tempdir.path(), + &[], + &[], + &pool, + None, + ) + .wait() + .unwrap() + .0; + // The preprocessor invocation. + next_command( + &creator, + Ok(MockChild::new(exit_status(0), "preprocessor output", "")), + ); + // The compiler invocation. + const COMPILER_STDOUT: &[u8] = b"compiler stdout"; + const COMPILER_STDERR: &[u8] = b"compiler stderr"; + let obj_file: &[u8] = &[1, 2, 3, 4]; + // A cache entry to hand out + let mut cachewrite = CacheWrite::new(); + cachewrite.put_stdout(COMPILER_STDOUT).expect("Failed to store stdout"); + cachewrite.put_stderr(COMPILER_STDERR).expect("Failed to store stderr"); + cachewrite.put_object("obj", &mut Cursor::new(obj_file), None).expect("Failed to store cache object"); + let entry = cachewrite.finish().expect("Failed to finish cache entry"); + let entry = CacheRead::from(Cursor::new(entry)).expect("Failed to re-read cache entry"); + + let cwd = f.tempdir.path(); + let arguments = ovec!["-c", "foo.c", "-o", "foo.o"]; + let hasher = match c.parse_arguments(&arguments, ".".as_ref(), &[]) { + CompilerArguments::Ok(h) => h, + o => panic!("Bad result from parse_arguments: {:?}", o), + }; + storage.next_get(Ok(Cache::Hit(entry))); + let (cached, _res) = runtime + .block_on(hasher.get_cached_or_compile( + None, + creator, + storage, + arguments.clone(), + cwd.to_path_buf(), + vec![], + CacheControl::Default, + pool, + )) + .unwrap(); + match cached { + CompileResult::CacheHit(duration) => { + assert!(duration >= storage_delay); + } + _ => panic!("Unexpected compile result: {:?}", cached), + } + } + #[test] fn test_compiler_get_cached_or_compile_force_recache() { drop(env_logger::try_init()); diff --git a/src/test/mock_storage.rs b/src/test/mock_storage.rs index ddfaeb54..5cfa391d 100644 --- a/src/test/mock_storage.rs +++ b/src/test/mock_storage.rs @@ -19,20 +19,23 @@ use futures::channel::mpsc; use std::sync::Arc; use std::time::Duration; use tokio::sync::Mutex; +use tokio::time::sleep; /// A mock `Storage` implementation. pub struct MockStorage { rx: Arc>>>, tx: mpsc::UnboundedSender>, + delay: Option, } impl MockStorage { - /// Create a new `MockStorage`. - pub(crate) fn new() -> MockStorage { + /// Create a new `MockStorage`. if `delay` is `Some`, wait for that amount of time before returning from operations. + pub(crate) fn new(delay: Option) -> MockStorage { let (tx, rx) = mpsc::unbounded(); Self { tx, rx: Arc::new(Mutex::new(rx)), + delay, } } @@ -45,12 +48,20 @@ impl MockStorage { #[async_trait] impl Storage for MockStorage { async fn get(&self, _key: &str) -> Result { + if let Some(delay) = self.delay { + sleep(delay).await; + } let next = self.rx.lock().await.try_next().unwrap(); next.expect("MockStorage get called but no get results available") } async fn put(&self, _key: &str, _entry: CacheWrite) -> Result { - Ok(Duration::from_secs(0)) + Ok(if let Some(delay) = self.delay { + sleep(delay).await; + delay + } else { + Duration::from_secs(0) + }) } fn location(&self) -> String { "Mock Storage".to_string()