Print CPU usage for rayon threads in pass timings

Author: Zoxc

src/Cargo.lock

@@ -28,6 +28,16 @@ syntax = { path = "../libsyntax" }
 syntax_pos = { path = "../libsyntax_pos" }
 lazy_static = "1.0.0"
 
+[target.'cfg(target_arch = "x86")'.dependencies]
+x86 = { git = "https://github.com/gz/rust-x86.git" }
+
+[target.'cfg(target_arch = "x86_64")'.dependencies]
+x86 = { git = "https://github.com/gz/rust-x86.git" }
+
+[target.'cfg(windows)'.dependencies]
+kernel32-sys = "0.2.2"
+winapi = "0.2.8"
+
 # Note that these dependencies are a lie, they're just here to get linkage to
 # work.
 #

src/librustc/Cargo.toml

@@ -78,6 +78,11 @@ extern crate getopts;
 extern crate graphviz;
 #[cfg(windows)]
 extern crate libc;
+#[cfg(windows)]
+extern crate kernel32;
+#[cfg(windows)]
+extern crate winapi;
+extern crate x86;
 extern crate owning_ref;
 extern crate rustc_back;
 #[macro_use] extern crate rustc_data_structures;

src/librustc/lib.rs

@@ -102,6 +102,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> {
     {
         if let Some((i, _)) = self.query().stack.iter().enumerate().rev()
                                  .find(|&(_, &(_, ref q))| q == query) {
+            println!("    cycle_check failed for query {:?}, span: {:?}", query, span);
             Err(CycleError {
                 span,
                 cycle: self.query().stack[i..].iter().cloned().collect(),

src/librustc/ty/maps/plumbing.rs

@@ -130,18 +130,103 @@ pub fn time<T, F>(do_it: bool, what: &str, f: F) -> T where
     if cfg!(debug_assertions) {
         profq_msg(ProfileQueriesMsg::TimeBegin(what.to_string()))
     };
+
+    #[cfg(not(all(windows, parallel_queries, any(target_arch = "x86", target_arch = "x86_64"))))]
+    let rv = time_impl(what, f);
+    #[cfg(all(windows, parallel_queries, any(target_arch = "x86", target_arch = "x86_64")))]
+    let rv = time_threads_impl(what, f);
+
+    TIME_DEPTH.with(|slot| slot.set(old));
+
+    rv
+}
+
+fn time_impl<T, F>(what: &str, f: F) -> T where
+    F: FnOnce() -> T,
+{
     let start = Instant::now();
     let rv = f();
     let dur = start.elapsed();
     if cfg!(debug_assertions) {
         profq_msg(ProfileQueriesMsg::TimeEnd)
     };
+    print_time_passes_entry_internal(what, duration_to_secs_str(dur));
+    rv
+}
 
-    print_time_passes_entry_internal(what, dur);
+#[cfg(all(windows, parallel_queries, any(target_arch = "x86", target_arch = "x86_64")))]
+fn time_threads_impl<T, F>(what: &str, f: F) -> T where
+    F: FnOnce() -> T,
+{
+    use rayon_core::registry;
+    use std::iter;
+    use x86;
+    use winapi;
+    use kernel32;
+
+    let registry = registry::get_current_registry();
+    if let Some(registry) = registry {
+        let freq = unsafe {
+            let mut freq = 0;
+            assert!(kernel32::QueryPerformanceFrequency(&mut freq) == winapi::TRUE);
+            freq as u64 * 1000
+        };
+
+        let threads: Vec<_> = {
+            let threads = registry.handles.lock();
+            let current = unsafe {
+                iter::once(kernel32::GetCurrentThread())
+            };
+            current.chain(threads.iter().map(|t| t.0)).collect()
+        };
+        let mut begin: Vec<u64> = iter::repeat(0).take(threads.len()).collect();
+        let mut end: Vec<u64> = iter::repeat(0).take(threads.len()).collect();
+        for (i, &handle) in threads.iter().enumerate() {
+            unsafe {
+                assert!(kernel32::QueryThreadCycleTime(handle, &mut begin[i]) == winapi::TRUE);
+            }
+        }
+        let time_start = unsafe { x86::shared::time::rdtsc() };
+        let result = f();
+        let time_end = unsafe { x86::shared::time::rdtsc() };
+        for (i, &handle) in threads.iter().enumerate() {
+            unsafe {
+                assert!(kernel32::QueryThreadCycleTime(handle, &mut end[i]) == winapi::TRUE);
+            }
+        }
+        if cfg!(debug_assertions) {
+            profq_msg(ProfileQueriesMsg::TimeEnd)
+        };
+        let time = time_end - time_start;
+        let time_secs = time as f64 / freq as f64;
+
+        let thread_times: Vec<u64> = end.iter().zip(begin.iter()).map(|(e, b)| *e - *b).collect();
+
+        let total_thread_time: u64 = thread_times.iter().cloned().sum();
+        let core_usage = total_thread_time as f64 / time as f64;
+
+        let mut data = format!("{:.3} - cores {:.2}x - cpu {:.2}% - threads (",
+                           time_secs,
+                           core_usage,
+                           core_usage * 100.0 / (thread_times.len() - 1) as f64);
+
+        for (i, thread_time) in thread_times.into_iter().enumerate() {
+            data.push_str(&format!("{:.2}x", thread_time as f64 / time as f64));
+            if i == 0 {
+                data.push_str(" - ");
+            }
+            else if i < begin.len() - 1 {
+                data.push_str(" ");
+            }
+        }
 
-    TIME_DEPTH.with(|slot| slot.set(old));
+        data.push_str(")");
 
-    rv
+        print_time_passes_entry_internal(what, data);
+        result
+    } else {
+        time_impl(what, f)
+    }
 }
 
 pub fn print_time_passes_entry(do_it: bool, what: &str, dur: Duration) {
@@ -155,12 +240,12 @@ pub fn print_time_passes_entry(do_it: bool, what: &str, dur: Duration) {
         r
     });
 
-    print_time_passes_entry_internal(what, dur);
+    print_time_passes_entry_internal(what, duration_to_secs_str(dur));
 
     TIME_DEPTH.with(|slot| slot.set(old));
 }
 
-fn print_time_passes_entry_internal(what: &str, dur: Duration) {
+fn print_time_passes_entry_internal(what: &str, data: String) {
     let indentation = TIME_DEPTH.with(|slot| slot.get());
 
     let mem_string = match get_resident() {
@@ -172,7 +257,7 @@ fn print_time_passes_entry_internal(what: &str, dur: Duration) {
     };
     println!("{}time: {}{}\t{}",
              repeat("  ").take(indentation).collect::<String>(),
-             duration_to_secs_str(dur),
+             data,
              mem_string,
              what);
 }