From 81dccb1a5c7b67c61cb7eb421150c671d6e1a7de Mon Sep 17 00:00:00 2001 From: Michael Woerister Date: Fri, 7 Feb 2020 15:01:23 +0100 Subject: [PATCH] self-profile: Support arguments for generic_activities. --- src/librustc/ty/query/on_disk_cache.rs | 6 +- src/librustc_codegen_llvm/back/lto.rs | 57 +++++++----- src/librustc_codegen_llvm/back/write.rs | 69 +++++++------- src/librustc_codegen_ssa/back/link.rs | 2 +- src/librustc_codegen_ssa/back/write.rs | 19 ++-- src/librustc_data_structures/profiling.rs | 107 +++++++++++++++------- src/librustc_lint/early.rs | 6 +- src/librustc_lint/late.rs | 21 ++--- 8 files changed, 169 insertions(+), 118 deletions(-) diff --git a/src/librustc/ty/query/on_disk_cache.rs b/src/librustc/ty/query/on_disk_cache.rs index a81fe33831c96..01f684dc65c30 100644 --- a/src/librustc/ty/query/on_disk_cache.rs +++ b/src/librustc/ty/query/on_disk_cache.rs @@ -1053,8 +1053,10 @@ where Q: super::config::QueryDescription<'tcx, Value: Encodable>, E: 'a + TyEncoder, { - let desc = &format!("encode_query_results_for_{}", ::std::any::type_name::()); - let _timer = tcx.sess.prof.extra_verbose_generic_activity(desc); + let _timer = tcx + .sess + .prof + .extra_verbose_generic_activity("encode_query_results_for", ::std::any::type_name::()); let shards = Q::query_cache(tcx).lock_shards(); assert!(shards.iter().all(|shard| shard.active.is_empty())); diff --git a/src/librustc_codegen_llvm/back/lto.rs b/src/librustc_codegen_llvm/back/lto.rs index b5895b53698dc..76a6ffbb1c5b2 100644 --- a/src/librustc_codegen_llvm/back/lto.rs +++ b/src/librustc_codegen_llvm/back/lto.rs @@ -110,23 +110,21 @@ fn prepare_lto( symbol_white_list.extend(exported_symbols[&cnum].iter().filter_map(symbol_filter)); } - let _timer = cgcx.prof.generic_activity("LLVM_lto_load_upstream_bitcode"); let archive = ArchiveRO::open(&path).expect("wanted an rlib"); let bytecodes = archive .iter() .filter_map(|child| child.ok().and_then(|c| c.name().map(|name| (name, c)))) .filter(|&(name, _)| name.ends_with(RLIB_BYTECODE_EXTENSION)); for (name, data) in bytecodes { + let _timer = + cgcx.prof.generic_activity_with_arg("LLVM_lto_load_upstream_bitcode", name); info!("adding bytecode {}", name); let bc_encoded = data.data(); - let (bc, id) = cgcx - .prof - .extra_verbose_generic_activity(&format!("decode {}", name)) - .run(|| match DecodedBytecode::new(bc_encoded) { - Ok(b) => Ok((b.bytecode(), b.identifier().to_string())), - Err(e) => Err(diag_handler.fatal(&e)), - })?; + let (bc, id) = match DecodedBytecode::new(bc_encoded) { + Ok(b) => Ok((b.bytecode(), b.identifier().to_string())), + Err(e) => Err(diag_handler.fatal(&e)), + }?; let bc = SerializedModule::FromRlib(bc); upstream_modules.push((bc, CString::new(id).unwrap())); } @@ -281,14 +279,14 @@ fn fat_lto( // save and persist everything with the original module. let mut linker = Linker::new(llmod); for (bc_decoded, name) in serialized_modules { - let _timer = cgcx.prof.generic_activity("LLVM_fat_lto_link_module"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_fat_lto_link_module", format!("{:?}", name)); info!("linking {:?}", name); - cgcx.prof.extra_verbose_generic_activity(&format!("ll link {:?}", name)).run(|| { - let data = bc_decoded.data(); - linker.add(&data).map_err(|()| { - let msg = format!("failed to load bc of {:?}", name); - write::llvm_err(&diag_handler, &msg) - }) + let data = bc_decoded.data(); + linker.add(&data).map_err(|()| { + let msg = format!("failed to load bc of {:?}", name); + write::llvm_err(&diag_handler, &msg) })?; serialized_bitcode.push(bc_decoded); } @@ -577,6 +575,8 @@ pub(crate) fn run_pass_manager( config: &ModuleConfig, thin: bool, ) { + let _timer = cgcx.prof.extra_verbose_generic_activity("LLVM_lto_optimize", &module.name[..]); + // Now we have one massive module inside of llmod. Time to run the // LTO-specific optimization passes that LLVM provides. // @@ -634,9 +634,7 @@ pub(crate) fn run_pass_manager( llvm::LLVMRustAddPass(pm, pass.unwrap()); } - cgcx.prof - .extra_verbose_generic_activity("LTO_passes") - .run(|| llvm::LLVMRunPassManager(pm, module.module_llvm.llmod())); + llvm::LLVMRunPassManager(pm, module.module_llvm.llmod()); llvm::LLVMDisposePassManager(pm); } @@ -760,7 +758,9 @@ pub unsafe fn optimize_thin_module( // Like with "fat" LTO, get some better optimizations if landing pads // are disabled by removing all landing pads. if cgcx.no_landing_pads { - let _timer = cgcx.prof.generic_activity("LLVM_thin_lto_remove_landing_pads"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_thin_lto_remove_landing_pads", thin_module.name()); llvm::LLVMRustMarkAllFunctionsNounwind(llmod); save_temp_bitcode(&cgcx, &module, "thin-lto-after-nounwind"); } @@ -774,7 +774,8 @@ pub unsafe fn optimize_thin_module( // You can find some more comments about these functions in the LLVM // bindings we've got (currently `PassWrapper.cpp`) { - let _timer = cgcx.prof.generic_activity("LLVM_thin_lto_rename"); + let _timer = + cgcx.prof.generic_activity_with_arg("LLVM_thin_lto_rename", thin_module.name()); if !llvm::LLVMRustPrepareThinLTORename(thin_module.shared.data.0, llmod) { let msg = "failed to prepare thin LTO module"; return Err(write::llvm_err(&diag_handler, msg)); @@ -783,7 +784,9 @@ pub unsafe fn optimize_thin_module( } { - let _timer = cgcx.prof.generic_activity("LLVM_thin_lto_resolve_weak"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_thin_lto_resolve_weak", thin_module.name()); if !llvm::LLVMRustPrepareThinLTOResolveWeak(thin_module.shared.data.0, llmod) { let msg = "failed to prepare thin LTO module"; return Err(write::llvm_err(&diag_handler, msg)); @@ -792,7 +795,9 @@ pub unsafe fn optimize_thin_module( } { - let _timer = cgcx.prof.generic_activity("LLVM_thin_lto_internalize"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_thin_lto_internalize", thin_module.name()); if !llvm::LLVMRustPrepareThinLTOInternalize(thin_module.shared.data.0, llmod) { let msg = "failed to prepare thin LTO module"; return Err(write::llvm_err(&diag_handler, msg)); @@ -801,7 +806,8 @@ pub unsafe fn optimize_thin_module( } { - let _timer = cgcx.prof.generic_activity("LLVM_thin_lto_import"); + let _timer = + cgcx.prof.generic_activity_with_arg("LLVM_thin_lto_import", thin_module.name()); if !llvm::LLVMRustPrepareThinLTOImport(thin_module.shared.data.0, llmod) { let msg = "failed to prepare thin LTO module"; return Err(write::llvm_err(&diag_handler, msg)); @@ -839,7 +845,9 @@ pub unsafe fn optimize_thin_module( // so it appears). Hopefully we can remove this once upstream bugs are // fixed in LLVM. { - let _timer = cgcx.prof.generic_activity("LLVM_thin_lto_patch_debuginfo"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_thin_lto_patch_debuginfo", thin_module.name()); llvm::LLVMRustThinLTOPatchDICompileUnit(llmod, cu1); save_temp_bitcode(cgcx, &module, "thin-lto-after-patch"); } @@ -850,7 +858,6 @@ pub unsafe fn optimize_thin_module( // populate a thin-specific pass manager, which presumably LLVM treats a // little differently. { - let _timer = cgcx.prof.generic_activity("LLVM_thin_lto_optimize"); info!("running thin lto passes over {}", module.name); let config = cgcx.config(module.kind); run_pass_manager(cgcx, &module, config, true); diff --git a/src/librustc_codegen_llvm/back/write.rs b/src/librustc_codegen_llvm/back/write.rs index 4be7b84660d09..7dd57da90c3d6 100644 --- a/src/librustc_codegen_llvm/back/write.rs +++ b/src/librustc_codegen_llvm/back/write.rs @@ -310,7 +310,7 @@ pub(crate) unsafe fn optimize( module: &ModuleCodegen, config: &ModuleConfig, ) -> Result<(), FatalError> { - let _timer = cgcx.prof.generic_activity("LLVM_module_optimize"); + let _timer = cgcx.prof.generic_activity_with_arg("LLVM_module_optimize", &module.name[..]); let llmod = module.module_llvm.llmod(); let llcx = &*module.module_llvm.llcx; @@ -424,23 +424,17 @@ pub(crate) unsafe fn optimize( // Finally, run the actual optimization passes { - let _timer = cgcx.prof.generic_activity("LLVM_module_optimize_function_passes"); - let desc = &format!("llvm function passes [{}]", module_name.unwrap()); - let _timer = if config.time_module { - Some(cgcx.prof.extra_verbose_generic_activity(desc)) - } else { - None - }; + let _timer = cgcx.prof.extra_verbose_generic_activity( + "LLVM_module_optimize_function_passes", + &module.name[..], + ); llvm::LLVMRustRunFunctionPassManager(fpm, llmod); } { - let _timer = cgcx.prof.generic_activity("LLVM_module_optimize_module_passes"); - let desc = &format!("llvm module passes [{}]", module_name.unwrap()); - let _timer = if config.time_module { - Some(cgcx.prof.extra_verbose_generic_activity(desc)) - } else { - None - }; + let _timer = cgcx.prof.extra_verbose_generic_activity( + "LLVM_module_optimize_module_passes", + &module.name[..], + ); llvm::LLVMRunPassManager(mpm, llmod); } @@ -480,7 +474,7 @@ pub(crate) unsafe fn codegen( module: ModuleCodegen, config: &ModuleConfig, ) -> Result { - let _timer = cgcx.prof.generic_activity("LLVM_module_codegen"); + let _timer = cgcx.prof.generic_activity_with_arg("LLVM_module_codegen", &module.name[..]); { let llmod = module.module_llvm.llmod(); let llcx = &*module.module_llvm.llcx; @@ -533,12 +527,17 @@ pub(crate) unsafe fn codegen( let obj_out = cgcx.output_filenames.temp_path(OutputType::Object, module_name); if write_bc || config.emit_bc_compressed || config.embed_bitcode { - let _timer = cgcx.prof.generic_activity("LLVM_module_codegen_make_bitcode"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_module_codegen_make_bitcode", &module.name[..]); let thin = ThinBuffer::new(llmod); let data = thin.data(); if write_bc { - let _timer = cgcx.prof.generic_activity("LLVM_module_codegen_emit_bitcode"); + let _timer = cgcx.prof.generic_activity_with_arg( + "LLVM_module_codegen_emit_bitcode", + &module.name[..], + ); if let Err(e) = fs::write(&bc_out, data) { let msg = format!("failed to write bytecode to {}: {}", bc_out.display(), e); diag_handler.err(&msg); @@ -546,13 +545,18 @@ pub(crate) unsafe fn codegen( } if config.embed_bitcode { - let _timer = cgcx.prof.generic_activity("LLVM_module_codegen_embed_bitcode"); + let _timer = cgcx.prof.generic_activity_with_arg( + "LLVM_module_codegen_embed_bitcode", + &module.name[..], + ); embed_bitcode(cgcx, llcx, llmod, Some(data)); } if config.emit_bc_compressed { - let _timer = - cgcx.prof.generic_activity("LLVM_module_codegen_emit_compressed_bitcode"); + let _timer = cgcx.prof.generic_activity_with_arg( + "LLVM_module_codegen_emit_compressed_bitcode", + &module.name[..], + ); let dst = bc_out.with_extension(RLIB_BYTECODE_EXTENSION); let data = bytecode::encode(&module.name, data); if let Err(e) = fs::write(&dst, data) { @@ -565,15 +569,10 @@ pub(crate) unsafe fn codegen( } { - let desc = &format!("codegen passes [{}]", module_name.unwrap()); - let _timer = if config.time_module { - Some(cgcx.prof.extra_verbose_generic_activity(desc)) - } else { - None - }; - if config.emit_ir { - let _timer = cgcx.prof.generic_activity("LLVM_module_codegen_emit_ir"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_module_codegen_emit_ir", &module.name[..]); let out = cgcx.output_filenames.temp_path(OutputType::LlvmAssembly, module_name); let out_c = path_to_c_string(&out); @@ -618,7 +617,9 @@ pub(crate) unsafe fn codegen( } if config.emit_asm || asm_to_obj { - let _timer = cgcx.prof.generic_activity("LLVM_module_codegen_emit_asm"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_module_codegen_emit_asm", &module.name[..]); let path = cgcx.output_filenames.temp_path(OutputType::Assembly, module_name); // We can't use the same module for asm and binary output, because that triggers @@ -638,7 +639,9 @@ pub(crate) unsafe fn codegen( } if write_obj { - let _timer = cgcx.prof.generic_activity("LLVM_module_codegen_emit_obj"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_module_codegen_emit_obj", &module.name[..]); with_codegen(tm, llmod, config.no_builtins, |cpm| { write_output_file( diag_handler, @@ -650,7 +653,9 @@ pub(crate) unsafe fn codegen( ) })?; } else if asm_to_obj { - let _timer = cgcx.prof.generic_activity("LLVM_module_codegen_asm_to_obj"); + let _timer = cgcx + .prof + .generic_activity_with_arg("LLVM_module_codegen_asm_to_obj", &module.name[..]); let assembly = cgcx.output_filenames.temp_path(OutputType::Assembly, module_name); run_assembler(cgcx, diag_handler, &assembly, &obj_out); diff --git a/src/librustc_codegen_ssa/back/link.rs b/src/librustc_codegen_ssa/back/link.rs index 4f05aac089867..d3b8f7ea33fab 100644 --- a/src/librustc_codegen_ssa/back/link.rs +++ b/src/librustc_codegen_ssa/back/link.rs @@ -1648,7 +1648,7 @@ fn add_upstream_rust_crates<'a, B: ArchiveBuilder<'a>>( let name = cratepath.file_name().unwrap().to_str().unwrap(); let name = &name[3..name.len() - 5]; // chop off lib/.rlib - sess.prof.extra_verbose_generic_activity(&format!("altering {}.rlib", name)).run(|| { + sess.prof.generic_activity_with_arg("link_altering_rlib", name).run(|| { let mut archive = ::new(sess, &dst, Some(cratepath)); archive.update_symbols(); diff --git a/src/librustc_codegen_ssa/back/write.rs b/src/librustc_codegen_ssa/back/write.rs index 841827d15fef4..9905b3a56c0fa 100644 --- a/src/librustc_codegen_ssa/back/write.rs +++ b/src/librustc_codegen_ssa/back/write.rs @@ -21,6 +21,7 @@ use rustc::session::Session; use rustc::ty::TyCtxt; use rustc_data_structures::fx::FxHashMap; use rustc_data_structures::profiling::SelfProfilerRef; +use rustc_data_structures::profiling::TimingGuard; use rustc_data_structures::profiling::VerboseTimingGuard; use rustc_data_structures::svh::Svh; use rustc_data_structures::sync::Lrc; @@ -691,11 +692,17 @@ impl WorkItem { } } - fn profiling_event_id(&self) -> &'static str { + fn start_profiling<'a>(&self, cgcx: &'a CodegenContext) -> TimingGuard<'a> { match *self { - WorkItem::Optimize(_) => "codegen_module_optimize", - WorkItem::CopyPostLtoArtifacts(_) => "codegen_copy_artifacts_from_incr_cache", - WorkItem::LTO(_) => "codegen_module_perform_lto", + WorkItem::Optimize(ref m) => { + cgcx.prof.generic_activity_with_arg("codegen_module_optimize", &m.name[..]) + } + WorkItem::CopyPostLtoArtifacts(ref m) => cgcx + .prof + .generic_activity_with_arg("codegen_copy_artifacts_from_incr_cache", &m.name[..]), + WorkItem::LTO(ref m) => { + cgcx.prof.generic_activity_with_arg("codegen_module_perform_lto", m.name()) + } } } } @@ -1520,7 +1527,7 @@ fn start_executing_work( llvm_start_time: &mut Option>, ) { if config.time_module && llvm_start_time.is_none() { - *llvm_start_time = Some(prof.extra_verbose_generic_activity("LLVM_passes")); + *llvm_start_time = Some(prof.extra_verbose_generic_activity("LLVM_passes", "crate")); } } } @@ -1575,7 +1582,7 @@ fn spawn_work(cgcx: CodegenContext, work: WorkItem // as a diagnostic was already sent off to the main thread - just // surface that there was an error in this worker. bomb.result = { - let _prof_timer = cgcx.prof.generic_activity(work.profiling_event_id()); + let _prof_timer = work.start_profiling(&cgcx); Some(execute_work_item(&cgcx, work)) }; }); diff --git a/src/librustc_data_structures/profiling.rs b/src/librustc_data_structures/profiling.rs index 90f74328a1d51..debda9f0a0a24 100644 --- a/src/librustc_data_structures/profiling.rs +++ b/src/librustc_data_structures/profiling.rs @@ -83,6 +83,9 @@ use crate::fx::FxHashMap; +use std::borrow::Borrow; +use std::collections::hash_map::Entry; +use std::convert::Into; use std::error::Error; use std::fs; use std::path::Path; @@ -123,11 +126,14 @@ bitflags::bitflags! { const INCR_CACHE_LOADS = 1 << 4; const QUERY_KEYS = 1 << 5; + const FUNCTION_ARGS = 1 << 6; const DEFAULT = Self::GENERIC_ACTIVITIES.bits | Self::QUERY_PROVIDERS.bits | Self::QUERY_BLOCKED.bits | Self::INCR_CACHE_LOADS.bits; + + const ARGS = Self::QUERY_KEYS.bits | Self::FUNCTION_ARGS.bits; } } @@ -142,6 +148,8 @@ const EVENT_FILTERS_BY_NAME: &[(&str, EventFilter)] = &[ ("query-blocked", EventFilter::QUERY_BLOCKED), ("incr-cache-load", EventFilter::INCR_CACHE_LOADS), ("query-keys", EventFilter::QUERY_KEYS), + ("function-args", EventFilter::FUNCTION_ARGS), + ("args", EventFilter::ARGS), ]; /// Something that uniquely identifies a query invocation. @@ -216,43 +224,68 @@ impl SelfProfilerRef { /// VerboseTimingGuard returned from this call is dropped. In addition to recording /// a measureme event, "verbose" generic activities also print a timing entry to /// stdout if the compiler is invoked with -Ztime or -Ztime-passes. - #[inline(always)] pub fn verbose_generic_activity<'a>( &'a self, - event_id: &'static str, + event_label: &'static str, ) -> VerboseTimingGuard<'a> { - VerboseTimingGuard::start( - event_id, - self.print_verbose_generic_activities, - self.generic_activity(event_id), - ) + let message = + if self.print_verbose_generic_activities { Some(event_label.to_owned()) } else { None }; + + VerboseTimingGuard::start(message, self.generic_activity(event_label)) } /// Start profiling a extra verbose generic activity. Profiling continues until the /// VerboseTimingGuard returned from this call is dropped. In addition to recording /// a measureme event, "extra verbose" generic activities also print a timing entry to /// stdout if the compiler is invoked with -Ztime-passes. - #[inline(always)] - pub fn extra_verbose_generic_activity<'a>( + pub fn extra_verbose_generic_activity<'a, A>( &'a self, - event_id: &'a str, - ) -> VerboseTimingGuard<'a> { - // FIXME: This does not yet emit a measureme event - // because callers encode arguments into `event_id`. - VerboseTimingGuard::start( - event_id, - self.print_extra_verbose_generic_activities, - TimingGuard::none(), - ) + event_label: &'static str, + event_arg: A, + ) -> VerboseTimingGuard<'a> + where + A: Borrow + Into, + { + let message = if self.print_extra_verbose_generic_activities { + Some(format!("{}({})", event_label, event_arg.borrow())) + } else { + None + }; + + VerboseTimingGuard::start(message, self.generic_activity_with_arg(event_label, event_arg)) + } + + /// Start profiling a generic activity. Profiling continues until the + /// TimingGuard returned from this call is dropped. + #[inline(always)] + pub fn generic_activity(&self, event_label: &'static str) -> TimingGuard<'_> { + self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { + let event_label = profiler.get_or_alloc_cached_string(event_label); + let event_id = EventId::from_label(event_label); + TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) + }) } /// Start profiling a generic activity. Profiling continues until the /// TimingGuard returned from this call is dropped. #[inline(always)] - pub fn generic_activity(&self, event_id: &'static str) -> TimingGuard<'_> { + pub fn generic_activity_with_arg( + &self, + event_label: &'static str, + event_arg: A, + ) -> TimingGuard<'_> + where + A: Borrow + Into, + { self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { - let event_id = profiler.get_or_alloc_cached_string(event_id); - let event_id = EventId::from_label(event_id); + let builder = EventIdBuilder::new(&profiler.profiler); + let event_label = profiler.get_or_alloc_cached_string(event_label); + let event_id = if profiler.event_filter_mask.contains(EventFilter::FUNCTION_ARGS) { + let event_arg = profiler.get_or_alloc_cached_string(event_arg); + builder.from_label_and_arg(event_label, event_arg) + } else { + builder.from_label(event_label) + }; TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id) }) } @@ -337,7 +370,7 @@ pub struct SelfProfiler { profiler: Profiler, event_filter_mask: EventFilter, - string_cache: RwLock>, + string_cache: RwLock>, query_event_kind: StringId, generic_activity_event_kind: StringId, @@ -419,13 +452,16 @@ impl SelfProfiler { /// Gets a `StringId` for the given string. This method makes sure that /// any strings going through it will only be allocated once in the /// profiling data. - pub fn get_or_alloc_cached_string(&self, s: &'static str) -> StringId { + pub fn get_or_alloc_cached_string(&self, s: A) -> StringId + where + A: Borrow + Into, + { // Only acquire a read-lock first since we assume that the string is // already present in the common case. { let string_cache = self.string_cache.read(); - if let Some(&id) = string_cache.get(s) { + if let Some(&id) = string_cache.get(s.borrow()) { return id; } } @@ -433,7 +469,13 @@ impl SelfProfiler { let mut string_cache = self.string_cache.write(); // Check if the string has already been added in the small time window // between dropping the read lock and acquiring the write lock. - *string_cache.entry(s).or_insert_with(|| self.profiler.alloc_string(s)) + match string_cache.entry(s.into()) { + Entry::Occupied(e) => *e.get(), + Entry::Vacant(e) => { + let string_id = self.profiler.alloc_string(&e.key()[..]); + *e.insert(string_id) + } + } } pub fn map_query_invocation_id_to_string(&self, from: QueryInvocationId, to: StringId) { @@ -498,18 +540,13 @@ impl<'a> TimingGuard<'a> { #[must_use] pub struct VerboseTimingGuard<'a> { - event_id: &'a str, - start: Option, + start_and_message: Option<(Instant, String)>, _guard: TimingGuard<'a>, } impl<'a> VerboseTimingGuard<'a> { - pub fn start(event_id: &'a str, verbose: bool, _guard: TimingGuard<'a>) -> Self { - VerboseTimingGuard { - event_id, - _guard, - start: if unlikely!(verbose) { Some(Instant::now()) } else { None }, - } + pub fn start(message: Option, _guard: TimingGuard<'a>) -> Self { + VerboseTimingGuard { _guard, start_and_message: message.map(|msg| (Instant::now(), msg)) } } #[inline(always)] @@ -521,7 +558,9 @@ impl<'a> VerboseTimingGuard<'a> { impl Drop for VerboseTimingGuard<'_> { fn drop(&mut self) { - self.start.map(|start| print_time_passes_entry(true, self.event_id, start.elapsed())); + if let Some((start, ref message)) = self.start_and_message { + print_time_passes_entry(true, &message[..], start.elapsed()); + } } } diff --git a/src/librustc_lint/early.rs b/src/librustc_lint/early.rs index 542cbea0c954a..27781eb41d28d 100644 --- a/src/librustc_lint/early.rs +++ b/src/librustc_lint/early.rs @@ -342,10 +342,8 @@ pub fn check_ast_crate( } } else { for pass in &mut passes { - buffered = sess - .prof - .extra_verbose_generic_activity(&format!("running lint: {}", pass.name())) - .run(|| { + buffered = + sess.prof.extra_verbose_generic_activity("run_lint", pass.name()).run(|| { early_lint_crate( sess, lint_store, diff --git a/src/librustc_lint/late.rs b/src/librustc_lint/late.rs index 30a3788377508..b3d5cdf15c933 100644 --- a/src/librustc_lint/late.rs +++ b/src/librustc_lint/late.rs @@ -441,27 +441,20 @@ fn late_lint_crate<'tcx, T: for<'a> LateLintPass<'a, 'tcx>>(tcx: TyCtxt<'tcx>, b late_lint_pass_crate(tcx, builtin_lints); } else { for pass in &mut passes { - tcx.sess - .prof - .extra_verbose_generic_activity(&format!("running late lint: {}", pass.name())) - .run(|| { - late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) }); - }); + tcx.sess.prof.extra_verbose_generic_activity("run_late_lint", pass.name()).run(|| { + late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) }); + }); } let mut passes: Vec<_> = unerased_lint_store(tcx).late_module_passes.iter().map(|pass| (pass)()).collect(); for pass in &mut passes { - tcx.sess - .prof - .extra_verbose_generic_activity(&format!( - "running late module lint: {}", - pass.name() - )) - .run(|| { + tcx.sess.prof.extra_verbose_generic_activity("run_late_module_lint", pass.name()).run( + || { late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) }); - }); + }, + ); } } }