diff --git a/compiler/rustc_codegen_cranelift/src/bin/cg_clif.rs b/compiler/rustc_codegen_cranelift/src/bin/cg_clif.rs index 58e45b4e9b972..be369b07fddfe 100644 --- a/compiler/rustc_codegen_cranelift/src/bin/cg_clif.rs +++ b/compiler/rustc_codegen_cranelift/src/bin/cg_clif.rs @@ -6,7 +6,7 @@ extern crate rustc_interface; extern crate rustc_session; extern crate rustc_target; -use rustc_data_structures::profiling::print_time_passes_entry; +use rustc_data_structures::profiling::{get_resident_set_size, print_time_passes_entry}; use rustc_interface::interface; use rustc_session::config::ErrorOutputType; use rustc_session::early_error; @@ -39,7 +39,8 @@ impl rustc_driver::Callbacks for CraneliftPassesCallbacks { } fn main() { - let start = std::time::Instant::now(); + let start_time = std::time::Instant::now(); + let start_rss = get_resident_set_size(); rustc_driver::init_rustc_env_logger(); let mut callbacks = CraneliftPassesCallbacks::default(); rustc_driver::install_ice_hook(); @@ -61,7 +62,11 @@ fn main() { }))); run_compiler.run() }); - // The extra `\t` is necessary to align this label with the others. - print_time_passes_entry(callbacks.time_passes, "\ttotal", start.elapsed()); + + if callbacks.time_passes { + let end_rss = get_resident_set_size(); + print_time_passes_entry("total", start_time.elapsed(), start_rss, end_rss); + } + std::process::exit(exit_code) } diff --git a/compiler/rustc_codegen_ssa/src/base.rs b/compiler/rustc_codegen_ssa/src/base.rs index 0ce85c5715f17..0fc11c286f899 100644 --- a/compiler/rustc_codegen_ssa/src/base.rs +++ b/compiler/rustc_codegen_ssa/src/base.rs @@ -12,7 +12,7 @@ use crate::{CachedModuleCodegen, CrateInfo, MemFlags, ModuleCodegen, ModuleKind} use rustc_attr as attr; use rustc_data_structures::fx::FxHashMap; -use rustc_data_structures::profiling::print_time_passes_entry; +use rustc_data_structures::profiling::{get_resident_set_size, print_time_passes_entry}; use rustc_data_structures::sync::{par_iter, ParallelIterator}; use rustc_hir as hir; use rustc_hir::def_id::{LocalDefId, LOCAL_CRATE}; @@ -595,6 +595,7 @@ pub fn codegen_crate( let mut cgu_reuse = Vec::new(); let mut pre_compiled_cgus: Option> = None; let mut total_codegen_time = Duration::new(0, 0); + let start_rss = tcx.sess.time_passes().then(|| get_resident_set_size()); for (i, cgu) in codegen_units.iter().enumerate() { ongoing_codegen.wait_for_signal_to_codegen_item(); @@ -669,7 +670,16 @@ pub fn codegen_crate( // Since the main thread is sometimes blocked during codegen, we keep track // -Ztime-passes output manually. - print_time_passes_entry(tcx.sess.time_passes(), "codegen_to_LLVM_IR", total_codegen_time); + if tcx.sess.time_passes() { + let end_rss = get_resident_set_size(); + + print_time_passes_entry( + "codegen_to_LLVM_IR", + total_codegen_time, + start_rss.unwrap(), + end_rss, + ); + } ongoing_codegen.check_for_errors(tcx.sess); diff --git a/compiler/rustc_data_structures/src/profiling.rs b/compiler/rustc_data_structures/src/profiling.rs index b16d5a9e2b421..9a85b9d02c995 100644 --- a/compiler/rustc_data_structures/src/profiling.rs +++ b/compiler/rustc_data_structures/src/profiling.rs @@ -555,13 +555,16 @@ impl<'a> TimingGuard<'a> { #[must_use] pub struct VerboseTimingGuard<'a> { - start_and_message: Option<(Instant, String)>, + start_and_message: Option<(Instant, Option, String)>, _guard: TimingGuard<'a>, } impl<'a> VerboseTimingGuard<'a> { pub fn start(message: Option, _guard: TimingGuard<'a>) -> Self { - VerboseTimingGuard { _guard, start_and_message: message.map(|msg| (Instant::now(), msg)) } + VerboseTimingGuard { + _guard, + start_and_message: message.map(|msg| (Instant::now(), get_resident_set_size(), msg)), + } } #[inline(always)] @@ -573,25 +576,42 @@ impl<'a> VerboseTimingGuard<'a> { impl Drop for VerboseTimingGuard<'_> { fn drop(&mut self) { - if let Some((start, ref message)) = self.start_and_message { - print_time_passes_entry(true, &message[..], start.elapsed()); + if let Some((start_time, start_rss, ref message)) = self.start_and_message { + let end_rss = get_resident_set_size(); + print_time_passes_entry(&message[..], start_time.elapsed(), start_rss, end_rss); } } } -pub fn print_time_passes_entry(do_it: bool, what: &str, dur: Duration) { - if !do_it { - return; - } - - let mem_string = match get_resident() { - Some(n) => { - let mb = n as f64 / 1_000_000.0; - format!("; rss: {}MB", mb.round() as usize) +pub fn print_time_passes_entry( + what: &str, + dur: Duration, + start_rss: Option, + end_rss: Option, +) { + let rss_to_mb = |rss| (rss as f64 / 1_000_000.0).round() as usize; + + let mem_string = match (start_rss, end_rss) { + (Some(start_rss), Some(end_rss)) => { + // It's tempting to add the change in RSS from start to end, but its somewhat confusing + // and misleading when looking at time-passes output. Consider two adjacent entries: + // + // time: 10.000; rss start: 1000MB, end: 1000MB, change: 0MB pass1 + // time: 5.000; rss start: 2000MB, end: 2000MB, change: 0MB pass2 + // + // If you're looking for jumps in RSS based on the change column, you miss the fact + // that a 1GB jump happened between pass1 and pass2 (supposing pass1 and pass2 actually + // occur sequentially and pass1 isn't just nested within pass2). It's easy to imagine + // someone missing this or being confused by the fact that the change is zero. + + format!("; rss: {:>5}MB -> {:>5}MB", rss_to_mb(start_rss), rss_to_mb(end_rss)) } - None => String::new(), + (Some(start_rss), None) => format!("; rss start: {:>5}MB", rss_to_mb(start_rss)), + (None, Some(end_rss)) => format!("; rss end: {:5>}MB", rss_to_mb(end_rss)), + (None, None) => String::new(), }; - println!("time: {}{}\t{}", duration_to_secs_str(dur), mem_string, what); + + println!("time: {:>7}{}\t{}", duration_to_secs_str(dur), mem_string, what); } // Hack up our own formatting for the duration to make it easier for scripts @@ -603,7 +623,7 @@ pub fn duration_to_secs_str(dur: std::time::Duration) -> String { // Memory reporting cfg_if! { if #[cfg(windows)] { - fn get_resident() -> Option { + pub fn get_resident_set_size() -> Option { use std::mem::{self, MaybeUninit}; use winapi::shared::minwindef::DWORD; use winapi::um::processthreadsapi::GetCurrentProcess; @@ -621,7 +641,7 @@ cfg_if! { } } } else if #[cfg(unix)] { - fn get_resident() -> Option { + pub fn get_resident_set_size() -> Option { let field = 1; let contents = fs::read("/proc/self/statm").ok()?; let contents = String::from_utf8(contents).ok()?; @@ -630,7 +650,7 @@ cfg_if! { Some(npages * 4096) } } else { - fn get_resident() -> Option { + pub fn get_resident_set_size() -> Option { None } } diff --git a/compiler/rustc_driver/src/lib.rs b/compiler/rustc_driver/src/lib.rs index 15b984acac590..8295e88f75ac7 100644 --- a/compiler/rustc_driver/src/lib.rs +++ b/compiler/rustc_driver/src/lib.rs @@ -16,7 +16,7 @@ pub extern crate rustc_plugin_impl as plugin; use rustc_ast as ast; use rustc_codegen_ssa::{traits::CodegenBackend, CodegenResults}; -use rustc_data_structures::profiling::print_time_passes_entry; +use rustc_data_structures::profiling::{get_resident_set_size, print_time_passes_entry}; use rustc_data_structures::sync::SeqCst; use rustc_errors::registry::{InvalidErrorCode, Registry}; use rustc_errors::{ErrorReported, PResult}; @@ -1312,7 +1312,8 @@ pub fn init_env_logger(env: &str) { } pub fn main() -> ! { - let start = Instant::now(); + let start_time = Instant::now(); + let start_rss = get_resident_set_size(); init_rustc_env_logger(); let mut callbacks = TimePassesCallbacks::default(); install_ice_hook(); @@ -1330,7 +1331,11 @@ pub fn main() -> ! { .collect::>(); RunCompiler::new(&args, &mut callbacks).run() }); - // The extra `\t` is necessary to align this label with the others. - print_time_passes_entry(callbacks.time_passes, "\ttotal", start.elapsed()); + + if callbacks.time_passes { + let end_rss = get_resident_set_size(); + print_time_passes_entry("total", start_time.elapsed(), start_rss, end_rss); + } + process::exit(exit_code) }