From 45482c6f994b5fd3b9a10c4d463dd80aa1f72d5c Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Sat, 19 May 2018 13:50:58 -0400 Subject: [PATCH 01/14] Basic profiling --- src/librustc/lib.rs | 1 + src/librustc/session/config.rs | 4 +- src/librustc/session/mod.rs | 15 +++ src/librustc/ty/query/config.rs | 2 + src/librustc/ty/query/mod.rs | 1 + src/librustc/ty/query/plumbing.rs | 8 ++ src/librustc/util/profiling.rs | 207 ++++++++++++++++++++++++++++++ src/librustc_codegen_llvm/base.rs | 3 + src/librustc_codegen_llvm/lib.rs | 3 + src/librustc_driver/driver.rs | 11 ++ src/librustc_typeck/lib.rs | 5 + 11 files changed, 259 insertions(+), 1 deletion(-) create mode 100644 src/librustc/util/profiling.rs 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..cc29bad9cb532 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,8 @@ 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"), } pub fn default_lib_output() -> CrateType { diff --git a/src/librustc/session/mod.rs b/src/librustc/session/mod.rs index 7b8bbbf4a10e0..a321728f74989 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,16 @@ 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 print_perf_stats(&self) { println!( "Total time spent computing symbol hashes: {}", @@ -1125,6 +1139,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..62e69ffee673f 100644 --- a/src/librustc/ty/query/plumbing.rs +++ b/src/librustc/ty/query/plumbing.rs @@ -379,6 +379,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 +387,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; @@ -523,6 +525,8 @@ 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)); + let res = job.start(self, |tcx| { if dep_node.kind.is_eval_always() { tcx.dep_graph.with_eval_always_task(dep_node, @@ -536,6 +540,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; @@ -655,6 +661,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 +775,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..eb20a85ca69f0 --- /dev/null +++ b/src/librustc/util/profiling.rs @@ -0,0 +1,207 @@ +// 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::io::{self, StdoutLock, Write}; +use std::time::Instant; + +#[derive(Clone, Copy, Debug, PartialEq, Eq, Hash)] +pub enum ProfileCategory { + Parsing, + Expansion, + TypeChecking, + BorrowChecking, + Codegen, + Linking, + Other, +} + +struct Categories { + parsing: T, + expansion: T, + type_checking: T, + borrow_checking: T, + codegen: T, + linking: T, + other: T, +} + +impl Categories { + fn new() -> Categories { + Categories { + parsing: T::default(), + expansion: T::default(), + type_checking: T::default(), + borrow_checking: T::default(), + codegen: T::default(), + linking: T::default(), + other: T::default(), + } + } +} + +impl Categories { + fn get(&self, category: ProfileCategory) -> &T { + match category { + ProfileCategory::Parsing => &self.parsing, + ProfileCategory::Expansion => &self.expansion, + ProfileCategory::TypeChecking => &self.type_checking, + ProfileCategory::BorrowChecking => &self.borrow_checking, + ProfileCategory::Codegen => &self.codegen, + ProfileCategory::Linking => &self.linking, + ProfileCategory::Other => &self.other, + } + } + + fn set(&mut self, category: ProfileCategory, value: T) { + match category { + ProfileCategory::Parsing => self.parsing = value, + ProfileCategory::Expansion => self.expansion = value, + ProfileCategory::TypeChecking => self.type_checking = value, + ProfileCategory::BorrowChecking => self.borrow_checking = value, + ProfileCategory::Codegen => self.codegen = value, + ProfileCategory::Linking => self.linking = value, + ProfileCategory::Other => self.other = value, + } + } +} + +struct CategoryData { + times: Categories, +} + +impl CategoryData { + fn new() -> CategoryData { + CategoryData { + times: Categories::new(), + } + } + + fn print(&self, lock: &mut StdoutLock) { + writeln!(lock, "{0: <15} \t\t {1: <15}", "Parsing", self.times.parsing / 1_000_000).unwrap(); + writeln!(lock, "{0: <15} \t\t {1: <15}", "Expansion", self.times.expansion / 1_000_000).unwrap(); + writeln!(lock, "{0: <15} \t\t {1: <15}", "TypeChecking", self.times.type_checking / 1_000_000).unwrap(); + writeln!(lock, "{0: <15} \t\t {1: <15}", "BorrowChecking", self.times.borrow_checking / 1_000_000).unwrap(); + writeln!(lock, "{0: <15} \t\t {1: <15}", "Codegen", self.times.codegen / 1_000_000).unwrap(); + writeln!(lock, "{0: <15} \t\t {1: <15}", "Linking", self.times.linking / 1_000_000).unwrap(); + writeln!(lock, "{0: <15} \t\t {1: <15}", "Other", self.times.other / 1_000_000).unwrap(); + } +} + +pub struct SelfProfiler { + timer_stack: Vec, + data: CategoryData, + current_timer: Instant, +} + +pub struct ProfilerActivity<'a>(ProfileCategory, &'a mut SelfProfiler); + +impl<'a> Drop for ProfilerActivity<'a> { + fn drop(&mut self) { + let ProfilerActivity (category, profiler) = self; + + profiler.end_activity(*category); + } +} + +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 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(); + + 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 record_activity<'a>(&'a mut self, category: ProfileCategory) -> ProfilerActivity<'a> { + self.start_activity(category); + + ProfilerActivity(category, self) + } +} \ No newline at end of file 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..d862741cda54f 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,10 @@ pub fn compile_input( sess.print_perf_stats(); } + if sess.opts.debugging_opts.self_profile { + sess.print_profiler_results(); + } + controller_entry_point!( compilation_done, sess, @@ -667,6 +672,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 +680,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 +951,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 +1029,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 +1359,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() } From 177776d55ed103d39d81b75d8b316291c241d01d Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Tue, 29 May 2018 23:12:49 -0400 Subject: [PATCH 02/14] Basic incremental stats --- src/librustc/ty/query/plumbing.rs | 17 +++++++++-- src/librustc/util/profiling.rs | 47 ++++++++++++++++++++++++++----- 2 files changed, 55 insertions(+), 9 deletions(-) diff --git a/src/librustc/ty/query/plumbing.rs b/src/librustc/ty/query/plumbing.rs index 62e69ffee673f..3a07f4859d2fe 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); } @@ -379,7 +384,10 @@ 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)); + self.sess.profiler(|p| { + p.start_activity(Q::CATEGORY); + p.record_query(Q::CATEGORY); + }); let res = job.start(self, |tcx| { tcx.dep_graph.with_anon_task(dep_node.kind, || { @@ -404,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, @@ -525,7 +535,10 @@ 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)); + 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() { diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index eb20a85ca69f0..d8eb5308ed1ec 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -76,23 +76,46 @@ impl Categories { 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, "{0: <15} \t\t {1: <15}", "Parsing", self.times.parsing / 1_000_000).unwrap(); - writeln!(lock, "{0: <15} \t\t {1: <15}", "Expansion", self.times.expansion / 1_000_000).unwrap(); - writeln!(lock, "{0: <15} \t\t {1: <15}", "TypeChecking", self.times.type_checking / 1_000_000).unwrap(); - writeln!(lock, "{0: <15} \t\t {1: <15}", "BorrowChecking", self.times.borrow_checking / 1_000_000).unwrap(); - writeln!(lock, "{0: <15} \t\t {1: <15}", "Codegen", self.times.codegen / 1_000_000).unwrap(); - writeln!(lock, "{0: <15} \t\t {1: <15}", "Linking", self.times.linking / 1_000_000).unwrap(); - writeln!(lock, "{0: <15} \t\t {1: <15}", "Other", self.times.other / 1_000_000).unwrap(); + macro_rules! p { + ($name:tt, $rustic_name:ident) => { + writeln!( + lock, + "{0: <15} \t\t {1: <15}", + $name, + self.times.$rustic_name / 1_000_000 + ).unwrap(); + + let (hits, total) = self.query_counts.$rustic_name; + if total > 0 { + writeln!( + lock, + "\t{} hits {} queries", + hits, + total + ).unwrap(); + } + }; + } + + p!("Parsing", parsing); + p!("Expansion", expansion); + p!("TypeChecking", type_checking); + p!("BorrowChecking", borrow_checking); + p!("Codegen", codegen); + p!("Linking", linking); + p!("Other", other); } } @@ -147,6 +170,16 @@ impl SelfProfiler { 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"), From aceee88c1add37cf02c1b67ebdd987696d4e6a43 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Wed, 30 May 2018 18:56:36 -0400 Subject: [PATCH 03/14] Add units to times --- src/librustc/util/profiling.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index d8eb5308ed1ec..cf165a2afefa9 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -92,7 +92,7 @@ impl CategoryData { ($name:tt, $rustic_name:ident) => { writeln!( lock, - "{0: <15} \t\t {1: <15}", + "{0: <15} \t\t {1: <15}ms", $name, self.times.$rustic_name / 1_000_000 ).unwrap(); From 0f43800d10efd4e6255d375dad00be6b8ab6b5d7 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Wed, 30 May 2018 23:41:20 -0400 Subject: [PATCH 04/14] Switch to markdown output --- src/librustc/util/profiling.rs | 27 +++++++++++++++------------ 1 file changed, 15 insertions(+), 12 deletions(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index cf165a2afefa9..5bb1ddd669bb0 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -90,25 +90,27 @@ impl CategoryData { fn print(&self, lock: &mut StdoutLock) { macro_rules! p { ($name:tt, $rustic_name:ident) => { + let (hits, total) = self.query_counts.$rustic_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: <15} \t\t {1: <15}ms", + "| {0: <16} | {1: <14} | {2: <14} | {3: <8} |", $name, - self.times.$rustic_name / 1_000_000 + self.times.$rustic_name / 1_000_000, + total, + hits ).unwrap(); - - let (hits, total) = self.query_counts.$rustic_name; - if total > 0 { - writeln!( - lock, - "\t{} hits {} queries", - hits, - total - ).unwrap(); - } }; } + writeln!(lock, "| Phase | Time (ms) | Queries | Hits (%) |").unwrap(); + writeln!(lock, "| ---------------- | -------------- | -------------- | -------- |").unwrap(); + p!("Parsing", parsing); p!("Expansion", expansion); p!("TypeChecking", type_checking); @@ -222,6 +224,7 @@ impl SelfProfiler { 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); From 6a0d37b69c6c32c4dcd2df85f0cd4df156d46b5a Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Mon, 4 Jun 2018 22:43:27 -0400 Subject: [PATCH 05/14] Fix some missed query data --- src/librustc/ty/query/plumbing.rs | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/src/librustc/ty/query/plumbing.rs b/src/librustc/ty/query/plumbing.rs index 3a07f4859d2fe..2b0cdccd51afc 100644 --- a/src/librustc/ty/query/plumbing.rs +++ b/src/librustc/ty/query/plumbing.rs @@ -363,6 +363,8 @@ 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) => { @@ -384,10 +386,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); - p.record_query(Q::CATEGORY); - }); + self.sess.profiler(|p| p.start_activity(Q::CATEGORY)); let res = job.start(self, |tcx| { tcx.dep_graph.with_anon_task(dep_node.kind, || { From d3aa593a6b339ae1475aa50e564e2774057faaa5 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Mon, 4 Jun 2018 23:10:23 -0400 Subject: [PATCH 06/14] Remove redundant s in output --- src/librustc/util/profiling.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index 5bb1ddd669bb0..ef4e233260470 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -92,7 +92,7 @@ impl CategoryData { ($name:tt, $rustic_name:ident) => { let (hits, total) = self.query_counts.$rustic_name; let (hits, total) = if total > 0 { - (format!("{:.2}%", (((hits as f32) / (total as f32)) * 100.0)), total.to_string()) + (format!("{:.2}", (((hits as f32) / (total as f32)) * 100.0)), total.to_string()) } else { ("".into(), "".into()) }; From e50dfe66f3c42bd67c0589b7bbd3307d5e9a1cf7 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Tue, 5 Jun 2018 21:37:31 -0400 Subject: [PATCH 07/14] Fix more missed query data --- src/librustc/ty/query/plumbing.rs | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/src/librustc/ty/query/plumbing.rs b/src/librustc/ty/query/plumbing.rs index 2b0cdccd51afc..0fa643d796e0e 100644 --- a/src/librustc/ty/query/plumbing.rs +++ b/src/librustc/ty/query/plumbing.rs @@ -369,6 +369,7 @@ impl<'a, 'gcx, 'tcx> TyCtxt<'a, 'gcx, 'tcx> { 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 }) @@ -592,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)); } } From 51cc594e106ab5c0452784e543b56d5a0b42cfe7 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Tue, 5 Jun 2018 23:05:30 -0400 Subject: [PATCH 08/14] First pass at json output --- src/librustc/session/config.rs | 2 ++ src/librustc/session/mod.rs | 5 ++++ src/librustc/util/profiling.rs | 45 ++++++++++++++++++++++++++++++++++ src/librustc_driver/driver.rs | 4 +++ 4 files changed, 56 insertions(+) diff --git a/src/librustc/session/config.rs b/src/librustc/session/config.rs index cc29bad9cb532..dda4a2d2418d7 100644 --- a/src/librustc/session/config.rs +++ b/src/librustc/session/config.rs @@ -1369,6 +1369,8 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options, "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 a321728f74989..8bb9f0b92679c 100644 --- a/src/librustc/session/mod.rs +++ b/src/librustc/session/mod.rs @@ -839,6 +839,11 @@ impl Session { profiler.print_results(&self.opts); } + pub fn save_json_results(&self) { + let profiler = self.self_profiling.borrow(); + profiler.save_results(); + } + pub fn print_perf_stats(&self) { println!( "Total time spent computing symbol hashes: {}", diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index ef4e233260470..73604d2a4371a 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -10,6 +10,7 @@ use session::config::Options; +use std::fs; use std::io::{self, StdoutLock, Write}; use std::time::Instant; @@ -119,6 +120,46 @@ impl CategoryData { p!("Linking", linking); p!("Other", other); } + + fn json(&self) -> String { + format!("[ + {{ + \"category\": \"Parsing\", + \"time_ms\": {} + }}, + {{ + \"category\": \"Expansion\", + \"time_ms\": {} + }}, + {{ + \"category\": \"TypeChecking\", + \"time_ms\": {} + }}, + {{ + \"category\": \"BorrowChecking\", + \"time_ms\": {} + }}, + {{ + \"category\": \"Codegen\", + \"time_ms\": {} + }}, + {{ + \"category\": \"Linking\", + \"time_ms\": {} + }}, + {{ + \"category\": \"Other\", + \"time_ms\": {} + }} + ]", + self.times.parsing / 1_000_000, + self.times.expansion / 1_000_000, + self.times.type_checking / 1_000_000, + self.times.borrow_checking / 1_000_000, + self.times.codegen / 1_000_000, + self.times.linking / 1_000_000, + self.times.other / 1_000_000) + } } pub struct SelfProfiler { @@ -235,6 +276,10 @@ impl SelfProfiler { writeln!(lock, "Incremental: {}", incremental).unwrap(); } + pub fn save_results(&self) { + fs::write("self_profiler_results.json", self.data.json()).unwrap(); + } + pub fn record_activity<'a>(&'a mut self, category: ProfileCategory) -> ProfilerActivity<'a> { self.start_activity(category); diff --git a/src/librustc_driver/driver.rs b/src/librustc_driver/driver.rs index d862741cda54f..f178f847aa51e 100644 --- a/src/librustc_driver/driver.rs +++ b/src/librustc_driver/driver.rs @@ -355,6 +355,10 @@ pub fn compile_input( 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!( From 4552607d64669335e12cb4c69e02a759668cba22 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Mon, 11 Jun 2018 23:41:11 -0400 Subject: [PATCH 09/14] Refactor json printing --- src/librustc/util/profiling.rs | 56 +++++++++++++--------------------- 1 file changed, 21 insertions(+), 35 deletions(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index 73604d2a4371a..b32122aad851b 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -122,43 +122,29 @@ impl CategoryData { } fn json(&self) -> String { + macro_rules! j { + ($category:tt, $rustic_name:ident) => { + format!("{{ \"category\": {}, \"time_ms\": {} }}", stringify!($category), self.times.$rustic_name / 1_000_000) + } + } + format!("[ - {{ - \"category\": \"Parsing\", - \"time_ms\": {} - }}, - {{ - \"category\": \"Expansion\", - \"time_ms\": {} - }}, - {{ - \"category\": \"TypeChecking\", - \"time_ms\": {} - }}, - {{ - \"category\": \"BorrowChecking\", - \"time_ms\": {} - }}, - {{ - \"category\": \"Codegen\", - \"time_ms\": {} - }}, - {{ - \"category\": \"Linking\", - \"time_ms\": {} - }}, - {{ - \"category\": \"Other\", - \"time_ms\": {} - }} + {}, + {}, + {}, + {}, + {}, + {}, + {} ]", - self.times.parsing / 1_000_000, - self.times.expansion / 1_000_000, - self.times.type_checking / 1_000_000, - self.times.borrow_checking / 1_000_000, - self.times.codegen / 1_000_000, - self.times.linking / 1_000_000, - self.times.other / 1_000_000) + j!("Parsing", parsing), + j!("Expansion", expansion), + j!("TypeChecking", type_checking), + j!("BorrowChecking", borrow_checking), + j!("Codegen", codegen), + j!("Linking", linking), + j!("Other", other) + ) } } From 579facaba2a11883e24d29c6ac4770942ce3cd50 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Wed, 13 Jun 2018 20:49:22 -0400 Subject: [PATCH 10/14] Include query hits/totals --- src/librustc/util/profiling.rs | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index b32122aad851b..bbb7bd083b0a0 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -123,9 +123,16 @@ impl CategoryData { fn json(&self) -> String { macro_rules! j { - ($category:tt, $rustic_name:ident) => { - format!("{{ \"category\": {}, \"time_ms\": {} }}", stringify!($category), self.times.$rustic_name / 1_000_000) - } + ($category:tt, $rustic_name:ident) => {{ + let (hits, total) = self.query_counts.$rustic_name; + + format!("{{ \"category\": {}, \"time_ms\": {}, \"query_count\": {}, \"query_hits\": {} }}", + stringify!($category), + self.times.$rustic_name / 1_000_000, + total, + format!("{:.2}", (((hits as f32) / (total as f32)) * 100.0)) + ) + }} } format!("[ From 256a6e4fa97b3f4261265c89a29a68c4c5ccb618 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Wed, 13 Jun 2018 22:08:41 -0400 Subject: [PATCH 11/14] Include additional data in the json output --- src/librustc/session/mod.rs | 2 +- src/librustc/util/profiling.rs | 13 +++++++++++-- 2 files changed, 12 insertions(+), 3 deletions(-) diff --git a/src/librustc/session/mod.rs b/src/librustc/session/mod.rs index 8bb9f0b92679c..0ab482c89a125 100644 --- a/src/librustc/session/mod.rs +++ b/src/librustc/session/mod.rs @@ -841,7 +841,7 @@ impl Session { pub fn save_json_results(&self) { let profiler = self.self_profiling.borrow(); - profiler.save_results(); + profiler.save_results(&self.opts); } pub fn print_perf_stats(&self) { diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index bbb7bd083b0a0..6bdc17a74ba46 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -269,8 +269,17 @@ impl SelfProfiler { writeln!(lock, "Incremental: {}", incremental).unwrap(); } - pub fn save_results(&self) { - fs::write("self_profiler_results.json", self.data.json()).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(); } pub fn record_activity<'a>(&'a mut self, category: ProfileCategory) -> ProfilerActivity<'a> { From 97ab37e2dcd85ec42f5b90495340322a16c09102 Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Wed, 20 Jun 2018 07:57:22 -0400 Subject: [PATCH 12/14] Remove some dead code --- src/librustc/util/profiling.rs | 18 +----------------- 1 file changed, 1 insertion(+), 17 deletions(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index 6bdc17a74ba46..951c5277d0d78 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -161,16 +161,6 @@ pub struct SelfProfiler { current_timer: Instant, } -pub struct ProfilerActivity<'a>(ProfileCategory, &'a mut SelfProfiler); - -impl<'a> Drop for ProfilerActivity<'a> { - fn drop(&mut self) { - let ProfilerActivity (category, profiler) = self; - - profiler.end_activity(*category); - } -} - impl SelfProfiler { pub fn new() -> SelfProfiler { let mut profiler = SelfProfiler { @@ -281,10 +271,4 @@ impl SelfProfiler { fs::write("self_profiler_results.json", json).unwrap(); } - - pub fn record_activity<'a>(&'a mut self, category: ProfileCategory) -> ProfilerActivity<'a> { - self.start_activity(category); - - ProfilerActivity(category, self) - } -} \ No newline at end of file +} From 60c2e9a329f3e10fb87927a7af4393ffa9c3aa1e Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Fri, 20 Jul 2018 21:28:37 -0400 Subject: [PATCH 13/14] Fix tidy --- src/librustc/util/profiling.rs | 37 +++++++++++++++++++++++----------- 1 file changed, 25 insertions(+), 12 deletions(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index 951c5277d0d78..ee00673dccdcb 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -93,7 +93,8 @@ impl CategoryData { ($name:tt, $rustic_name:ident) => { let (hits, total) = self.query_counts.$rustic_name; let (hits, total) = if total > 0 { - (format!("{:.2}", (((hits as f32) / (total as f32)) * 100.0)), total.to_string()) + (format!("{:.2}", + (((hits as f32) / (total as f32)) * 100.0)), total.to_string()) } else { ("".into(), "".into()) }; @@ -109,8 +110,10 @@ impl CategoryData { }; } - writeln!(lock, "| Phase | Time (ms) | Queries | Hits (%) |").unwrap(); - writeln!(lock, "| ---------------- | -------------- | -------------- | -------- |").unwrap(); + writeln!(lock, "| Phase | Time (ms) | Queries | Hits (%) |") + .unwrap(); + writeln!(lock, "| ---------------- | -------------- | -------------- | -------- |") + .unwrap(); p!("Parsing", parsing); p!("Expansion", expansion); @@ -126,7 +129,9 @@ impl CategoryData { ($category:tt, $rustic_name:ident) => {{ let (hits, total) = self.query_counts.$rustic_name; - format!("{{ \"category\": {}, \"time_ms\": {}, \"query_count\": {}, \"query_hits\": {} }}", + format!( + "{{ \"category\": {}, \"time_ms\": {}, + \"query_count\": {}, \"query_hits\": {} }}", stringify!($category), self.times.$rustic_name / 1_000_000, total, @@ -209,9 +214,9 @@ impl SelfProfiler { 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) => + Some(c) => assert!( - c == category, + c == category, "end_activity() was called but a different activity was running"), } @@ -223,7 +228,8 @@ impl SelfProfiler { } } - //the new timer is different than the previous, so record the elapsed time and start a new timer + //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); @@ -240,12 +246,18 @@ impl SelfProfiler { 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"); + 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(); + 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(); @@ -261,9 +273,10 @@ impl SelfProfiler { 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 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, From 2d3a0a99279093e024c819dda826626a088bcd7e Mon Sep 17 00:00:00 2001 From: Wesley Wiser Date: Mon, 23 Jul 2018 21:52:39 -0400 Subject: [PATCH 14/14] Generate self-profiler types with macros --- src/librustc/util/profiling.rs | 221 ++++++++++++++------------------- 1 file changed, 91 insertions(+), 130 deletions(-) diff --git a/src/librustc/util/profiling.rs b/src/librustc/util/profiling.rs index ee00673dccdcb..447b75e547f01 100644 --- a/src/librustc/util/profiling.rs +++ b/src/librustc/util/profiling.rs @@ -14,152 +14,113 @@ use std::fs; use std::io::{self, StdoutLock, Write}; use std::time::Instant; -#[derive(Clone, Copy, Debug, PartialEq, Eq, Hash)] -pub enum ProfileCategory { - Parsing, - Expansion, - TypeChecking, - BorrowChecking, - Codegen, - Linking, - Other, -} - -struct Categories { - parsing: T, - expansion: T, - type_checking: T, - borrow_checking: T, - codegen: T, - linking: T, - other: T, -} - -impl Categories { - fn new() -> Categories { - Categories { - parsing: T::default(), - expansion: T::default(), - type_checking: T::default(), - borrow_checking: T::default(), - codegen: T::default(), - linking: T::default(), - other: T::default(), +macro_rules! define_categories { + ($($name:ident,)*) => { + #[derive(Clone, Copy, Debug, PartialEq, Eq)] + pub enum ProfileCategory { + $($name),* } - } -} -impl Categories { - fn get(&self, category: ProfileCategory) -> &T { - match category { - ProfileCategory::Parsing => &self.parsing, - ProfileCategory::Expansion => &self.expansion, - ProfileCategory::TypeChecking => &self.type_checking, - ProfileCategory::BorrowChecking => &self.borrow_checking, - ProfileCategory::Codegen => &self.codegen, - ProfileCategory::Linking => &self.linking, - ProfileCategory::Other => &self.other, + #[allow(bad_style)] + struct Categories { + $($name: T),* } - } - fn set(&mut self, category: ProfileCategory, value: T) { - match category { - ProfileCategory::Parsing => self.parsing = value, - ProfileCategory::Expansion => self.expansion = value, - ProfileCategory::TypeChecking => self.type_checking = value, - ProfileCategory::BorrowChecking => self.borrow_checking = value, - ProfileCategory::Codegen => self.codegen = value, - ProfileCategory::Linking => self.linking = value, - ProfileCategory::Other => self.other = value, + impl Categories { + fn new() -> Categories { + Categories { + $($name: T::default()),* + } + } } - } -} -struct CategoryData { - times: Categories, - query_counts: Categories<(u64, u64)>, -} + impl Categories { + fn get(&self, category: ProfileCategory) -> &T { + match category { + $(ProfileCategory::$name => &self.$name),* + } + } -impl CategoryData { - fn new() -> CategoryData { - CategoryData { - times: Categories::new(), - query_counts: Categories::new(), + fn set(&mut self, category: ProfileCategory, value: T) { + match category { + $(ProfileCategory::$name => self.$name = value),* + } + } } - } - fn print(&self, lock: &mut StdoutLock) { - macro_rules! p { - ($name:tt, $rustic_name:ident) => { - let (hits, total) = self.query_counts.$rustic_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} |", - $name, - self.times.$rustic_name / 1_000_000, - total, - hits - ).unwrap(); - }; + struct CategoryData { + times: Categories, + query_counts: Categories<(u64, u64)>, } - writeln!(lock, "| Phase | Time (ms) | Queries | Hits (%) |") - .unwrap(); - writeln!(lock, "| ---------------- | -------------- | -------------- | -------- |") - .unwrap(); - - p!("Parsing", parsing); - p!("Expansion", expansion); - p!("TypeChecking", type_checking); - p!("BorrowChecking", borrow_checking); - p!("Codegen", codegen); - p!("Linking", linking); - p!("Other", other); - } + impl CategoryData { + fn new() -> CategoryData { + CategoryData { + times: Categories::new(), + query_counts: Categories::new(), + } + } - fn json(&self) -> String { - macro_rules! j { - ($category:tt, $rustic_name:ident) => {{ - let (hits, total) = self.query_counts.$rustic_name; - - format!( - "{{ \"category\": {}, \"time_ms\": {}, - \"query_count\": {}, \"query_hits\": {} }}", - stringify!($category), - self.times.$rustic_name / 1_000_000, - total, - format!("{:.2}", (((hits as f32) / (total as f32)) * 100.0)) - ) - }} - } + 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(); + )* + } - format!("[ - {}, - {}, - {}, - {}, - {}, - {}, - {} - ]", - j!("Parsing", parsing), - j!("Expansion", expansion), - j!("TypeChecking", type_checking), - j!("BorrowChecking", borrow_checking), - j!("Codegen", codegen), - j!("Linking", linking), - j!("Other", other) - ) + 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,