Rollup merge of rust-lang#81536 - tgnottingham:time-passes-rss, r=oli-obk

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

Previously, only the end of pass RSS was indicated. This could easily
lead one to believe that the change in RSS from one pass to the next was
attributable to the second pass, when in fact it occurred between the
end of the first pass and the start of the second.

Also, improve alignment of columns.

Sample of output:

```
time:   0.739; rss:   607MB ->   637MB	item_types_checking
time:   8.429; rss:   637MB ->   775MB	item_bodies_checking
time:  11.063; rss:   470MB ->   775MB	type_check_crate
time:   0.232; rss:   775MB ->   777MB	match_checking
time:   0.139; rss:   777MB ->   779MB	liveness_and_intrinsic_checking
time:   0.372; rss:   775MB ->   779MB	misc_checking_2
time:   8.188; rss:   779MB ->  1019MB	MIR_borrow_checking
time:   0.062; rss:  1019MB ->  1021MB	MIR_effect_checking
```

Author: jonas-schievink

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();
@@ -669,7 +670,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)
 }