diff --git a/src/librustc/lib.rs b/src/librustc/lib.rs index 8e71df3c34b0b..bac511aac1fe1 100644 --- a/src/librustc/lib.rs +++ b/src/librustc/lib.rs @@ -165,6 +165,7 @@ pub mod util { pub mod nodemap; pub mod fs; pub mod time_graph; + pub mod profiling; } // A private module so that macro-expanded idents like diff --git a/src/librustc/session/config.rs b/src/librustc/session/config.rs index e0532a3320bc4..dda4a2d2418d7 100644 --- a/src/librustc/session/config.rs +++ b/src/librustc/session/config.rs @@ -65,7 +65,7 @@ pub enum Sanitizer { Thread, } -#[derive(Clone, Copy, PartialEq, Hash)] +#[derive(Clone, Copy, Debug, PartialEq, Hash)] pub enum OptLevel { No, // -O0 Less, // -O1 @@ -1367,6 +1367,10 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options, "disables the 'leak check' for subtyping; unsound, but useful for tests"), crate_attr: Vec = (Vec::new(), parse_string_push, [TRACKED], "inject the given attribute in the crate"), + self_profile: bool = (false, parse_bool, [UNTRACKED], + "run the self profiler"), + profile_json: bool = (false, parse_bool, [UNTRACKED], + "output a json file with profiler results"), } pub fn default_lib_output() -> CrateType { diff --git a/src/librustc/session/mod.rs b/src/librustc/session/mod.rs index 7b8bbbf4a10e0..0ab482c89a125 100644 --- a/src/librustc/session/mod.rs +++ b/src/librustc/session/mod.rs @@ -40,6 +40,7 @@ use syntax::parse::ParseSess; use syntax::{ast, codemap}; use syntax::feature_gate::AttributeType; use syntax_pos::{MultiSpan, Span}; +use util::profiling::SelfProfiler; use rustc_target::spec::{LinkerFlavor, PanicStrategy}; use rustc_target::spec::{Target, TargetTriple}; @@ -133,6 +134,9 @@ pub struct Session { /// Used by -Z profile-queries in util::common pub profile_channel: Lock>>, + /// Used by -Z self-profile + pub self_profiling: Lock, + /// Some measurements that are being gathered during compilation. pub perf_stats: PerfStats, @@ -825,6 +829,21 @@ impl Session { } } + pub fn profiler ()>(&self, f: F) { + let mut profiler = self.self_profiling.borrow_mut(); + f(&mut profiler); + } + + pub fn print_profiler_results(&self) { + let mut profiler = self.self_profiling.borrow_mut(); + profiler.print_results(&self.opts); + } + + pub fn save_json_results(&self) { + let profiler = self.self_profiling.borrow(); + profiler.save_results(&self.opts); + } + pub fn print_perf_stats(&self) { println!( "Total time spent computing symbol hashes: {}", @@ -1125,6 +1144,7 @@ pub fn build_session_( imported_macro_spans: OneThread::new(RefCell::new(HashMap::new())), incr_comp_session: OneThread::new(RefCell::new(IncrCompSession::NotInitialized)), ignored_attr_names: ich::compute_ignored_attr_names(), + self_profiling: Lock::new(SelfProfiler::new()), profile_channel: Lock::new(None), perf_stats: PerfStats { symbol_hash_time: Lock::new(Duration::from_secs(0)), diff --git a/src/librustc/ty/query/config.rs b/src/librustc/ty/query/config.rs index fedf090b9e915..d2648cad55ee9 100644 --- a/src/librustc/ty/query/config.rs +++ b/src/librustc/ty/query/config.rs @@ -21,6 +21,7 @@ use ty::subst::Substs; use ty::query::queries; use ty::query::Query; use ty::query::QueryCache; +use util::profiling::ProfileCategory; use std::hash::Hash; use std::fmt::Debug; @@ -33,6 +34,7 @@ use ich::StableHashingContext; pub trait QueryConfig<'tcx> { const NAME: &'static str; + const CATEGORY: ProfileCategory; type Key: Eq + Hash + Clone + Debug; type Value: Clone + for<'a> HashStable>; diff --git a/src/librustc/ty/query/mod.rs b/src/librustc/ty/query/mod.rs index 1b1020c9bd86d..ab9bdd82e01eb 100644 --- a/src/librustc/ty/query/mod.rs +++ b/src/librustc/ty/query/mod.rs @@ -46,6 +46,7 @@ use ty::steal::Steal; use ty::subst::Substs; use util::nodemap::{DefIdSet, DefIdMap, ItemLocalSet}; use util::common::{ErrorReported}; +use util::profiling::ProfileCategory::*; use rustc_data_structures::indexed_set::IdxSetBuf; use rustc_target::spec::PanicStrategy; diff --git a/src/librustc/ty/query/plumbing.rs b/src/librustc/ty/query/plumbing.rs index 7a9827b50a176..0fa643d796e0e 100644 --- a/src/librustc/ty/query/plumbing.rs +++ b/src/librustc/ty/query/plumbing.rs @@ -118,6 +118,11 @@ impl<'a, 'tcx, Q: QueryDescription<'tcx>> JobOwner<'a, 'tcx, Q> { let mut lock = cache.borrow_mut(); if let Some(value) = lock.results.get(key) { profq_msg!(tcx, ProfileQueriesMsg::CacheHit); + tcx.sess.profiler(|p| { + p.record_query(Q::CATEGORY); + p.record_query_hit(Q::CATEGORY); + }); + let result = Ok((value.value.clone(), value.index)); return TryGetJob::JobCompleted(result); } @@ -358,10 +363,13 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { ) ); + self.sess.profiler(|p| p.record_query(Q::CATEGORY)); + let job = match JobOwner::try_get(self, span, &key) { TryGetJob::NotYetStarted(job) => job, TryGetJob::JobCompleted(result) => { return result.map(|(v, index)| { + self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY)); self.dep_graph.read_index(index); v }) @@ -379,6 +387,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { if dep_node.kind.is_anon() { profq_msg!(self, ProfileQueriesMsg::ProviderBegin); + self.sess.profiler(|p| p.start_activity(Q::CATEGORY)); let res = job.start(self, |tcx| { tcx.dep_graph.with_anon_task(dep_node.kind, || { @@ -386,6 +395,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { }) }); + self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); profq_msg!(self, ProfileQueriesMsg::ProviderEnd); let ((result, dep_node_index), diagnostics) = res; @@ -402,6 +412,8 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { if !dep_node.kind.is_input() { if let Some(dep_node_index) = self.try_mark_green_and_read(&dep_node) { profq_msg!(self, ProfileQueriesMsg::CacheHit); + self.sess.profiler(|p| p.record_query_hit(Q::CATEGORY)); + return self.load_from_disk_and_cache_in_memory::(key, job, dep_node_index, @@ -523,6 +535,11 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { key, dep_node); profq_msg!(self, ProfileQueriesMsg::ProviderBegin); + self.sess.profiler(|p| { + p.start_activity(Q::CATEGORY); + p.record_query(Q::CATEGORY); + }); + let res = job.start(self, |tcx| { if dep_node.kind.is_eval_always() { tcx.dep_graph.with_eval_always_task(dep_node, @@ -536,6 +553,8 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { Q::compute) } }); + + self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); profq_msg!(self, ProfileQueriesMsg::ProviderEnd); let ((result, dep_node_index), diagnostics) = res; @@ -574,7 +593,15 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { // DepNodeIndex. We must invoke the query itself. The performance cost // this introduces should be negligible as we'll immediately hit the // in-memory cache, or another query down the line will. + + self.sess.profiler(|p| { + p.start_activity(Q::CATEGORY); + p.record_query(Q::CATEGORY); + }); + let _ = self.get_query::(DUMMY_SP, key); + + self.sess.profiler(|p| p.end_activity(Q::CATEGORY)); } } @@ -655,6 +682,7 @@ macro_rules! define_queries_inner { rustc_data_structures::stable_hasher::StableHasher, ich::StableHashingContext }; + use util::profiling::ProfileCategory; define_queries_struct! { tcx: $tcx, @@ -768,6 +796,7 @@ macro_rules! define_queries_inner { type Value = $V; const NAME: &'static str = stringify!($name); + const CATEGORY: ProfileCategory = $category; } impl<$tcx> QueryAccessors<$tcx> for queries::$name<$tcx> { diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs new file mode 100644 index 0000000000000..447b75e547f01 --- /dev/null +++ b/src/librustc/util/profiling.rs @@ -0,0 +1,248 @@ +// Copyright 2018 The Rust Project Developers. See the COPYRIGHT +// file at the top-level directory of this distribution and at +// http://rust-lang.org/COPYRIGHT. +// +// Licensed under the Apache License, Version 2.0 or the MIT license +// , at your +// option. This file may not be copied, modified, or distributed +// except according to those terms. + +use session::config::Options; + +use std::fs; +use std::io::{self, StdoutLock, Write}; +use std::time::Instant; + +macro_rules! define_categories { + ($($name:ident,)*) => { + #[derive(Clone, Copy, Debug, PartialEq, Eq)] + pub enum ProfileCategory { + $($name),* + } + + #[allow(bad_style)] + struct Categories { + $($name: T),* + } + + impl Categories { + fn new() -> Categories { + Categories { + $($name: T::default()),* + } + } + } + + impl Categories { + fn get(&self, category: ProfileCategory) -> &T { + match category { + $(ProfileCategory::$name => &self.$name),* + } + } + + fn set(&mut self, category: ProfileCategory, value: T) { + match category { + $(ProfileCategory::$name => self.$name = value),* + } + } + } + + struct CategoryData { + times: Categories, + query_counts: Categories<(u64, u64)>, + } + + impl CategoryData { + fn new() -> CategoryData { + CategoryData { + times: Categories::new(), + query_counts: Categories::new(), + } + } + + fn print(&self, lock: &mut StdoutLock) { + writeln!(lock, "| Phase | Time (ms) | Queries | Hits (%) |") + .unwrap(); + writeln!(lock, "| ---------------- | -------------- | -------------- | -------- |") + .unwrap(); + + $( + let (hits, total) = self.query_counts.$name; + let (hits, total) = if total > 0 { + (format!("{:.2}", + (((hits as f32) / (total as f32)) * 100.0)), total.to_string()) + } else { + ("".into(), "".into()) + }; + + writeln!( + lock, + "| {0: <16} | {1: <14} | {2: <14} | {3: <8} |", + stringify!($name), + self.times.$name / 1_000_000, + total, + hits + ).unwrap(); + )* + } + + fn json(&self) -> String { + let mut json = String::from("["); + + $( + let (hits, total) = self.query_counts.$name; + + json.push_str(&format!( + "{{ \"category\": {}, \"time_ms\": {}, + \"query_count\": {}, \"query_hits\": {} }}", + stringify!($name), + self.times.$name / 1_000_000, + total, + format!("{:.2}", (((hits as f32) / (total as f32)) * 100.0)) + )); + )* + + json.push(']'); + + json + } + } + } +} + +define_categories! { + Parsing, + Expansion, + TypeChecking, + BorrowChecking, + Codegen, + Linking, + Other, +} + +pub struct SelfProfiler { + timer_stack: Vec, + data: CategoryData, + current_timer: Instant, +} + +impl SelfProfiler { + pub fn new() -> SelfProfiler { + let mut profiler = SelfProfiler { + timer_stack: Vec::new(), + data: CategoryData::new(), + current_timer: Instant::now(), + }; + + profiler.start_activity(ProfileCategory::Other); + + profiler + } + + pub fn start_activity(&mut self, category: ProfileCategory) { + match self.timer_stack.last().cloned() { + None => { + self.current_timer = Instant::now(); + }, + Some(current_category) if current_category == category => { + //since the current category is the same as the new activity's category, + //we don't need to do anything with the timer, we just need to push it on the stack + } + Some(current_category) => { + let elapsed = self.stop_timer(); + + //record the current category's time + let new_time = self.data.times.get(current_category) + elapsed; + self.data.times.set(current_category, new_time); + } + } + + //push the new category + self.timer_stack.push(category); + } + + pub fn record_query(&mut self, category: ProfileCategory) { + let (hits, total) = *self.data.query_counts.get(category); + self.data.query_counts.set(category, (hits, total + 1)); + } + + pub fn record_query_hit(&mut self, category: ProfileCategory) { + let (hits, total) = *self.data.query_counts.get(category); + self.data.query_counts.set(category, (hits + 1, total)); + } + + pub fn end_activity(&mut self, category: ProfileCategory) { + match self.timer_stack.pop() { + None => bug!("end_activity() was called but there was no running activity"), + Some(c) => + assert!( + c == category, + "end_activity() was called but a different activity was running"), + } + + //check if the new running timer is in the same category as this one + //if it is, we don't need to do anything + if let Some(c) = self.timer_stack.last() { + if *c == category { + return; + } + } + + //the new timer is different than the previous, + //so record the elapsed time and start a new timer + let elapsed = self.stop_timer(); + let new_time = self.data.times.get(category) + elapsed; + self.data.times.set(category, new_time); + } + + fn stop_timer(&mut self) -> u64 { + let elapsed = self.current_timer.elapsed(); + + self.current_timer = Instant::now(); + + (elapsed.as_secs() * 1_000_000_000) + (elapsed.subsec_nanos() as u64) + } + + pub fn print_results(&mut self, opts: &Options) { + self.end_activity(ProfileCategory::Other); + + assert!( + self.timer_stack.is_empty(), + "there were timers running when print_results() was called"); + + let out = io::stdout(); + let mut lock = out.lock(); + + let crate_name = + opts.crate_name + .as_ref() + .map(|n| format!(" for {}", n)) + .unwrap_or_default(); + + writeln!(lock, "Self profiling results{}:", crate_name).unwrap(); + writeln!(lock).unwrap(); + + self.data.print(&mut lock); + + writeln!(lock).unwrap(); + writeln!(lock, "Optimization level: {:?}", opts.optimize).unwrap(); + + let incremental = if opts.incremental.is_some() { "on" } else { "off" }; + writeln!(lock, "Incremental: {}", incremental).unwrap(); + } + + pub fn save_results(&self, opts: &Options) { + let category_data = self.data.json(); + let compilation_options = + format!("{{ \"optimization_level\": \"{:?}\", \"incremental\": {} }}", + opts.optimize, + if opts.incremental.is_some() { "true" } else { "false" }); + + let json = format!("{{ \"category_data\": {}, \"compilation_options\": {} }}", + category_data, + compilation_options); + + fs::write("self_profiler_results.json", json).unwrap(); + } +} diff --git a/src/librustc_codegen_llvm/base.rs b/src/librustc_codegen_llvm/base.rs index 8278b443a4c83..34cd3998f83cc 100644 --- a/src/librustc_codegen_llvm/base.rs +++ b/src/librustc_codegen_llvm/base.rs @@ -45,6 +45,7 @@ use rustc::dep_graph::{DepNode, DepConstructor}; use rustc::middle::cstore::{self, LinkMeta, LinkagePreference}; use rustc::middle::exported_symbols; use rustc::util::common::{time, print_time_passes_entry}; +use rustc::util::profiling::ProfileCategory; use rustc::session::config::{self, NoDebugInfo}; use rustc::session::Session; use rustc_incremental; @@ -741,11 +742,13 @@ pub fn codegen_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>, let link_meta = link::build_link_meta(crate_hash); // Codegen the metadata. + tcx.sess.profiler(|p| p.start_activity(ProfileCategory::Codegen)); let llmod_id = "metadata"; let metadata_llvm_module = ModuleLlvm::new(tcx.sess, llmod_id); let metadata = time(tcx.sess, "write metadata", || { write_metadata(tcx, &metadata_llvm_module, &link_meta) }); + tcx.sess.profiler(|p| p.end_activity(ProfileCategory::Codegen)); let metadata_module = ModuleCodegen { name: link::METADATA_MODULE_NAME.to_string(), diff --git a/src/librustc_codegen_llvm/lib.rs b/src/librustc_codegen_llvm/lib.rs index 724a2e3e65f42..c01ef37d1b8cc 100644 --- a/src/librustc_codegen_llvm/lib.rs +++ b/src/librustc_codegen_llvm/lib.rs @@ -84,6 +84,7 @@ use rustc::session::config::{OutputFilenames, OutputType, PrintRequest}; use rustc::ty::{self, TyCtxt}; use rustc::util::time_graph; use rustc::util::nodemap::{FxHashSet, FxHashMap}; +use rustc::util::profiling::ProfileCategory; use rustc_mir::monomorphize; use rustc_codegen_utils::codegen_backend::CodegenBackend; @@ -240,10 +241,12 @@ impl CodegenBackend for LlvmCodegenBackend { // Run the linker on any artifacts that resulted from the LLVM run. // This should produce either a finished executable or library. + sess.profiler(|p| p.start_activity(ProfileCategory::Linking)); time(sess, "linking", || { back::link::link_binary(sess, &ongoing_codegen, outputs, &ongoing_codegen.crate_name.as_str()); }); + sess.profiler(|p| p.end_activity(ProfileCategory::Linking)); // Now that we won't touch anything in the incremental compilation directory // any more, we can finalize it (which involves renaming it) diff --git a/src/librustc_driver/driver.rs b/src/librustc_driver/driver.rs index 24a2354775cb5..f178f847aa51e 100644 --- a/src/librustc_driver/driver.rs +++ b/src/librustc_driver/driver.rs @@ -25,6 +25,7 @@ use rustc::middle::privacy::AccessLevels; use rustc::ty::{self, AllArenas, Resolutions, TyCtxt}; use rustc::traits; use rustc::util::common::{install_panic_hook, time, ErrorReported}; +use rustc::util::profiling::ProfileCategory; use rustc_allocator as allocator; use rustc_borrowck as borrowck; use rustc_incremental; @@ -352,6 +353,14 @@ pub fn compile_input( sess.print_perf_stats(); } + if sess.opts.debugging_opts.self_profile { + sess.print_profiler_results(); + + if sess.opts.debugging_opts.profile_json { + sess.save_json_results(); + } + } + controller_entry_point!( compilation_done, sess, @@ -667,6 +676,7 @@ pub fn phase_1_parse_input<'a>( profile::begin(sess); } + sess.profiler(|p| p.start_activity(ProfileCategory::Parsing)); let krate = time(sess, "parsing", || match *input { Input::File(ref file) => parse::parse_crate_from_file(file, &sess.parse_sess), Input::Str { @@ -674,6 +684,7 @@ pub fn phase_1_parse_input<'a>( ref name, } => parse::parse_crate_from_source_str(name.clone(), input.clone(), &sess.parse_sess), })?; + sess.profiler(|p| p.end_activity(ProfileCategory::Parsing)); sess.diagnostic().set_continue_after_error(true); @@ -944,6 +955,7 @@ where syntax_ext::register_builtins(&mut resolver, syntax_exts, sess.features_untracked().quote); // Expand all macros + sess.profiler(|p| p.start_activity(ProfileCategory::Expansion)); krate = time(sess, "expansion", || { // Windows dlls do not have rpaths, so they don't know how to find their // dependencies. It's up to us to tell the system where to find all the @@ -1021,6 +1033,7 @@ where } krate }); + sess.profiler(|p| p.end_activity(ProfileCategory::Expansion)); krate = time(sess, "maybe building test harness", || { syntax::test::modify_for_testing( @@ -1350,7 +1363,9 @@ pub fn phase_4_codegen<'a, 'tcx>( ::rustc::middle::dependency_format::calculate(tcx) }); + tcx.sess.profiler(|p| p.start_activity(ProfileCategory::Codegen)); let codegen = time(tcx.sess, "codegen", move || codegen_backend.codegen_crate(tcx, rx)); + tcx.sess.profiler(|p| p.end_activity(ProfileCategory::Codegen)); if tcx.sess.profile_queries() { profile::dump(&tcx.sess, "profile_queries".to_string()) } diff --git a/src/librustc_typeck/lib.rs b/src/librustc_typeck/lib.rs index 0cc1f6333afa0..4f1609455178b 100644 --- a/src/librustc_typeck/lib.rs +++ b/src/librustc_typeck/lib.rs @@ -109,6 +109,7 @@ use rustc::ty::subst::Substs; use rustc::ty::{self, Ty, TyCtxt}; use rustc::ty::query::Providers; use rustc::traits::{ObligationCause, ObligationCauseCode, TraitEngine, TraitEngineExt}; +use rustc::util::profiling::ProfileCategory; use session::{CompileIncomplete, config}; use util::common::time; @@ -334,6 +335,8 @@ pub fn provide(providers: &mut Providers) { pub fn check_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>) -> Result<(), CompileIncomplete> { + tcx.sess.profiler(|p| p.start_activity(ProfileCategory::TypeChecking)); + // this ensures that later parts of type checking can assume that items // have valid types and not error tcx.sess.track_errors(|| { @@ -371,6 +374,8 @@ pub fn check_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>) check_unused::check_crate(tcx); check_for_entry_fn(tcx); + tcx.sess.profiler(|p| p.end_activity(ProfileCategory::TypeChecking)); + tcx.sess.compile_status() }