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

This commit is contained in:
Eduard-Mihai Burtescu 2021-02-18 14:13:38 +02:00
parent 25a2c13e9d
commit 6165d1cc72
12 changed files with 64 additions and 64 deletions

View File

@ -608,7 +608,7 @@ pub fn print_time_passes_entry(
(None, None) => String::new(), (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 // Hack up our own formatting for the duration to make it easier for scripts

View File

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

View File

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

View File

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

View File

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

View File

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

View File

@ -67,29 +67,29 @@ pub fn print_stats(tcx: TyCtxt<'_>) {
if cfg!(debug_assertions) { if cfg!(debug_assertions) {
let hits: usize = queries.iter().map(|s| s.cache_hits).sum(); let hits: usize = queries.iter().map(|s| s.cache_hits).sum();
let results: usize = queries.iter().map(|s| s.entry_count).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(); let mut query_key_sizes = queries.clone();
query_key_sizes.sort_by_key(|q| q.key_size); 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) { 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(); let mut query_value_sizes = queries.clone();
query_value_sizes.sort_by_key(|q| q.value_size); 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) { 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) { if cfg!(debug_assertions) {
let mut query_cache_hits = queries.clone(); let mut query_cache_hits = queries.clone();
query_cache_hits.sort_by_key(|q| q.cache_hits); 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() { for q in query_cache_hits.iter().rev() {
println!( eprintln!(
" {} - {} ({}%)", " {} - {} ({}%)",
q.name, q.name,
q.cache_hits, q.cache_hits,
@ -100,19 +100,19 @@ pub fn print_stats(tcx: TyCtxt<'_>) {
let mut query_value_count = queries.clone(); let mut query_value_count = queries.clone();
query_value_count.sort_by_key(|q| q.entry_count); 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() { 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<_> = let mut def_id_density: Vec<_> =
queries.iter().filter(|q| q.local_def_id_keys.is_some()).collect(); 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()); 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; let total = tcx.hir().definitions().def_index_count() as f64;
for q in def_id_density.iter().rev() { for q in def_id_density.iter().rev() {
let local = q.local_def_id_keys.unwrap(); 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);
} }
} }

View File

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

View File

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

View File

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

View File

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

View File

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