Indicate both start and end of pass RSS in time-passes output

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)
 }

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<B: ExtraBackendMethods>(
     let mut cgu_reuse = Vec::new();
     let mut pre_compiled_cgus: Option<FxHashMap<usize, _>> = 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();
@@ -664,7 +665,16 @@ pub fn codegen_crate<B: ExtraBackendMethods>(
 
     // 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);
 

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<usize>, String)>,
     _guard: TimingGuard<'a>,
 }
 
 impl<'a> VerboseTimingGuard<'a> {
     pub fn start(message: Option<String>, _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<usize>,
+    end_rss: Option<usize>,
+) {
+    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<usize> {
+        pub fn get_resident_set_size() -> Option<usize> {
             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<usize> {
+        pub fn get_resident_set_size() -> Option<usize> {
             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<usize> {
+        pub fn get_resident_set_size() -> Option<usize> {
             None
         }
     }

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::<Vec<_>>();
         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)
 }