mikros/rust
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Rollup merge of #68932 - michaelwoerister:self-profile-generic-activity-args, r=wesleywiser

Browse Source 
self-profile: Support arguments for generic_activities.

This PR adds support for recording arguments of "generic activities". The most notable use case is LLVM module names, which should be very interesting for `crox` profiles. In the future it might be interesting to add more fine-grained events for pre-query passes like macro expansion.

I tried to judiciously de-duplicate existing self-profile events with `extra_verbose_generic_activity`, now that the latter also generates self-profile events.

r? @wesleywiser
This commit is contained in:
Dylan DPC 2020-02-10 17:28:57 +01:00 committed by GitHub
commit 24260e5bae
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
8 changed files with 169 additions and 118 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
src/librustc/ty/query/on_disk_cache.rs
View File

@ -1053,8 +1053,10 @@ where
Q: super::config::QueryDescription<'tcx, Value: Encodable>, Q: super::config::QueryDescription<'tcx, Value: Encodable>,
E: 'a + TyEncoder, E: 'a + TyEncoder,
{ {
let desc = &format!("encode_query_results_for_{}", ::std::any::type_name::<Q>()); let _timer = tcx
let _timer = tcx.sess.prof.extra_verbose_generic_activity(desc); .sess
.prof
.extra_verbose_generic_activity("encode_query_results_for", ::std::any::type_name::<Q>());
let shards = Q::query_cache(tcx).lock_shards(); let shards = Q::query_cache(tcx).lock_shards();
assert!(shards.iter().all(|shard| shard.active.is_empty())); assert!(shards.iter().all(|shard| shard.active.is_empty()));

57
src/librustc_codegen_llvm/back/lto.rs
View File

@ -110,23 +110,21 @@ fn prepare_lto(
symbol_white_list.extend(exported_symbols[&cnum].iter().filter_map(symbol_filter)); 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 archive = ArchiveRO::open(&path).expect("wanted an rlib");
let bytecodes = archive let bytecodes = archive
.iter() .iter()
.filter_map(|child| child.ok().and_then(|c| c.name().map(|name| (name, c)))) .filter_map(|child| child.ok().and_then(|c| c.name().map(|name| (name, c))))
.filter(|&(name, _)| name.ends_with(RLIB_BYTECODE_EXTENSION)); .filter(|&(name, _)| name.ends_with(RLIB_BYTECODE_EXTENSION));
for (name, data) in bytecodes { for (name, data) in bytecodes {
let _timer =
cgcx.prof.generic_activity_with_arg("LLVM_lto_load_upstream_bitcode", name);
info!("adding bytecode {}", name); info!("adding bytecode {}", name);
let bc_encoded = data.data(); let bc_encoded = data.data();
let (bc, id) = cgcx let (bc, id) = match DecodedBytecode::new(bc_encoded) {
.prof Ok(b) => Ok((b.bytecode(), b.identifier().to_string())),
.extra_verbose_generic_activity(&format!("decode {}", name)) Err(e) => Err(diag_handler.fatal(&e)),
.run(|| 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); let bc = SerializedModule::FromRlib(bc);
upstream_modules.push((bc, CString::new(id).unwrap())); upstream_modules.push((bc, CString::new(id).unwrap()));
} }
@ -281,14 +279,14 @@ fn fat_lto(
// save and persist everything with the original module. // save and persist everything with the original module.
let mut linker = Linker::new(llmod); let mut linker = Linker::new(llmod);
for (bc_decoded, name) in serialized_modules { 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); info!("linking {:?}", name);
cgcx.prof.extra_verbose_generic_activity(&format!("ll link {:?}", name)).run(|| { let data = bc_decoded.data();
let data = bc_decoded.data(); linker.add(&data).map_err(|()| {
linker.add(&data).map_err(|()| { let msg = format!("failed to load bc of {:?}", name);
let msg = format!("failed to load bc of {:?}", name); write::llvm_err(&diag_handler, &msg)
write::llvm_err(&diag_handler, &msg)
})
})?; })?;
serialized_bitcode.push(bc_decoded); serialized_bitcode.push(bc_decoded);
} }
@ -577,6 +575,8 @@ pub(crate) fn run_pass_manager(
config: &ModuleConfig, config: &ModuleConfig,
thin: bool, 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 // Now we have one massive module inside of llmod. Time to run the
// LTO-specific optimization passes that LLVM provides. // LTO-specific optimization passes that LLVM provides.
// //
@ -634,9 +634,7 @@ pub(crate) fn run_pass_manager(
llvm::LLVMRustAddPass(pm, pass.unwrap()); llvm::LLVMRustAddPass(pm, pass.unwrap());
} }
cgcx.prof llvm::LLVMRunPassManager(pm, module.module_llvm.llmod());
.extra_verbose_generic_activity("LTO_passes")
.run(|| llvm::LLVMRunPassManager(pm, module.module_llvm.llmod()));
llvm::LLVMDisposePassManager(pm); llvm::LLVMDisposePassManager(pm);
} }
@ -760,7 +758,9 @@ pub unsafe fn optimize_thin_module(
// Like with "fat" LTO, get some better optimizations if landing pads // Like with "fat" LTO, get some better optimizations if landing pads
// are disabled by removing all landing pads. // are disabled by removing all landing pads.
if cgcx.no_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); llvm::LLVMRustMarkAllFunctionsNounwind(llmod);
save_temp_bitcode(&cgcx, &module, "thin-lto-after-nounwind"); 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 // You can find some more comments about these functions in the LLVM
// bindings we've got (currently `PassWrapper.cpp`) // 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) { if !llvm::LLVMRustPrepareThinLTORename(thin_module.shared.data.0, llmod) {
let msg = "failed to prepare thin LTO module"; let msg = "failed to prepare thin LTO module";
return Err(write::llvm_err(&diag_handler, msg)); 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) { if !llvm::LLVMRustPrepareThinLTOResolveWeak(thin_module.shared.data.0, llmod) {
let msg = "failed to prepare thin LTO module"; let msg = "failed to prepare thin LTO module";
return Err(write::llvm_err(&diag_handler, msg)); 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) { if !llvm::LLVMRustPrepareThinLTOInternalize(thin_module.shared.data.0, llmod) {
let msg = "failed to prepare thin LTO module"; let msg = "failed to prepare thin LTO module";
return Err(write::llvm_err(&diag_handler, msg)); 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) { if !llvm::LLVMRustPrepareThinLTOImport(thin_module.shared.data.0, llmod) {
let msg = "failed to prepare thin LTO module"; let msg = "failed to prepare thin LTO module";
return Err(write::llvm_err(&diag_handler, msg)); 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 // so it appears). Hopefully we can remove this once upstream bugs are
// fixed in LLVM. // 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); llvm::LLVMRustThinLTOPatchDICompileUnit(llmod, cu1);
save_temp_bitcode(cgcx, &module, "thin-lto-after-patch"); 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 // populate a thin-specific pass manager, which presumably LLVM treats a
// little differently. // little differently.
{ {
let _timer = cgcx.prof.generic_activity("LLVM_thin_lto_optimize");
info!("running thin lto passes over {}", module.name); info!("running thin lto passes over {}", module.name);
let config = cgcx.config(module.kind); let config = cgcx.config(module.kind);
run_pass_manager(cgcx, &module, config, true); run_pass_manager(cgcx, &module, config, true);

69
src/librustc_codegen_llvm/back/write.rs
View File

@ -310,7 +310,7 @@ pub(crate) unsafe fn optimize(
module: &ModuleCodegen<ModuleLlvm>, module: &ModuleCodegen<ModuleLlvm>,
config: &ModuleConfig, config: &ModuleConfig,
) -> Result<(), FatalError> { ) -> 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 llmod = module.module_llvm.llmod();
let llcx = &*module.module_llvm.llcx; let llcx = &*module.module_llvm.llcx;
@ -424,23 +424,17 @@ pub(crate) unsafe fn optimize(
// Finally, run the actual optimization passes // Finally, run the actual optimization passes
{ {
let _timer = cgcx.prof.generic_activity("LLVM_module_optimize_function_passes"); let _timer = cgcx.prof.extra_verbose_generic_activity(
let desc = &format!("llvm function passes [{}]", module_name.unwrap()); "LLVM_module_optimize_function_passes",
let _timer = if config.time_module { &module.name[..],
Some(cgcx.prof.extra_verbose_generic_activity(desc)) );
} else {
None
};
llvm::LLVMRustRunFunctionPassManager(fpm, llmod); llvm::LLVMRustRunFunctionPassManager(fpm, llmod);
} }
{ {
let _timer = cgcx.prof.generic_activity("LLVM_module_optimize_module_passes"); let _timer = cgcx.prof.extra_verbose_generic_activity(
let desc = &format!("llvm module passes [{}]", module_name.unwrap()); "LLVM_module_optimize_module_passes",
let _timer = if config.time_module { &module.name[..],
Some(cgcx.prof.extra_verbose_generic_activity(desc)) );
} else {
None
};
llvm::LLVMRunPassManager(mpm, llmod); llvm::LLVMRunPassManager(mpm, llmod);
} }
@ -480,7 +474,7 @@ pub(crate) unsafe fn codegen(
module: ModuleCodegen<ModuleLlvm>, module: ModuleCodegen<ModuleLlvm>,
config: &ModuleConfig, config: &ModuleConfig,
) -> Result<CompiledModule, FatalError> { ) -> Result<CompiledModule, FatalError> {
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 llmod = module.module_llvm.llmod();
let llcx = &*module.module_llvm.llcx; 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); let obj_out = cgcx.output_filenames.temp_path(OutputType::Object, module_name);
if write_bc || config.emit_bc_compressed || config.embed_bitcode { 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 thin = ThinBuffer::new(llmod);
let data = thin.data(); let data = thin.data();
if write_bc { 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) { if let Err(e) = fs::write(&bc_out, data) {
let msg = format!("failed to write bytecode to {}: {}", bc_out.display(), e); let msg = format!("failed to write bytecode to {}: {}", bc_out.display(), e);
diag_handler.err(&msg); diag_handler.err(&msg);
@ -546,13 +545,18 @@ pub(crate) unsafe fn codegen(
} }
if config.embed_bitcode { 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)); embed_bitcode(cgcx, llcx, llmod, Some(data));
} }
if config.emit_bc_compressed { if config.emit_bc_compressed {
let _timer = let _timer = cgcx.prof.generic_activity_with_arg(
cgcx.prof.generic_activity("LLVM_module_codegen_emit_compressed_bitcode"); "LLVM_module_codegen_emit_compressed_bitcode",
&module.name[..],
);
let dst = bc_out.with_extension(RLIB_BYTECODE_EXTENSION); let dst = bc_out.with_extension(RLIB_BYTECODE_EXTENSION);
let data = bytecode::encode(&module.name, data); let data = bytecode::encode(&module.name, data);
if let Err(e) = fs::write(&dst, 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 { 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 = cgcx.output_filenames.temp_path(OutputType::LlvmAssembly, module_name);
let out_c = path_to_c_string(&out); let out_c = path_to_c_string(&out);
@ -618,7 +617,9 @@ pub(crate) unsafe fn codegen(
} }
if config.emit_asm || asm_to_obj { 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); 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 // 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 { 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| { with_codegen(tm, llmod, config.no_builtins, |cpm| {
write_output_file( write_output_file(
diag_handler, diag_handler,
@ -650,7 +653,9 @@ pub(crate) unsafe fn codegen(
) )
})?; })?;
} else if asm_to_obj { } 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); let assembly = cgcx.output_filenames.temp_path(OutputType::Assembly, module_name);
run_assembler(cgcx, diag_handler, &assembly, &obj_out); run_assembler(cgcx, diag_handler, &assembly, &obj_out);

2
src/librustc_codegen_ssa/back/link.rs
View File

@ -1648,7 +1648,7 @@ fn add_upstream_rust_crates<'a, B: ArchiveBuilder<'a>>(
let name = cratepath.file_name().unwrap().to_str().unwrap(); let name = cratepath.file_name().unwrap().to_str().unwrap();
let name = &name[3..name.len() - 5]; // chop off lib/.rlib 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 = <B as ArchiveBuilder>::new(sess, &dst, Some(cratepath)); let mut archive = <B as ArchiveBuilder>::new(sess, &dst, Some(cratepath));
archive.update_symbols(); archive.update_symbols();

19
src/librustc_codegen_ssa/back/write.rs
View File

@ -21,6 +21,7 @@ use rustc::session::Session;
use rustc::ty::TyCtxt; use rustc::ty::TyCtxt;
use rustc_data_structures::fx::FxHashMap; use rustc_data_structures::fx::FxHashMap;
use rustc_data_structures::profiling::SelfProfilerRef; use rustc_data_structures::profiling::SelfProfilerRef;
use rustc_data_structures::profiling::TimingGuard;
use rustc_data_structures::profiling::VerboseTimingGuard; use rustc_data_structures::profiling::VerboseTimingGuard;
use rustc_data_structures::svh::Svh; use rustc_data_structures::svh::Svh;
use rustc_data_structures::sync::Lrc; use rustc_data_structures::sync::Lrc;
@ -691,11 +692,17 @@ impl<B: WriteBackendMethods> WorkItem<B> {
} }
} }
fn profiling_event_id(&self) -> &'static str { fn start_profiling<'a>(&self, cgcx: &'a CodegenContext<B>) -> TimingGuard<'a> {
match *self { match *self {
WorkItem::Optimize(_) => "codegen_module_optimize", WorkItem::Optimize(ref m) => {
WorkItem::CopyPostLtoArtifacts(_) => "codegen_copy_artifacts_from_incr_cache", cgcx.prof.generic_activity_with_arg("codegen_module_optimize", &m.name[..])
WorkItem::LTO(_) => "codegen_module_perform_lto", }
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<B: ExtraBackendMethods>(
llvm_start_time: &mut Option<VerboseTimingGuard<'a>>, llvm_start_time: &mut Option<VerboseTimingGuard<'a>>,
) { ) {
if config.time_module && llvm_start_time.is_none() { 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<B: ExtraBackendMethods>(cgcx: CodegenContext<B>, work: WorkItem<B>
// as a diagnostic was already sent off to the main thread - just // as a diagnostic was already sent off to the main thread - just
// surface that there was an error in this worker. // surface that there was an error in this worker.
bomb.result = { 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)) Some(execute_work_item(&cgcx, work))
}; };
}); });

107
src/librustc_data_structures/profiling.rs
View File

@ -83,6 +83,9 @@
use crate::fx::FxHashMap; use crate::fx::FxHashMap;
use std::borrow::Borrow;
use std::collections::hash_map::Entry;
use std::convert::Into;
use std::error::Error; use std::error::Error;
use std::fs; use std::fs;
use std::path::Path; use std::path::Path;
@ -123,11 +126,14 @@ bitflags::bitflags! {
const INCR_CACHE_LOADS = 1 << 4; const INCR_CACHE_LOADS = 1 << 4;
const QUERY_KEYS = 1 << 5; const QUERY_KEYS = 1 << 5;
const FUNCTION_ARGS = 1 << 6;
const DEFAULT = Self::GENERIC_ACTIVITIES.bits | const DEFAULT = Self::GENERIC_ACTIVITIES.bits |
Self::QUERY_PROVIDERS.bits | Self::QUERY_PROVIDERS.bits |
Self::QUERY_BLOCKED.bits | Self::QUERY_BLOCKED.bits |
Self::INCR_CACHE_LOADS.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), ("query-blocked", EventFilter::QUERY_BLOCKED),
("incr-cache-load", EventFilter::INCR_CACHE_LOADS), ("incr-cache-load", EventFilter::INCR_CACHE_LOADS),
("query-keys", EventFilter::QUERY_KEYS), ("query-keys", EventFilter::QUERY_KEYS),
("function-args", EventFilter::FUNCTION_ARGS),
("args", EventFilter::ARGS),
]; ];
/// Something that uniquely identifies a query invocation. /// Something that uniquely identifies a query invocation.
@ -216,43 +224,68 @@ impl SelfProfilerRef {
/// VerboseTimingGuard returned from this call is dropped. In addition to recording /// VerboseTimingGuard returned from this call is dropped. In addition to recording
/// a measureme event, "verbose" generic activities also print a timing entry to /// a measureme event, "verbose" generic activities also print a timing entry to
/// stdout if the compiler is invoked with -Ztime or -Ztime-passes. /// stdout if the compiler is invoked with -Ztime or -Ztime-passes.
#[inline(always)]
pub fn verbose_generic_activity<'a>( pub fn verbose_generic_activity<'a>(
&'a self, &'a self,
event_id: &'static str, event_label: &'static str,
) -> VerboseTimingGuard<'a> { ) -> VerboseTimingGuard<'a> {
VerboseTimingGuard::start( let message =
event_id, if self.print_verbose_generic_activities { Some(event_label.to_owned()) } else { None };
self.print_verbose_generic_activities,
self.generic_activity(event_id), VerboseTimingGuard::start(message, self.generic_activity(event_label))
)
} }
/// Start profiling a extra verbose generic activity. Profiling continues until the /// Start profiling a extra verbose generic activity. Profiling continues until the
/// VerboseTimingGuard returned from this call is dropped. In addition to recording /// VerboseTimingGuard returned from this call is dropped. In addition to recording
/// a measureme event, "extra verbose" generic activities also print a timing entry to /// a measureme event, "extra verbose" generic activities also print a timing entry to
/// stdout if the compiler is invoked with -Ztime-passes. /// stdout if the compiler is invoked with -Ztime-passes.
#[inline(always)] pub fn extra_verbose_generic_activity<'a, A>(
pub fn extra_verbose_generic_activity<'a>(
&'a self, &'a self,
event_id: &'a str, event_label: &'static str,
) -> VerboseTimingGuard<'a> { event_arg: A,
// FIXME: This does not yet emit a measureme event ) -> VerboseTimingGuard<'a>
// because callers encode arguments into `event_id`. where
VerboseTimingGuard::start( A: Borrow<str> + Into<String>,
event_id, {
self.print_extra_verbose_generic_activities, let message = if self.print_extra_verbose_generic_activities {
TimingGuard::none(), 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 /// Start profiling a generic activity. Profiling continues until the
/// TimingGuard returned from this call is dropped. /// TimingGuard returned from this call is dropped.
#[inline(always)] #[inline(always)]
pub fn generic_activity(&self, event_id: &'static str) -> TimingGuard<'_> { pub fn generic_activity(&self, event_label: &'static str) -> TimingGuard<'_> {
self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| { self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
let event_id = profiler.get_or_alloc_cached_string(event_id); let event_label = profiler.get_or_alloc_cached_string(event_label);
let event_id = EventId::from_label(event_id); 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_with_arg<A>(
&self,
event_label: &'static str,
event_arg: A,
) -> TimingGuard<'_>
where
A: Borrow<str> + Into<String>,
{
self.exec(EventFilter::GENERIC_ACTIVITIES, |profiler| {
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) TimingGuard::start(profiler, profiler.generic_activity_event_kind, event_id)
}) })
} }
@ -337,7 +370,7 @@ pub struct SelfProfiler {
profiler: Profiler, profiler: Profiler,
event_filter_mask: EventFilter, event_filter_mask: EventFilter,
string_cache: RwLock<FxHashMap<&'static str, StringId>>, string_cache: RwLock<FxHashMap<String, StringId>>,
query_event_kind: StringId, query_event_kind: StringId,
generic_activity_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 /// Gets a `StringId` for the given string. This method makes sure that
/// any strings going through it will only be allocated once in the /// any strings going through it will only be allocated once in the
/// profiling data. /// profiling data.
pub fn get_or_alloc_cached_string(&self, s: &'static str) -> StringId { pub fn get_or_alloc_cached_string<A>(&self, s: A) -> StringId
where
A: Borrow<str> + Into<String>,
{
// Only acquire a read-lock first since we assume that the string is // Only acquire a read-lock first since we assume that the string is
// already present in the common case. // already present in the common case.
{ {
let string_cache = self.string_cache.read(); 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; return id;
} }
} }
@ -433,7 +469,13 @@ impl SelfProfiler {
let mut string_cache = self.string_cache.write(); let mut string_cache = self.string_cache.write();
// Check if the string has already been added in the small time window // Check if the string has already been added in the small time window
// between dropping the read lock and acquiring the write lock. // 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) { pub fn map_query_invocation_id_to_string(&self, from: QueryInvocationId, to: StringId) {
@ -498,18 +540,13 @@ impl<'a> TimingGuard<'a> {
#[must_use] #[must_use]
pub struct VerboseTimingGuard<'a> { pub struct VerboseTimingGuard<'a> {
event_id: &'a str, start_and_message: Option<(Instant, String)>,
start: Option<Instant>,
_guard: TimingGuard<'a>, _guard: TimingGuard<'a>,
} }
impl<'a> VerboseTimingGuard<'a> { impl<'a> VerboseTimingGuard<'a> {
pub fn start(event_id: &'a str, verbose: bool, _guard: TimingGuard<'a>) -> Self { pub fn start(message: Option<String>, _guard: TimingGuard<'a>) -> Self {
VerboseTimingGuard { VerboseTimingGuard { _guard, start_and_message: message.map(|msg| (Instant::now(), msg)) }
event_id,
_guard,
start: if unlikely!(verbose) { Some(Instant::now()) } else { None },
}
} }
#[inline(always)] #[inline(always)]
@ -521,7 +558,9 @@ impl<'a> VerboseTimingGuard<'a> {
impl Drop for VerboseTimingGuard<'_> { impl Drop for VerboseTimingGuard<'_> {
fn drop(&mut self) { 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());
}
} }
} }

6
src/librustc_lint/early.rs
View File

@ -342,10 +342,8 @@ pub fn check_ast_crate<T: EarlyLintPass>(
} }
} else { } else {
for pass in &mut passes { for pass in &mut passes {
buffered = sess buffered =
.prof sess.prof.extra_verbose_generic_activity("run_lint", pass.name()).run(|| {
.extra_verbose_generic_activity(&format!("running lint: {}", pass.name()))
.run(|| {
early_lint_crate( early_lint_crate(
sess, sess,
lint_store, lint_store,

21
src/librustc_lint/late.rs
View File

@ -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); late_lint_pass_crate(tcx, builtin_lints);
} else { } else {
for pass in &mut passes { for pass in &mut passes {
tcx.sess tcx.sess.prof.extra_verbose_generic_activity("run_late_lint", pass.name()).run(|| {
.prof late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) });
.extra_verbose_generic_activity(&format!("running late lint: {}", pass.name())) });
.run(|| {
late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) });
});
} }
let mut passes: Vec<_> = let mut passes: Vec<_> =
unerased_lint_store(tcx).late_module_passes.iter().map(|pass| (pass)()).collect(); unerased_lint_store(tcx).late_module_passes.iter().map(|pass| (pass)()).collect();
for pass in &mut passes { for pass in &mut passes {
tcx.sess tcx.sess.prof.extra_verbose_generic_activity("run_late_module_lint", pass.name()).run(
.prof || {
.extra_verbose_generic_activity(&format!(
"running late module lint: {}",
pass.name()
))
.run(|| {
late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) }); late_lint_pass_crate(tcx, LateLintPassObjects { lints: slice::from_mut(pass) });
}); },
);
} }
} }
} }