Rollup merge of #82256 - eddyb:time-passes-stderr, r=varkor

Print -Ztime-passes (and misc stats/logs) on stderr, not stdout.

I've tried not to change anything that looked similar to `rustc --print`, where people might use automation, and/or any "bulk" prints, such as dumping an entire Graphviz (`dot`) graph on stdout.

The reason I want `-Ztime-passes` to be on stderr like debug logging is I can get a complete (and correctly interleaved) view just by looking at stderr, which is merely a convenience when running `rustc`/Cargo directly, but even more important when it's nested in a build script, as Cargo will split the build script output into stdout (named `output`) and `stderr`.

compiler/rustc_data_structures/src/profiling.rs

@@ -608,7 +608,7 @@ pub fn print_time_passes_entry(
         (None, None) => String::new(),
     };
 
-    println!("time: {:>7}{}\t{}", duration_to_secs_str(dur), mem_string, what);
+    eprintln!("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

compiler/rustc_incremental/src/persist/file_format.rs

@@ -109,7 +109,7 @@ fn report_format_mismatch(report_incremental_info: bool, file: &Path, message: &
     debug!("read_file: {}", message);
 
     if report_incremental_info {
-        println!(
+        eprintln!(
             "[incremental] ignoring cache artifact `{}`: {}",
             file.file_name().unwrap().to_string_lossy(),
             message

compiler/rustc_incremental/src/persist/fs.rs

@@ -440,12 +440,12 @@ fn copy_files(sess: &Session, target_dir: &Path, source_dir: &Path) -> Result<bo
     }
 
     if sess.opts.debugging_opts.incremental_info {
-        println!(
+        eprintln!(
             "[incremental] session directory: \
                   {} files hard-linked",
             files_linked
         );
-        println!(
+        eprintln!(
             "[incremental] session directory: \
                  {} files copied",
             files_copied

compiler/rustc_incremental/src/persist/load.rs

@@ -170,7 +170,7 @@ pub fn load_dep_graph(sess: &Session) -> DepGraphFuture {
 
                 if prev_commandline_args_hash != expected_hash {
                     if report_incremental_info {
-                        println!(
+                        eprintln!(
                             "[incremental] completely ignoring cache because of \
                                     differing commandline arguments"
                         );

compiler/rustc_interface/src/passes.rs

@@ -64,8 +64,8 @@ pub fn parse<'a>(sess: &'a Session, input: &Input) -> PResult<'a, ast::Crate> {
     }
 
     if sess.opts.debugging_opts.input_stats {
-        println!("Lines of code:             {}", sess.source_map().count_lines());
-        println!("Pre-expansion node count:  {}", count_nodes(&krate));
+        eprintln!("Lines of code:             {}", sess.source_map().count_lines());
+        eprintln!("Pre-expansion node count:  {}", count_nodes(&krate));
     }
 
     if let Some(ref s) = sess.opts.debugging_opts.show_span {
@@ -394,7 +394,7 @@ fn configure_and_expand_inner<'a>(
     // Done with macro expansion!
 
     if sess.opts.debugging_opts.input_stats {
-        println!("Post-expansion node count: {}", count_nodes(&krate));
+        eprintln!("Post-expansion node count: {}", count_nodes(&krate));
     }
 
     if sess.opts.debugging_opts.hir_stats {

compiler/rustc_metadata/src/rmeta/encoder.rs

@@ -695,23 +695,23 @@ impl<'a, 'tcx> EncodeContext<'a, 'tcx> {
                 }
             }
 
-            println!("metadata stats:");
-            println!("             dep bytes: {}", dep_bytes);
-            println!("     lib feature bytes: {}", lib_feature_bytes);
-            println!("       lang item bytes: {}", lang_item_bytes);
-            println!(" diagnostic item bytes: {}", diagnostic_item_bytes);
-            println!("          native bytes: {}", native_lib_bytes);
-            println!("      source_map bytes: {}", source_map_bytes);
-            println!("            impl bytes: {}", impl_bytes);
-            println!("    exp. symbols bytes: {}", exported_symbols_bytes);
-            println!("  def-path table bytes: {}", def_path_table_bytes);
-            println!(" proc-macro-data-bytes: {}", proc_macro_data_bytes);
-            println!("             mir bytes: {}", mir_bytes);
-            println!("            item bytes: {}", item_bytes);
-            println!("           table bytes: {}", tables_bytes);
-            println!("         hygiene bytes: {}", hygiene_bytes);
-            println!("            zero bytes: {}", zero_bytes);
-            println!("           total bytes: {}", total_bytes);
+            eprintln!("metadata stats:");
+            eprintln!("             dep bytes: {}", dep_bytes);
+            eprintln!("     lib feature bytes: {}", lib_feature_bytes);
+            eprintln!("       lang item bytes: {}", lang_item_bytes);
+            eprintln!(" diagnostic item bytes: {}", diagnostic_item_bytes);
+            eprintln!("          native bytes: {}", native_lib_bytes);
+            eprintln!("      source_map bytes: {}", source_map_bytes);
+            eprintln!("            impl bytes: {}", impl_bytes);
+            eprintln!("    exp. symbols bytes: {}", exported_symbols_bytes);
+            eprintln!("  def-path table bytes: {}", def_path_table_bytes);
+            eprintln!(" proc-macro-data-bytes: {}", proc_macro_data_bytes);
+            eprintln!("             mir bytes: {}", mir_bytes);
+            eprintln!("            item bytes: {}", item_bytes);
+            eprintln!("           table bytes: {}", tables_bytes);
+            eprintln!("         hygiene bytes: {}", hygiene_bytes);
+            eprintln!("            zero bytes: {}", zero_bytes);
+            eprintln!("           total bytes: {}", total_bytes);
         }
 
         root

compiler/rustc_middle/src/ty/query/stats.rs

@@ -67,29 +67,29 @@ pub fn print_stats(tcx: TyCtxt<'_>) {
     if cfg!(debug_assertions) {
         let hits: usize = queries.iter().map(|s| s.cache_hits).sum();
         let results: usize = queries.iter().map(|s| s.entry_count).sum();
-        println!("\nQuery cache hit rate: {}", hits as f64 / (hits + results) as f64);
+        eprintln!("\nQuery cache hit rate: {}", hits as f64 / (hits + results) as f64);
     }
 
     let mut query_key_sizes = queries.clone();
     query_key_sizes.sort_by_key(|q| q.key_size);
-    println!("\nLarge query keys:");
+    eprintln!("\nLarge query keys:");
     for q in query_key_sizes.iter().rev().filter(|q| q.key_size > 8) {
-        println!("   {} - {} x {} - {}", q.name, q.key_size, q.entry_count, q.key_type);
+        eprintln!("   {} - {} x {} - {}", q.name, q.key_size, q.entry_count, q.key_type);
     }
 
     let mut query_value_sizes = queries.clone();
     query_value_sizes.sort_by_key(|q| q.value_size);
-    println!("\nLarge query values:");
+    eprintln!("\nLarge query values:");
     for q in query_value_sizes.iter().rev().filter(|q| q.value_size > 8) {
-        println!("   {} - {} x {} - {}", q.name, q.value_size, q.entry_count, q.value_type);
+        eprintln!("   {} - {} x {} - {}", q.name, q.value_size, q.entry_count, q.value_type);
     }
 
     if cfg!(debug_assertions) {
         let mut query_cache_hits = queries.clone();
         query_cache_hits.sort_by_key(|q| q.cache_hits);
-        println!("\nQuery cache hits:");
+        eprintln!("\nQuery cache hits:");
         for q in query_cache_hits.iter().rev() {
-            println!(
+            eprintln!(
                 "   {} - {} ({}%)",
                 q.name,
                 q.cache_hits,
@@ -100,19 +100,19 @@ pub fn print_stats(tcx: TyCtxt<'_>) {
 
     let mut query_value_count = queries.clone();
     query_value_count.sort_by_key(|q| q.entry_count);
-    println!("\nQuery value count:");
+    eprintln!("\nQuery value count:");
     for q in query_value_count.iter().rev() {
-        println!("   {} - {}", q.name, q.entry_count);
+        eprintln!("   {} - {}", q.name, q.entry_count);
     }
 
     let mut def_id_density: Vec<_> =
         queries.iter().filter(|q| q.local_def_id_keys.is_some()).collect();
     def_id_density.sort_by_key(|q| q.local_def_id_keys.unwrap());
-    println!("\nLocal DefId density:");
+    eprintln!("\nLocal DefId density:");
     let total = tcx.hir().definitions().def_index_count() as f64;
     for q in def_id_density.iter().rev() {
         let local = q.local_def_id_keys.unwrap();
-        println!("   {} - {} = ({}%)", q.name, local, (local as f64 * 100.0) / total);
+        eprintln!("   {} - {} = ({}%)", q.name, local, (local as f64 * 100.0) / total);
     }
 }
 

compiler/rustc_mir/src/transform/coverage/tests.rs

@@ -327,7 +327,7 @@ macro_rules! assert_successors {
 fn test_covgraph_goto_switchint() {
     let mir_body = goto_switchint();
     if false {
-        println!("basic_blocks = {}", debug_basic_blocks(&mir_body));
+        eprintln!("basic_blocks = {}", debug_basic_blocks(&mir_body));
     }
     let basic_coverage_blocks = graph::CoverageGraph::from_mir(&mir_body);
     print_coverage_graphviz("covgraph_goto_switchint ", &mir_body, &basic_coverage_blocks);
@@ -583,11 +583,11 @@ fn test_find_loop_backedges_none() {
     let mir_body = goto_switchint();
     let basic_coverage_blocks = graph::CoverageGraph::from_mir(&mir_body);
     if false {
-        println!(
+        eprintln!(
             "basic_coverage_blocks = {:?}",
             basic_coverage_blocks.iter_enumerated().collect::<Vec<_>>()
         );
-        println!("successors = {:?}", basic_coverage_blocks.successors);
+        eprintln!("successors = {:?}", basic_coverage_blocks.successors);
     }
     let backedges = graph::find_loop_backedges(&basic_coverage_blocks);
     assert_eq!(

compiler/rustc_passes/src/hir_stats.rs

@@ -66,13 +66,13 @@ impl<'k> StatCollector<'k> {
 
         let mut total_size = 0;
 
-        println!("\n{}\n", title);
+        eprintln!("\n{}\n", title);
 
-        println!("{:<18}{:>18}{:>14}{:>14}", "Name", "Accumulated Size", "Count", "Item Size");
-        println!("----------------------------------------------------------------");
+        eprintln!("{:<18}{:>18}{:>14}{:>14}", "Name", "Accumulated Size", "Count", "Item Size");
+        eprintln!("----------------------------------------------------------------");
 
         for (label, data) in stats {
-            println!(
+            eprintln!(
                 "{:<18}{:>18}{:>14}{:>14}",
                 label,
                 to_readable_str(data.count * data.size),
@@ -82,8 +82,8 @@ impl<'k> StatCollector<'k> {
 
             total_size += data.count * data.size;
         }
-        println!("----------------------------------------------------------------");
-        println!("{:<18}{:>18}\n", "Total", to_readable_str(total_size));
+        eprintln!("----------------------------------------------------------------");
+        eprintln!("{:<18}{:>18}\n", "Total", to_readable_str(total_size));
     }
 }
 

compiler/rustc_query_system/src/dep_graph/graph.rs

@@ -964,29 +964,29 @@ impl<K: DepKind> DepGraph<K> {
                                  ----------------------------------------------\
                                  ------------";
 
-        println!("[incremental]");
-        println!("[incremental] DepGraph Statistics");
-        println!("{}", SEPARATOR);
-        println!("[incremental]");
-        println!("[incremental] Total Node Count: {}", total_node_count);
-        println!("[incremental] Total Edge Count: {}", total_edge_count);
+        eprintln!("[incremental]");
+        eprintln!("[incremental] DepGraph Statistics");
+        eprintln!("{}", SEPARATOR);
+        eprintln!("[incremental]");
+        eprintln!("[incremental] Total Node Count: {}", total_node_count);
+        eprintln!("[incremental] Total Edge Count: {}", total_edge_count);
 
         if cfg!(debug_assertions) {
             let total_edge_reads = current.total_read_count.load(Relaxed);
             let total_duplicate_edge_reads = current.total_duplicate_read_count.load(Relaxed);
 
-            println!("[incremental] Total Edge Reads: {}", total_edge_reads);
-            println!("[incremental] Total Duplicate Edge Reads: {}", total_duplicate_edge_reads);
+            eprintln!("[incremental] Total Edge Reads: {}", total_edge_reads);
+            eprintln!("[incremental] Total Duplicate Edge Reads: {}", total_duplicate_edge_reads);
         }
 
-        println!("[incremental]");
+        eprintln!("[incremental]");
 
-        println!(
+        eprintln!(
             "[incremental]  {:<36}| {:<17}| {:<12}| {:<17}|",
             "Node Kind", "Node Frequency", "Node Count", "Avg. Edge Count"
         );
 
-        println!(
+        eprintln!(
             "[incremental] -------------------------------------\
                   |------------------\
                   |-------------\
@@ -997,7 +997,7 @@ impl<K: DepKind> DepGraph<K> {
             let node_kind_ratio = (100.0 * (stat.node_counter as f64)) / (total_node_count as f64);
             let node_kind_avg_edges = (stat.edge_counter as f64) / (stat.node_counter as f64);
 
-            println!(
+            eprintln!(
                 "[incremental]  {:<36}|{:>16.1}% |{:>12} |{:>17.1} |",
                 format!("{:?}", stat.kind),
                 node_kind_ratio,
@@ -1006,8 +1006,8 @@ impl<K: DepKind> DepGraph<K> {
             );
         }
 
-        println!("{}", SEPARATOR);
-        println!("[incremental]");
+        eprintln!("{}", SEPARATOR);
+        eprintln!("[incremental]");
     }
 
     fn next_virtual_depnode_index(&self) -> DepNodeIndex {

compiler/rustc_session/src/session.rs

@@ -959,19 +959,19 @@ impl Session {
     }
 
     pub fn print_perf_stats(&self) {
-        println!(
+        eprintln!(
             "Total time spent computing symbol hashes:      {}",
             duration_to_secs_str(*self.perf_stats.symbol_hash_time.lock())
         );
-        println!(
+        eprintln!(
             "Total queries canonicalized:                   {}",
             self.perf_stats.queries_canonicalized.load(Ordering::Relaxed)
         );
-        println!(
+        eprintln!(
             "normalize_generic_arg_after_erasing_regions:   {}",
             self.perf_stats.normalize_generic_arg_after_erasing_regions.load(Ordering::Relaxed)
         );
-        println!(
+        eprintln!(
             "normalize_projection_ty:                       {}",
             self.perf_stats.normalize_projection_ty.load(Ordering::Relaxed)
         );

compiler/rustc_span/src/source_map/tests.rs

@@ -243,7 +243,7 @@ impl SourceMapExtension for SourceMap {
         substring: &str,
         n: usize,
     ) -> Span {
-        println!(
+        eprintln!(
             "span_substr(file={:?}/{:?}, substring={:?}, n={})",
             file.name, file.start_pos, substring, n
         );