Skip to content

Commit

Permalink
Basic profiling
Browse files Browse the repository at this point in the history
  • Loading branch information
wesleywiser committed Aug 2, 2018
1 parent 40cb447 commit 45482c6
Show file tree
Hide file tree
Showing 11 changed files with 259 additions and 1 deletion.
1 change: 1 addition & 0 deletions src/librustc/lib.rs
Expand Up @@ -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
Expand Down
4 changes: 3 additions & 1 deletion src/librustc/session/config.rs
Expand Up @@ -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
Expand Down Expand Up @@ -1367,6 +1367,8 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options,
"disables the 'leak check' for subtyping; unsound, but useful for tests"),
crate_attr: Vec<String> = (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 {
Expand Down
15 changes: 15 additions & 0 deletions src/librustc/session/mod.rs
Expand Up @@ -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};
Expand Down Expand Up @@ -133,6 +134,9 @@ pub struct Session {
/// Used by -Z profile-queries in util::common
pub profile_channel: Lock<Option<mpsc::Sender<ProfileQueriesMsg>>>,

/// Used by -Z self-profile
pub self_profiling: Lock<SelfProfiler>,

/// Some measurements that are being gathered during compilation.
pub perf_stats: PerfStats,

Expand Down Expand Up @@ -825,6 +829,16 @@ impl Session {
}
}

pub fn profiler<F: FnOnce(&mut SelfProfiler) -> ()>(&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: {}",
Expand Down Expand Up @@ -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)),
Expand Down
2 changes: 2 additions & 0 deletions src/librustc/ty/query/config.rs
Expand Up @@ -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;
Expand All @@ -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<StableHashingContext<'a>>;
Expand Down
1 change: 1 addition & 0 deletions src/librustc/ty/query/mod.rs
Expand Up @@ -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;
Expand Down
8 changes: 8 additions & 0 deletions src/librustc/ty/query/plumbing.rs
Expand Up @@ -379,13 +379,15 @@ 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, || {
Q::compute(tcx.global_tcx(), key)
})
});

self.sess.profiler(|p| p.end_activity(Q::CATEGORY));
profq_msg!(self, ProfileQueriesMsg::ProviderEnd);
let ((result, dep_node_index), diagnostics) = res;

Expand Down Expand Up @@ -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,
Expand All @@ -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;
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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> {
Expand Down
207 changes: 207 additions & 0 deletions 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 <LICENSE-APACHE or
// http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
// <LICENSE-MIT or http://opensource.org/licenses/MIT>, 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<T> {
parsing: T,
expansion: T,
type_checking: T,
borrow_checking: T,
codegen: T,
linking: T,
other: T,
}

impl<T: Default> Categories<T> {
fn new() -> Categories<T> {
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<T> Categories<T> {
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<u64>,
}

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<ProfileCategory>,
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)
}
}
3 changes: 3 additions & 0 deletions src/librustc_codegen_llvm/base.rs
Expand Up @@ -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;
Expand Down Expand Up @@ -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(),
Expand Down
3 changes: 3 additions & 0 deletions src/librustc_codegen_llvm/lib.rs
Expand Up @@ -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;

Expand Down Expand Up @@ -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)
Expand Down

0 comments on commit 45482c6

Please sign in to comment.