From 88192785233d0fed6cc8702e3067f02208e62a14 Mon Sep 17 00:00:00 2001 From: Michael Woerister Date: Thu, 27 Jul 2017 13:02:31 +0200 Subject: [PATCH] async-llvm(22): mw invokes mad html skillz to produce graphical LLVM timing reports. --- src/librustc/session/config.rs | 2 + src/librustc_trans/back/write.rs | 26 +++++ src/librustc_trans/base.rs | 14 +++ src/librustc_trans/lib.rs | 1 + src/librustc_trans/time_graph.rs | 181 +++++++++++++++++++++++++++++++ 5 files changed, 224 insertions(+) create mode 100644 src/librustc_trans/time_graph.rs diff --git a/src/librustc/session/config.rs b/src/librustc/session/config.rs index 8c4cc20deb7b9..4a9fbbe6f157d 100644 --- a/src/librustc/session/config.rs +++ b/src/librustc/session/config.rs @@ -1059,6 +1059,8 @@ options! {DebuggingOptions, DebuggingSetter, basic_debugging_options, "choose which RELRO level to use"), nll: bool = (false, parse_bool, [UNTRACKED], "run the non-lexical lifetimes MIR pass"), + trans_time_graph: bool = (false, parse_bool, [UNTRACKED], + "generate a graphical HTML report of time spent in trans and LLVM"), } pub fn default_lib_output() -> CrateType { diff --git a/src/librustc_trans/back/write.rs b/src/librustc_trans/back/write.rs index 086980777e1dd..a3845cf0e8e7e 100644 --- a/src/librustc_trans/back/write.rs +++ b/src/librustc_trans/back/write.rs @@ -17,6 +17,7 @@ use rustc::middle::cstore::{LinkMeta, EncodedMetadata}; use rustc::session::config::{self, OutputFilenames, OutputType, OutputTypes, Passes, SomePasses, AllPasses, Sanitizer}; use rustc::session::Session; +use time_graph::{self, TimeGraph}; use llvm; use llvm::{ModuleRef, TargetMachineRef, PassManagerRef, DiagnosticInfoRef}; use llvm::SMDiagnosticRef; @@ -342,6 +343,9 @@ pub struct CodegenContext { pub incr_comp_session_dir: Option, // Channel back to the main control thread to send messages to coordinator_send: Sender, + // A reference to the TimeGraph so we can register timings. None means that + // measuring is disabled. + time_graph: Option, } impl CodegenContext { @@ -662,6 +666,7 @@ fn need_crate_bitcode_for_rlib(sess: &Session) -> bool { pub fn start_async_translation(sess: &Session, crate_output: &OutputFilenames, + time_graph: Option, crate_name: Symbol, link: LinkMeta, metadata: EncodedMetadata, @@ -768,6 +773,7 @@ pub fn start_async_translation(sess: &Session, coordinator_send.clone(), coordinator_receive, client, + time_graph.clone(), exported_symbols.clone()); OngoingCrateTranslation { crate_name, @@ -783,6 +789,7 @@ pub fn start_async_translation(sess: &Session, metadata_module_config: metadata_config, allocator_module_config: allocator_config, + time_graph, output_filenames: crate_output.clone(), coordinator_send, shared_emitter_main, @@ -1084,6 +1091,7 @@ fn start_executing_work(sess: &Session, coordinator_send: Sender, coordinator_receive: Receiver, jobserver: Client, + time_graph: Option, exported_symbols: Arc) -> thread::JoinHandle { // First up, convert our jobserver into a helper thread so we can use normal @@ -1123,6 +1131,7 @@ fn start_executing_work(sess: &Session, incr_comp_session_dir: sess.incr_comp_session_dir_opt().map(|r| r.clone()), coordinator_send: coordinator_send, diag_emitter: shared_emitter.clone(), + time_graph, }; // This is the "main loop" of parallel work happening for parallel codegen. @@ -1295,10 +1304,22 @@ fn start_executing_work(sess: &Session, }) } +pub const TRANS_WORKER_ID: usize = ::std::usize::MAX; +pub const TRANS_WORKER_TIMELINE: time_graph::TimelineId = + time_graph::TimelineId(TRANS_WORKER_ID); +pub const TRANS_WORK_PACKAGE_KIND: time_graph::WorkPackageKind = + time_graph::WorkPackageKind(&["#DE9597", "#FED1D3", "#FDC5C7", "#B46668", "#88494B"]); +const LLVM_WORK_PACKAGE_KIND: time_graph::WorkPackageKind = + time_graph::WorkPackageKind(&["#7DB67A", "#C6EEC4", "#ACDAAA", "#579354", "#3E6F3C"]); + fn spawn_work(cgcx: CodegenContext, work: WorkItem) { let depth = time_depth(); thread::spawn(move || { + let _timing_guard = cgcx.time_graph + .as_ref() + .map(|tg| tg.start(time_graph::TimelineId(cgcx.worker), + LLVM_WORK_PACKAGE_KIND)); set_time_depth(depth); // Set up a destructor which will fire off a message that we're done as @@ -1555,6 +1576,7 @@ pub struct OngoingCrateTranslation { metadata_module_config: ModuleConfig, allocator_module_config: ModuleConfig, + time_graph: Option, coordinator_send: Sender, shared_emitter_main: SharedEmitterMain, future: thread::JoinHandle, @@ -1567,6 +1589,10 @@ impl OngoingCrateTranslation { sess.abort_if_errors(); + if let Some(time_graph) = self.time_graph { + time_graph.dump(&format!("{}-timings", self.crate_name)); + } + copy_module_artifacts_into_incr_comp_cache(sess, &compiled_modules, &self.output_filenames); diff --git a/src/librustc_trans/base.rs b/src/librustc_trans/base.rs index 2e6093eb1ca37..0b82ac71c33d3 100644 --- a/src/librustc_trans/base.rs +++ b/src/librustc_trans/base.rs @@ -69,6 +69,7 @@ use mir; use monomorphize::{self, Instance}; use partitioning::{self, PartitioningStrategy, CodegenUnit}; use symbol_names_test; +use time_graph; use trans_item::{TransItem, DefPathBasedNames}; use type_::Type; use type_of; @@ -956,6 +957,11 @@ pub fn trans_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>, }; let no_builtins = attr::contains_name(&krate.attrs, "no_builtins"); + let time_graph = if tcx.sess.opts.debugging_opts.trans_time_graph { + Some(time_graph::TimeGraph::new()) + } else { + None + }; // Skip crate items and just output metadata in -Z no-trans mode. if tcx.sess.opts.debugging_opts.no_trans || @@ -965,6 +971,7 @@ pub fn trans_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>, let ongoing_translation = write::start_async_translation( tcx.sess, output_filenames, + time_graph.clone(), tcx.crate_name(LOCAL_CRATE), link_meta, metadata, @@ -1015,6 +1022,7 @@ pub fn trans_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>, let ongoing_translation = write::start_async_translation( tcx.sess, output_filenames, + time_graph.clone(), tcx.crate_name(LOCAL_CRATE), link_meta, metadata, @@ -1033,6 +1041,12 @@ pub fn trans_crate<'a, 'tcx>(tcx: TyCtxt<'a, 'tcx, 'tcx>, for cgu in codegen_units.into_iter() { ongoing_translation.check_for_errors(tcx.sess); + + let _timing_guard = time_graph + .as_ref() + .map(|time_graph| time_graph.start(write::TRANS_WORKER_TIMELINE, + write::TRANS_WORK_PACKAGE_KIND)); + let dep_node = cgu.work_product_dep_node(); let ((stats, module), _) = tcx.dep_graph.with_task(dep_node, diff --git a/src/librustc_trans/lib.rs b/src/librustc_trans/lib.rs index 62ff1535be956..83835cb794abf 100644 --- a/src/librustc_trans/lib.rs +++ b/src/librustc_trans/lib.rs @@ -125,6 +125,7 @@ mod mir; mod monomorphize; mod partitioning; mod symbol_names_test; +mod time_graph; mod trans_item; mod tvec; mod type_; diff --git a/src/librustc_trans/time_graph.rs b/src/librustc_trans/time_graph.rs new file mode 100644 index 0000000000000..e0ebe8a0933f1 --- /dev/null +++ b/src/librustc_trans/time_graph.rs @@ -0,0 +1,181 @@ +// Copyright 2017 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 std::collections::HashMap; +use std::marker::PhantomData; +use std::sync::{Arc, Mutex}; +use std::time::Instant; +use std::io::prelude::*; +use std::fs::File; + +const OUTPUT_WIDTH_IN_PX: u64 = 1000; +const TIME_LINE_HEIGHT_IN_PX: u64 = 7; +const TIME_LINE_HEIGHT_STRIDE_IN_PX: usize = 10; + +#[derive(Clone)] +struct Timing { + start: Instant, + end: Instant, + work_package_kind: WorkPackageKind, +} + +#[derive(Clone, Copy, Hash, Eq, PartialEq, Debug)] +pub struct TimelineId(pub usize); + +#[derive(Clone)] +struct PerThread { + timings: Vec, + open_work_package: Option<(Instant, WorkPackageKind)>, +} + +#[derive(Clone)] +pub struct TimeGraph { + data: Arc>>, +} + +#[derive(Clone, Copy)] +pub struct WorkPackageKind(pub &'static [&'static str]); + +pub struct RaiiToken { + graph: TimeGraph, + timeline: TimelineId, + // The token must not be Send: + _marker: PhantomData<*const ()> +} + + +impl Drop for RaiiToken { + fn drop(&mut self) { + self.graph.end(self.timeline); + } +} + +impl TimeGraph { + pub fn new() -> TimeGraph { + TimeGraph { + data: Arc::new(Mutex::new(HashMap::new())) + } + } + + pub fn start(&self, + timeline: TimelineId, + work_package_kind: WorkPackageKind) -> RaiiToken { + { + let mut table = self.data.lock().unwrap(); + + let mut data = table.entry(timeline).or_insert(PerThread { + timings: Vec::new(), + open_work_package: None, + }); + + assert!(data.open_work_package.is_none()); + data.open_work_package = Some((Instant::now(), work_package_kind)); + } + + RaiiToken { + graph: self.clone(), + timeline, + _marker: PhantomData, + } + } + + fn end(&self, timeline: TimelineId) { + let end = Instant::now(); + + let mut table = self.data.lock().unwrap(); + let mut data = table.get_mut(&timeline).unwrap(); + + if let Some((start, work_package_kind)) = data.open_work_package { + data.timings.push(Timing { + start, + end, + work_package_kind, + }); + } else { + bug!("end timing without start?") + } + + data.open_work_package = None; + } + + pub fn dump(&self, output_filename: &str) { + let table = self.data.lock().unwrap(); + + for data in table.values() { + assert!(data.open_work_package.is_none()); + } + + let mut timelines: Vec = + table.values().map(|data| data.clone()).collect(); + + timelines.sort_by_key(|timeline| timeline.timings[0].start); + + let earliest_instant = timelines[0].timings[0].start; + let latest_instant = timelines.iter() + .map(|timeline| timeline.timings + .last() + .unwrap() + .end) + .max() + .unwrap(); + let max_distance = distance(earliest_instant, latest_instant); + + let mut file = File::create(format!("{}.html", output_filename)).unwrap(); + + writeln!(file, "").unwrap(); + writeln!(file, "").unwrap(); + writeln!(file, "").unwrap(); + + let mut color = 0; + + for (line_index, timeline) in timelines.iter().enumerate() { + let line_top = line_index * TIME_LINE_HEIGHT_STRIDE_IN_PX; + + for span in &timeline.timings { + let start = distance(earliest_instant, span.start); + let end = distance(earliest_instant, span.end); + + let start = normalize(start, max_distance, OUTPUT_WIDTH_IN_PX); + let end = normalize(end, max_distance, OUTPUT_WIDTH_IN_PX); + + let colors = span.work_package_kind.0; + + writeln!(file, "
", + line_top, + start, + end - start, + TIME_LINE_HEIGHT_IN_PX, + colors[color % colors.len()] + ).unwrap(); + + color += 1; + } + } + + writeln!(file, "").unwrap(); + writeln!(file, "").unwrap(); + } +} + +fn distance(zero: Instant, x: Instant) -> u64 { + + let duration = x.duration_since(zero); + (duration.as_secs() * 1_000_000_000 + duration.subsec_nanos() as u64) // / div +} + +fn normalize(distance: u64, max: u64, max_pixels: u64) -> u64 { + (max_pixels * distance) / max +} +