mirror of
https://github.com/rust-lang/cargo
synced 2024-08-28 11:50:23 +00:00
Auto merge of #7311 - ehuss:pipeline-timing, r=alexcrichton
Experiment: Create timing report. This is just an experiment, so I'm not sure if we'll want to merge it. This adds an HTML report which gets saved to disk when the build is finished. It is primarily geared for identifying slow dependencies, and for visualizing how pipelining affects the build. Here's an example: https://ehuss.github.io/cargo-timing.html You can mouse over the blocks to highlight the reverse-dependencies that are released when a unit finishes. `syn` is a really good example. It does a few other things, like displaying a message after each unit is finished. See the docs for more information.
This commit is contained in:
bors
commit
d764fff2da
|
|
@ -37,6 +37,7 @@ git2-curl = "0.11.0"
|
|||
glob = "0.3.0"
|
||||
hex = "0.3"
|
||||
home = "0.5"
|
||||
humantime = "1.2.0"
|
||||
ignore = "0.4.7"
|
||||
lazy_static = "1.2.0"
|
||||
jobserver = "0.1.13"
|
||||
|
|
|
|||
|
|
@ -36,6 +36,7 @@ Available unstable (nightly-only) flags:
|
|||
-Z config-profile -- Read profiles from .cargo/config files
|
||||
-Z install-upgrade -- `cargo install` will upgrade instead of failing
|
||||
-Z cache-messages -- Cache compiler messages
|
||||
-Z timings -- Display concurrency information
|
||||
|
||||
Run with 'cargo -Z [FLAG] [SUBCOMMAND]'"
|
||||
);
|
||||
|
|
|
|||
|
|
@ -129,7 +129,7 @@ impl<'a, 'cfg> Context<'a, 'cfg> {
|
|||
export_dir: Option<PathBuf>,
|
||||
exec: &Arc<dyn Executor>,
|
||||
) -> CargoResult<Compilation<'cfg>> {
|
||||
let mut queue = JobQueue::new(self.bcx);
|
||||
let mut queue = JobQueue::new(self.bcx, units);
|
||||
let mut plan = BuildPlan::new();
|
||||
let build_plan = self.bcx.build_config.build_plan;
|
||||
self.prepare_units(export_dir, units)?;
|
||||
|
|
@ -523,6 +523,6 @@ impl<'a, 'cfg> Context<'a, 'cfg> {
|
|||
/// Returns whether when `unit` is built whether it should emit metadata as
|
||||
/// well because some compilations rely on that.
|
||||
pub fn rmeta_required(&self, unit: &Unit<'a>) -> bool {
|
||||
self.rmeta_required.contains(unit)
|
||||
self.rmeta_required.contains(unit) || self.bcx.config.cli_unstable().timings.is_some()
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -16,6 +16,7 @@ use super::job::{
|
|||
Freshness::{self, Dirty, Fresh},
|
||||
Job,
|
||||
};
|
||||
use super::timings::Timings;
|
||||
use super::{BuildContext, BuildPlan, CompileMode, Context, Unit};
|
||||
use crate::core::{PackageId, TargetKind};
|
||||
use crate::handle_error;
|
||||
|
|
@ -41,6 +42,7 @@ pub struct JobQueue<'a, 'cfg> {
|
|||
is_release: bool,
|
||||
progress: Progress<'cfg>,
|
||||
next_id: u32,
|
||||
timings: Timings<'a, 'cfg>,
|
||||
}
|
||||
|
||||
pub struct JobState<'a> {
|
||||
|
|
@ -82,7 +84,7 @@ enum Artifact {
|
|||
}
|
||||
|
||||
enum Message {
|
||||
Run(String),
|
||||
Run(u32, String),
|
||||
BuildPlanMsg(String, ProcessBuilder, Arc<Vec<OutputFile>>),
|
||||
Stdout(String),
|
||||
Stderr(String),
|
||||
|
|
@ -93,7 +95,7 @@ enum Message {
|
|||
|
||||
impl<'a> JobState<'a> {
|
||||
pub fn running(&self, cmd: &ProcessBuilder) {
|
||||
let _ = self.tx.send(Message::Run(cmd.to_string()));
|
||||
let _ = self.tx.send(Message::Run(self.id, cmd.to_string()));
|
||||
}
|
||||
|
||||
pub fn build_plan(
|
||||
|
|
@ -121,7 +123,6 @@ impl<'a> JobState<'a> {
|
|||
/// This should only be called once because a metadata file can only be
|
||||
/// produced once!
|
||||
pub fn rmeta_produced(&self) {
|
||||
assert!(self.rmeta_required.get());
|
||||
self.rmeta_required.set(false);
|
||||
let _ = self
|
||||
.tx
|
||||
|
|
@ -130,9 +131,10 @@ impl<'a> JobState<'a> {
|
|||
}
|
||||
|
||||
impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
||||
pub fn new(bcx: &BuildContext<'a, 'cfg>) -> JobQueue<'a, 'cfg> {
|
||||
pub fn new(bcx: &BuildContext<'a, 'cfg>, root_units: &[Unit<'a>]) -> JobQueue<'a, 'cfg> {
|
||||
let (tx, rx) = channel();
|
||||
let progress = Progress::with_style("Building", ProgressStyle::Ratio, bcx.config);
|
||||
let timings = Timings::new(bcx, root_units);
|
||||
JobQueue {
|
||||
queue: DependencyQueue::new(),
|
||||
tx,
|
||||
|
|
@ -144,6 +146,7 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
|||
is_release: bcx.build_config.release,
|
||||
progress,
|
||||
next_id: 0,
|
||||
timings,
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -318,6 +321,9 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
|||
// to the jobserver itself.
|
||||
tokens.truncate(self.active.len() - 1);
|
||||
|
||||
self.timings
|
||||
.mark_concurrency(self.active.len(), queue.len(), self.queue.len());
|
||||
|
||||
// Drain all events at once to avoid displaying the progress bar
|
||||
// unnecessarily.
|
||||
let events: Vec<_> = self.rx.try_iter().collect();
|
||||
|
|
@ -330,18 +336,18 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
|||
|
||||
for event in events {
|
||||
match event {
|
||||
Message::Run(cmd) => {
|
||||
Message::Run(id, cmd) => {
|
||||
cx.bcx
|
||||
.config
|
||||
.shell()
|
||||
.verbose(|c| c.status("Running", &cmd))?;
|
||||
self.timings.unit_start(id, self.active[&id]);
|
||||
}
|
||||
Message::BuildPlanMsg(module_name, cmd, filenames) => {
|
||||
plan.update(&module_name, &cmd, &filenames)?;
|
||||
}
|
||||
Message::Stdout(out) => {
|
||||
self.progress.clear();
|
||||
println!("{}", out);
|
||||
cx.bcx.config.shell().stdout_println(out);
|
||||
}
|
||||
Message::Stderr(err) => {
|
||||
let mut shell = cx.bcx.config.shell();
|
||||
|
|
@ -369,7 +375,7 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
|||
};
|
||||
info!("end ({:?}): {:?}", unit, result);
|
||||
match result {
|
||||
Ok(()) => self.finish(&unit, artifact, cx)?,
|
||||
Ok(()) => self.finish(id, &unit, artifact, cx)?,
|
||||
Err(e) => {
|
||||
let msg = "The following warnings were emitted during compilation:";
|
||||
self.emit_warnings(Some(msg), &unit, cx)?;
|
||||
|
|
@ -427,6 +433,7 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
|||
if !cx.bcx.build_config.build_plan {
|
||||
cx.bcx.config.shell().status("Finished", message)?;
|
||||
}
|
||||
self.timings.finished()?;
|
||||
Ok(())
|
||||
} else {
|
||||
debug!("queue: {:#?}", self.queue);
|
||||
|
|
@ -542,8 +549,12 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
|||
}
|
||||
|
||||
match fresh {
|
||||
Freshness::Fresh => doit(),
|
||||
Freshness::Fresh => {
|
||||
self.timings.add_fresh();
|
||||
doit()
|
||||
}
|
||||
Freshness::Dirty => {
|
||||
self.timings.add_dirty();
|
||||
scope.spawn(move |_| doit());
|
||||
}
|
||||
}
|
||||
|
|
@ -581,6 +592,7 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
|||
|
||||
fn finish(
|
||||
&mut self,
|
||||
id: u32,
|
||||
unit: &Unit<'a>,
|
||||
artifact: Artifact,
|
||||
cx: &mut Context<'_, '_>,
|
||||
|
|
@ -588,7 +600,11 @@ impl<'a, 'cfg> JobQueue<'a, 'cfg> {
|
|||
if unit.mode.is_run_custom_build() && cx.bcx.show_warnings(unit.pkg.package_id()) {
|
||||
self.emit_warnings(None, unit, cx)?;
|
||||
}
|
||||
self.queue.finish(unit, &artifact);
|
||||
let unlocked = self.queue.finish(unit, &artifact);
|
||||
match artifact {
|
||||
Artifact::All => self.timings.unit_finished(id, unlocked),
|
||||
Artifact::Metadata => self.timings.unit_rmeta_finished(id, unlocked),
|
||||
}
|
||||
Ok(())
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -11,6 +11,7 @@ mod layout;
|
|||
mod links;
|
||||
mod output_depinfo;
|
||||
pub mod standard_lib;
|
||||
mod timings;
|
||||
mod unit;
|
||||
pub mod unit_dependencies;
|
||||
|
||||
|
|
@ -18,13 +19,12 @@ use std::env;
|
|||
use std::ffi::{OsStr, OsString};
|
||||
use std::fs::{self, File};
|
||||
use std::io::Write;
|
||||
use std::path::{Path, PathBuf};
|
||||
use std::path::PathBuf;
|
||||
use std::sync::Arc;
|
||||
|
||||
use failure::Error;
|
||||
use lazycell::LazyCell;
|
||||
use log::debug;
|
||||
use same_file::is_same_file;
|
||||
use serde::Serialize;
|
||||
|
||||
pub use self::build_config::{BuildConfig, CompileMode, MessageFormat};
|
||||
|
|
@ -442,12 +442,12 @@ fn link_targets<'a, 'cfg>(
|
|||
}
|
||||
};
|
||||
destinations.push(dst.clone());
|
||||
hardlink_or_copy(src, dst)?;
|
||||
paths::link_or_copy(src, dst)?;
|
||||
if let Some(ref path) = output.export_path {
|
||||
let export_dir = export_dir.as_ref().unwrap();
|
||||
paths::create_dir_all(export_dir)?;
|
||||
|
||||
hardlink_or_copy(src, path)?;
|
||||
paths::link_or_copy(src, path)?;
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -476,54 +476,6 @@ fn link_targets<'a, 'cfg>(
|
|||
}))
|
||||
}
|
||||
|
||||
/// Hardlink (file) or symlink (dir) src to dst if possible, otherwise copy it.
|
||||
fn hardlink_or_copy(src: &Path, dst: &Path) -> CargoResult<()> {
|
||||
debug!("linking {} to {}", src.display(), dst.display());
|
||||
if is_same_file(src, dst).unwrap_or(false) {
|
||||
return Ok(());
|
||||
}
|
||||
|
||||
// NB: we can't use dst.exists(), as if dst is a broken symlink,
|
||||
// dst.exists() will return false. This is problematic, as we still need to
|
||||
// unlink dst in this case. symlink_metadata(dst).is_ok() will tell us
|
||||
// whether dst exists *without* following symlinks, which is what we want.
|
||||
if fs::symlink_metadata(dst).is_ok() {
|
||||
paths::remove_file(&dst)?;
|
||||
}
|
||||
|
||||
let link_result = if src.is_dir() {
|
||||
#[cfg(target_os = "redox")]
|
||||
use std::os::redox::fs::symlink;
|
||||
#[cfg(unix)]
|
||||
use std::os::unix::fs::symlink;
|
||||
#[cfg(windows)]
|
||||
use std::os::windows::fs::symlink_dir as symlink;
|
||||
|
||||
let dst_dir = dst.parent().unwrap();
|
||||
let src = if src.starts_with(dst_dir) {
|
||||
src.strip_prefix(dst_dir).unwrap()
|
||||
} else {
|
||||
src
|
||||
};
|
||||
symlink(src, dst)
|
||||
} else {
|
||||
fs::hard_link(src, dst)
|
||||
};
|
||||
link_result
|
||||
.or_else(|err| {
|
||||
debug!("link failed {}. falling back to fs::copy", err);
|
||||
fs::copy(src, dst).map(|_| ())
|
||||
})
|
||||
.chain_err(|| {
|
||||
format!(
|
||||
"failed to link or copy `{}` to `{}`",
|
||||
src.display(),
|
||||
dst.display()
|
||||
)
|
||||
})?;
|
||||
Ok(())
|
||||
}
|
||||
|
||||
// For all plugin dependencies, add their -L paths (now calculated and present
|
||||
// in `build_script_outputs`) to the dynamic library load path for the command
|
||||
// to execute.
|
||||
|
|
|
|||
437
src/cargo/core/compiler/timings.js
Normal file
437
src/cargo/core/compiler/timings.js
Normal file
|
|
@ -0,0 +1,437 @@
|
|||
// Position of the vertical axis.
|
||||
const X_LINE = 50;
|
||||
// General-use margin size.
|
||||
const MARGIN = 5;
|
||||
// Position of the horizontal axis, relative to the bottom.
|
||||
const Y_LINE = 35;
|
||||
// Minimum distance between time tick labels.
|
||||
const MIN_TICK_DIST = 50;
|
||||
// Radius for rounded rectangle corners.
|
||||
const RADIUS = 3;
|
||||
// Height of unit boxes.
|
||||
const BOX_HEIGHT = 25;
|
||||
// Distance between Y tick marks on the unit graph.
|
||||
const Y_TICK_DIST = BOX_HEIGHT + 2;
|
||||
// Rects used for mouseover detection.
|
||||
// Objects of {x, y, x2, y2, i} where `i` is the index into UNIT_DATA.
|
||||
let HIT_BOXES = [];
|
||||
// Index into UNIT_DATA of the last unit hovered over by mouse.
|
||||
let LAST_HOVER = null;
|
||||
// Key is unit index, value is {x, y, width, rmeta_x} of the box.
|
||||
let UNIT_COORDS = {};
|
||||
// Map of unit index to the index it was unlocked by.
|
||||
let REVERSE_UNIT_DEPS = {};
|
||||
let REVERSE_UNIT_RMETA_DEPS = {};
|
||||
for (let n=0; n<UNIT_DATA.length; n++) {
|
||||
let unit = UNIT_DATA[n];
|
||||
for (let unlocked of unit.unlocked_units) {
|
||||
REVERSE_UNIT_DEPS[unlocked] = n;
|
||||
}
|
||||
for (let unlocked of unit.unlocked_rmeta_units) {
|
||||
REVERSE_UNIT_RMETA_DEPS[unlocked] = n;
|
||||
}
|
||||
}
|
||||
|
||||
function render_pipeline_graph() {
|
||||
if (UNIT_DATA.length == 0) {
|
||||
return;
|
||||
}
|
||||
let g = document.getElementById('pipeline-graph');
|
||||
HIT_BOXES.length = 0;
|
||||
g.onmousemove = pipeline_mousemove;
|
||||
const min_time = document.getElementById('min-unit-time').valueAsNumber;
|
||||
|
||||
const units = UNIT_DATA.filter(unit => unit.duration >= min_time);
|
||||
|
||||
const graph_height = Y_TICK_DIST * units.length;
|
||||
const {ctx, width, height} = draw_graph_axes('pipeline-graph', graph_height);
|
||||
const container = document.getElementById('pipeline-container');
|
||||
container.style.width = width;
|
||||
container.style.height = height;
|
||||
const PX_PER_SEC = document.getElementById('scale').valueAsNumber;
|
||||
|
||||
// Canvas for hover highlights. This is a separate layer to improve performance.
|
||||
const linectx = setup_canvas('pipeline-graph-lines', width, height);
|
||||
linectx.clearRect(0, 0, width, height);
|
||||
|
||||
// Draw Y tick marks.
|
||||
for (let n=1; n<units.length; n++) {
|
||||
const y = graph_height - (n * Y_TICK_DIST);
|
||||
ctx.beginPath();
|
||||
ctx.moveTo(X_LINE, y);
|
||||
ctx.lineTo(X_LINE-5, y);
|
||||
ctx.stroke();
|
||||
}
|
||||
|
||||
// Draw Y labels.
|
||||
ctx.textAlign = 'end';
|
||||
for (let n=0; n<units.length; n++) {
|
||||
let y = MARGIN + (Y_TICK_DIST * (n + 1)) - 13;
|
||||
ctx.fillText(n+1, X_LINE-4, y);
|
||||
}
|
||||
|
||||
// Draw the graph.
|
||||
ctx.save();
|
||||
ctx.translate(X_LINE, MARGIN);
|
||||
|
||||
// Compute x,y coordinate of each block.
|
||||
UNIT_COORDS = {};
|
||||
for (i=0; i<units.length; i++) {
|
||||
let unit = units[i];
|
||||
let y = i * Y_TICK_DIST + 1;
|
||||
let x = PX_PER_SEC * unit.start;
|
||||
let rmeta_x = null;
|
||||
if (unit.rmeta_time != null) {
|
||||
rmeta_x = x + PX_PER_SEC * unit.rmeta_time;
|
||||
}
|
||||
let width = Math.max(PX_PER_SEC * unit.duration, 1.0);
|
||||
UNIT_COORDS[unit.i] = {x, y, width, rmeta_x};
|
||||
}
|
||||
|
||||
// Draw the blocks.
|
||||
for (i=0; i<units.length; i++) {
|
||||
let unit = units[i];
|
||||
let {x, y, width, rmeta_x} = UNIT_COORDS[unit.i];
|
||||
|
||||
HIT_BOXES.push({x: X_LINE+x, y:MARGIN+y, x2: X_LINE+x+width, y2: MARGIN+y+BOX_HEIGHT, i: unit.i});
|
||||
|
||||
ctx.beginPath();
|
||||
ctx.fillStyle = unit.mode == 'run-custom-build' ? '#f0b165' : '#95cce8';
|
||||
roundedRect(ctx, x, y, width, BOX_HEIGHT, RADIUS);
|
||||
ctx.fill();
|
||||
|
||||
if (unit.rmeta_time != null) {
|
||||
ctx.beginPath();
|
||||
ctx.fillStyle = '#aa95e8';
|
||||
let ctime = unit.duration - unit.rmeta_time;
|
||||
roundedRect(ctx, rmeta_x, y, PX_PER_SEC * ctime, BOX_HEIGHT, RADIUS);
|
||||
ctx.fill();
|
||||
}
|
||||
ctx.fillStyle = "#000";
|
||||
ctx.textAlign = 'start';
|
||||
ctx.textBaseline = 'hanging';
|
||||
ctx.font = '14px sans-serif';
|
||||
ctx.fillText(`${unit.name}${unit.target} ${unit.duration}s`, x + 5.0, y + BOX_HEIGHT / 2 - 6);
|
||||
draw_dep_lines(ctx, unit.i, false);
|
||||
}
|
||||
ctx.restore();
|
||||
}
|
||||
|
||||
// Draws lines from the given unit to the units it unlocks.
|
||||
function draw_dep_lines(ctx, unit_idx, highlighted) {
|
||||
const unit = UNIT_DATA[unit_idx];
|
||||
const {x, y, rmeta_x} = UNIT_COORDS[unit_idx];
|
||||
ctx.save();
|
||||
for (const unlocked of unit.unlocked_units) {
|
||||
draw_one_dep_line(ctx, x, y, unlocked, highlighted);
|
||||
}
|
||||
for (const unlocked of unit.unlocked_rmeta_units) {
|
||||
draw_one_dep_line(ctx, rmeta_x, y, unlocked, highlighted);
|
||||
}
|
||||
ctx.restore();
|
||||
}
|
||||
|
||||
function draw_one_dep_line(ctx, from_x, from_y, to_unit, highlighted) {
|
||||
if (to_unit in UNIT_COORDS) {
|
||||
let {x: u_x, y: u_y} = UNIT_COORDS[to_unit];
|
||||
ctx.strokeStyle = highlighted ? '#000' : '#ddd';
|
||||
ctx.setLineDash([2]);
|
||||
ctx.beginPath();
|
||||
ctx.moveTo(from_x, from_y+BOX_HEIGHT/2);
|
||||
ctx.lineTo(from_x-5, from_y+BOX_HEIGHT/2);
|
||||
ctx.lineTo(from_x-5, u_y+BOX_HEIGHT/2);
|
||||
ctx.lineTo(u_x, u_y+BOX_HEIGHT/2);
|
||||
ctx.stroke();
|
||||
}
|
||||
}
|
||||
|
||||
function render_timing_graph() {
|
||||
if (CONCURRENCY_DATA.length == 0) {
|
||||
return;
|
||||
}
|
||||
const HEIGHT = 400;
|
||||
const AXIS_HEIGHT = HEIGHT - MARGIN - Y_LINE;
|
||||
const TOP_MARGIN = 10;
|
||||
const GRAPH_HEIGHT = AXIS_HEIGHT - TOP_MARGIN;
|
||||
|
||||
const {graph_width, ctx} = draw_graph_axes('timing-graph', AXIS_HEIGHT);
|
||||
|
||||
// Draw Y tick marks and labels.
|
||||
let max_v = 0;
|
||||
for (c of CONCURRENCY_DATA) {
|
||||
max_v = Math.max(max_v, c.active, c.waiting, c.inactive);
|
||||
}
|
||||
let [step, top] = split_ticks(max_v, GRAPH_HEIGHT / MIN_TICK_DIST);
|
||||
let num_ticks = top / step;
|
||||
let tick_dist = GRAPH_HEIGHT / num_ticks;
|
||||
ctx.textAlign = 'end';
|
||||
for (n=0; n<num_ticks; n++) {
|
||||
let y = HEIGHT - Y_LINE - ((n + 1) * tick_dist);
|
||||
ctx.beginPath();
|
||||
ctx.moveTo(X_LINE, y);
|
||||
ctx.lineTo(X_LINE-5, y);
|
||||
ctx.stroke();
|
||||
ctx.fillText((n+1) * step, X_LINE-10, y+5);
|
||||
}
|
||||
|
||||
// Label the Y axis.
|
||||
let label_y = (HEIGHT - Y_LINE) / 2;
|
||||
ctx.save();
|
||||
ctx.translate(15, label_y);
|
||||
ctx.rotate(3*Math.PI/2);
|
||||
ctx.textAlign = 'center';
|
||||
ctx.fillText('# Units', 0, 0);
|
||||
ctx.restore();
|
||||
|
||||
// Draw the graph.
|
||||
ctx.save();
|
||||
ctx.translate(X_LINE, MARGIN);
|
||||
|
||||
function coord(t, v) {
|
||||
return {
|
||||
x: graph_width * (t/DURATION),
|
||||
y: TOP_MARGIN + GRAPH_HEIGHT * (1.0 - (v / max_v))
|
||||
};
|
||||
}
|
||||
function draw_line(style, key) {
|
||||
let first = CONCURRENCY_DATA[0];
|
||||
let last = coord(first.t, key(first));
|
||||
ctx.strokeStyle = style;
|
||||
ctx.beginPath();
|
||||
ctx.moveTo(last.x, last.y);
|
||||
for (let i=1; i<CONCURRENCY_DATA.length; i++) {
|
||||
let c = CONCURRENCY_DATA[i];
|
||||
let {x, y} = coord(c.t, key(c));
|
||||
ctx.lineTo(x, last.y);
|
||||
ctx.lineTo(x, y);
|
||||
last = {x, y};
|
||||
}
|
||||
ctx.stroke();
|
||||
}
|
||||
|
||||
draw_line('blue', function(c) {return c.inactive;});
|
||||
draw_line('red', function(c) {return c.waiting;});
|
||||
draw_line('green', function(c) {return c.active;});
|
||||
|
||||
// Draw a legend.
|
||||
ctx.restore();
|
||||
ctx.save();
|
||||
ctx.translate(graph_width-120, MARGIN);
|
||||
// background
|
||||
ctx.fillStyle = '#fff';
|
||||
ctx.strokeStyle = '#000';
|
||||
ctx.lineWidth = 1;
|
||||
ctx.textBaseline = 'middle'
|
||||
ctx.textAlign = 'start';
|
||||
ctx.beginPath();
|
||||
ctx.rect(0, 0, 120, 62);
|
||||
ctx.stroke();
|
||||
ctx.fill();
|
||||
|
||||
ctx.fillStyle = '#000'
|
||||
ctx.beginPath();
|
||||
ctx.lineWidth = 2;
|
||||
ctx.strokeStyle = 'red';
|
||||
ctx.moveTo(5, 10);
|
||||
ctx.lineTo(50, 10);
|
||||
ctx.stroke();
|
||||
ctx.fillText('Waiting', 54, 11);
|
||||
|
||||
ctx.beginPath();
|
||||
ctx.strokeStyle = 'blue';
|
||||
ctx.moveTo(5, 30);
|
||||
ctx.lineTo(50, 30);
|
||||
ctx.stroke();
|
||||
ctx.fillText('Inactive', 54, 31);
|
||||
|
||||
ctx.beginPath();
|
||||
ctx.strokeStyle = 'green';
|
||||
ctx.moveTo(5, 50);
|
||||
ctx.lineTo(50, 50);
|
||||
ctx.stroke();
|
||||
ctx.fillText('Active', 54, 51);
|
||||
|
||||
ctx.restore();
|
||||
}
|
||||
|
||||
function setup_canvas(id, width, height) {
|
||||
let g = document.getElementById(id);
|
||||
let dpr = window.devicePixelRatio || 1;
|
||||
g.width = width * dpr;
|
||||
g.height = height * dpr;
|
||||
g.style.width = width;
|
||||
g.style.height = height;
|
||||
let ctx = g.getContext('2d');
|
||||
ctx.scale(dpr, dpr);
|
||||
return ctx;
|
||||
}
|
||||
|
||||
function draw_graph_axes(id, graph_height) {
|
||||
const PX_PER_SEC = document.getElementById('scale').valueAsNumber;
|
||||
const graph_width = PX_PER_SEC * DURATION;
|
||||
const width = graph_width + X_LINE + 30;
|
||||
const height = graph_height + MARGIN + Y_LINE;
|
||||
let ctx = setup_canvas(id, width, height);
|
||||
ctx.fillStyle = '#f7f7f7';
|
||||
ctx.fillRect(0, 0, width, height);
|
||||
|
||||
ctx.lineWidth = 2;
|
||||
ctx.font = '16px sans-serif';
|
||||
ctx.textAlign = 'center';
|
||||
|
||||
// Draw main axes.
|
||||
ctx.beginPath();
|
||||
ctx.moveTo(X_LINE, MARGIN);
|
||||
ctx.lineTo(X_LINE, graph_height + MARGIN);
|
||||
ctx.lineTo(X_LINE+graph_width+20, graph_height + MARGIN);
|
||||
ctx.stroke();
|
||||
|
||||
// Draw X tick marks.
|
||||
const tick_width = graph_width - 10;
|
||||
const [step, top] = split_ticks(DURATION, tick_width / MIN_TICK_DIST);
|
||||
const num_ticks = top / step;
|
||||
const tick_dist = tick_width / num_ticks;
|
||||
ctx.fillStyle = '#303030';
|
||||
for (let n=0; n<num_ticks; n++) {
|
||||
const x = X_LINE + ((n + 1) * tick_dist);
|
||||
ctx.beginPath();
|
||||
ctx.moveTo(x, height-Y_LINE);
|
||||
ctx.lineTo(x, height-Y_LINE+5);
|
||||
ctx.stroke();
|
||||
|
||||
ctx.fillText(`${(n+1) * step}s`, x, height - Y_LINE + 20);
|
||||
}
|
||||
|
||||
// Draw vertical lines.
|
||||
ctx.strokeStyle = '#e6e6e6';
|
||||
ctx.setLineDash([2, 4]);
|
||||
for (n=0; n<num_ticks; n++) {
|
||||
const x = X_LINE + ((n + 1) * tick_dist);
|
||||
ctx.beginPath();
|
||||
ctx.moveTo(x, MARGIN);
|
||||
ctx.lineTo(x, MARGIN+graph_height);
|
||||
ctx.stroke();
|
||||
}
|
||||
ctx.strokeStyle = '#000';
|
||||
ctx.setLineDash([]);
|
||||
return {width, height, graph_width, graph_height, ctx};
|
||||
}
|
||||
|
||||
function round_up(n, step) {
|
||||
if (n % step == 0) {
|
||||
return n;
|
||||
} else {
|
||||
return (step - n % step) + n;
|
||||
}
|
||||
}
|
||||
|
||||
// Determine the `(step, max_value)` of the number of ticks along an axis.
|
||||
function split_ticks(n, max_ticks) {
|
||||
if (n <= max_ticks) {
|
||||
return [1, n];
|
||||
} else if (n <= max_ticks * 2) {
|
||||
return [2, round_up(n, 2)];
|
||||
} else if (n <= max_ticks * 4) {
|
||||
return [4, round_up(n, 4)];
|
||||
} else if (n <= max_ticks * 5) {
|
||||
return [5, round_up(n, 5)];
|
||||
} else {
|
||||
let step = 10;
|
||||
while (true) {
|
||||
let top = round_up(n, step);
|
||||
if (top <= max_ticks * step) {
|
||||
return [step, top];
|
||||
}
|
||||
step += 10;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
function codegen_time(unit) {
|
||||
if (unit.rmeta_time == null) {
|
||||
return null;
|
||||
}
|
||||
let ctime = unit.duration - unit.rmeta_time;
|
||||
return [unit.rmeta_time, ctime];
|
||||
}
|
||||
|
||||
function roundedRect(ctx, x, y, width, height, r) {
|
||||
r = Math.min(r, width, height);
|
||||
ctx.beginPath();
|
||||
ctx.moveTo(x+r, y);
|
||||
ctx.lineTo(x+width-r, y);
|
||||
ctx.arc(x+width-r, y+r, r, 3*Math.PI/2, 0);
|
||||
ctx.lineTo(x+width, y+height-r);
|
||||
ctx.arc(x+width-r, y+height-r, r, 0, Math.PI/2);
|
||||
ctx.lineTo(x+r, y+height);
|
||||
ctx.arc(x+r, y+height-r, r, Math.PI/2, Math.PI);
|
||||
ctx.lineTo(x, y-r);
|
||||
ctx.arc(x+r, y+r, r, Math.PI, 3*Math.PI/2);
|
||||
ctx.closePath();
|
||||
}
|
||||
|
||||
function pipeline_mouse_hit(event) {
|
||||
// This brute-force method can be optimized if needed.
|
||||
for (let box of HIT_BOXES) {
|
||||
if (event.offsetX >= box.x && event.offsetX <= box.x2 &&
|
||||
event.offsetY >= box.y && event.offsetY <= box.y2) {
|
||||
return box;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
function pipeline_mousemove(event) {
|
||||
// Highlight dependency lines on mouse hover.
|
||||
let box = pipeline_mouse_hit(event);
|
||||
if (box) {
|
||||
if (box.i != LAST_HOVER) {
|
||||
LAST_HOVER = box.i;
|
||||
let g = document.getElementById('pipeline-graph-lines');
|
||||
let ctx = g.getContext('2d');
|
||||
ctx.clearRect(0, 0, g.width, g.height);
|
||||
ctx.save();
|
||||
ctx.translate(X_LINE, MARGIN);
|
||||
ctx.lineWidth = 2;
|
||||
draw_dep_lines(ctx, box.i, true);
|
||||
|
||||
if (box.i in REVERSE_UNIT_DEPS) {
|
||||
const dep_unit = REVERSE_UNIT_DEPS[box.i];
|
||||
if (dep_unit in UNIT_COORDS) {
|
||||
const {x, y, rmeta_x} = UNIT_COORDS[dep_unit];
|
||||
draw_one_dep_line(ctx, x, y, box.i, true);
|
||||
}
|
||||
}
|
||||
if (box.i in REVERSE_UNIT_RMETA_DEPS) {
|
||||
const dep_unit = REVERSE_UNIT_RMETA_DEPS[box.i];
|
||||
if (dep_unit in UNIT_COORDS) {
|
||||
const {x, y, rmeta_x} = UNIT_COORDS[dep_unit];
|
||||
draw_one_dep_line(ctx, rmeta_x, y, box.i, true);
|
||||
}
|
||||
}
|
||||
ctx.restore();
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
render_pipeline_graph();
|
||||
render_timing_graph();
|
||||
|
||||
// Set up and handle controls.
|
||||
{
|
||||
const range = document.getElementById('min-unit-time');
|
||||
const time_output = document.getElementById('min-unit-time-output');
|
||||
time_output.innerHTML = `${range.value}s`;
|
||||
range.oninput = event => {
|
||||
time_output.innerHTML = `${range.value}s`;
|
||||
render_pipeline_graph();
|
||||
};
|
||||
|
||||
const scale = document.getElementById('scale');
|
||||
const scale_output = document.getElementById('scale-output');
|
||||
scale_output.innerHTML = `${scale.value}`;
|
||||
scale.oninput = event => {
|
||||
scale_output.innerHTML = `${scale.value}`;
|
||||
render_pipeline_graph();
|
||||
render_timing_graph();
|
||||
};
|
||||
}
|
||||
668
src/cargo/core/compiler/timings.rs
Normal file
668
src/cargo/core/compiler/timings.rs
Normal file
|
|
@ -0,0 +1,668 @@
|
|||
//! Timing tracking.
|
||||
//!
|
||||
//! This module implements some simple tracking information for timing of how
|
||||
//! long it takes for different units to compile.
|
||||
use super::{CompileMode, Unit};
|
||||
use crate::core::compiler::BuildContext;
|
||||
use crate::core::PackageId;
|
||||
use crate::util::machine_message::{self, Message};
|
||||
use crate::util::{paths, CargoResult, Config};
|
||||
use std::collections::HashMap;
|
||||
use std::fs::File;
|
||||
use std::io::{BufWriter, Write};
|
||||
use std::time::{Duration, Instant, SystemTime};
|
||||
|
||||
pub struct Timings<'a, 'cfg> {
|
||||
config: &'cfg Config,
|
||||
/// Whether or not timings should be captured.
|
||||
enabled: bool,
|
||||
/// If true, saves an HTML report to disk.
|
||||
report_html: bool,
|
||||
/// If true, reports unit completion to stderr.
|
||||
report_info: bool,
|
||||
/// If true, emits JSON information with timing information.
|
||||
report_json: bool,
|
||||
/// When Cargo started.
|
||||
start: Instant,
|
||||
/// A rendered string of when compilation started.
|
||||
start_str: String,
|
||||
/// Some information to display about rustc.
|
||||
rustc_info: String,
|
||||
/// A summary of the root units.
|
||||
///
|
||||
/// Tuples of `(package_description, target_descrptions)`.
|
||||
root_targets: Vec<(String, Vec<String>)>,
|
||||
/// The build profile.
|
||||
profile: String,
|
||||
/// Total number of fresh units.
|
||||
total_fresh: u32,
|
||||
/// Total number of dirty units.
|
||||
total_dirty: u32,
|
||||
/// Time tracking for each individual unit.
|
||||
unit_times: Vec<UnitTime<'a>>,
|
||||
/// Units that are in the process of being built.
|
||||
/// When they finished, they are moved to `unit_times`.
|
||||
active: HashMap<u32, UnitTime<'a>>,
|
||||
/// Concurrency-tracking information. This is periodically updated while
|
||||
/// compilation progresses.
|
||||
concurrency: Vec<Concurrency>,
|
||||
}
|
||||
|
||||
/// Tracking information for an individual unit.
|
||||
struct UnitTime<'a> {
|
||||
unit: Unit<'a>,
|
||||
/// A string describing the cargo target.
|
||||
target: String,
|
||||
/// The time when this unit started as an offset in seconds from `Timings::start`.
|
||||
start: f64,
|
||||
/// Total time to build this unit in seconds.
|
||||
duration: f64,
|
||||
/// The time when the `.rmeta` file was generated, an offset in seconds
|
||||
/// from `start`.
|
||||
rmeta_time: Option<f64>,
|
||||
/// Reverse deps that are freed to run after this unit finished.
|
||||
unlocked_units: Vec<Unit<'a>>,
|
||||
/// Same as `unlocked_units`, but unlocked by rmeta.
|
||||
unlocked_rmeta_units: Vec<Unit<'a>>,
|
||||
}
|
||||
|
||||
/// Periodic concurrency tracking information.
|
||||
#[derive(serde::Serialize)]
|
||||
struct Concurrency {
|
||||
/// Time as an offset in seconds from `Timings::start`.
|
||||
t: f64,
|
||||
/// Number of units currently running.
|
||||
active: usize,
|
||||
/// Number of units that could run, but are waiting for a jobserver token.
|
||||
waiting: usize,
|
||||
/// Number of units that are not yet ready, because they are waiting for
|
||||
/// dependencies to finish.
|
||||
inactive: usize,
|
||||
}
|
||||
|
||||
impl<'a, 'cfg> Timings<'a, 'cfg> {
|
||||
pub fn new(bcx: &BuildContext<'a, 'cfg>, root_units: &[Unit<'_>]) -> Timings<'a, 'cfg> {
|
||||
let has_report = |what| {
|
||||
bcx.config
|
||||
.cli_unstable()
|
||||
.timings
|
||||
.as_ref()
|
||||
.map_or(false, |t| t.iter().any(|opt| opt == what))
|
||||
};
|
||||
let report_html = has_report("html");
|
||||
let report_info = has_report("info");
|
||||
let report_json = has_report("json");
|
||||
let enabled = report_html | report_info | report_json;
|
||||
|
||||
let mut root_map: HashMap<PackageId, Vec<String>> = HashMap::new();
|
||||
for unit in root_units {
|
||||
let target_desc = unit.target.description_named();
|
||||
root_map
|
||||
.entry(unit.pkg.package_id())
|
||||
.or_default()
|
||||
.push(target_desc);
|
||||
}
|
||||
let root_targets = root_map
|
||||
.into_iter()
|
||||
.map(|(pkg_id, targets)| {
|
||||
let pkg_desc = format!("{} {}", pkg_id.name(), pkg_id.version());
|
||||
(pkg_desc, targets)
|
||||
})
|
||||
.collect();
|
||||
let start_str = humantime::format_rfc3339_seconds(SystemTime::now()).to_string();
|
||||
let rustc_info = render_rustc_info(bcx);
|
||||
let profile = if bcx.build_config.release {
|
||||
"release"
|
||||
} else {
|
||||
"dev"
|
||||
}
|
||||
.to_string();
|
||||
|
||||
Timings {
|
||||
config: bcx.config,
|
||||
enabled,
|
||||
report_html,
|
||||
report_info,
|
||||
report_json,
|
||||
start: bcx.config.creation_time(),
|
||||
start_str,
|
||||
rustc_info,
|
||||
root_targets,
|
||||
profile,
|
||||
total_fresh: 0,
|
||||
total_dirty: 0,
|
||||
unit_times: Vec::new(),
|
||||
active: HashMap::new(),
|
||||
concurrency: Vec::new(),
|
||||
}
|
||||
}
|
||||
|
||||
/// Mark that a unit has started running.
|
||||
pub fn unit_start(&mut self, id: u32, unit: Unit<'a>) {
|
||||
if !self.enabled {
|
||||
return;
|
||||
}
|
||||
let mut target = if unit.target.is_lib() && unit.mode == CompileMode::Build {
|
||||
// Special case for brevity, since most dependencies hit
|
||||
// this path.
|
||||
"".to_string()
|
||||
} else {
|
||||
format!(" {}", unit.target.description_named())
|
||||
};
|
||||
match unit.mode {
|
||||
CompileMode::Test => target.push_str(" (test)"),
|
||||
CompileMode::Build => {}
|
||||
CompileMode::Check { test: true } => target.push_str(" (check-test)"),
|
||||
CompileMode::Check { test: false } => target.push_str(" (check)"),
|
||||
CompileMode::Bench => target.push_str(" (bench)"),
|
||||
CompileMode::Doc { .. } => target.push_str(" (doc)"),
|
||||
CompileMode::Doctest => target.push_str(" (doc test)"),
|
||||
CompileMode::RunCustomBuild => target.push_str(" (run)"),
|
||||
}
|
||||
let unit_time = UnitTime {
|
||||
unit,
|
||||
target,
|
||||
start: d_as_f64(self.start.elapsed()),
|
||||
duration: 0.0,
|
||||
rmeta_time: None,
|
||||
unlocked_units: Vec::new(),
|
||||
unlocked_rmeta_units: Vec::new(),
|
||||
};
|
||||
assert!(self.active.insert(id, unit_time).is_none());
|
||||
}
|
||||
|
||||
/// Mark that the `.rmeta` file as generated.
|
||||
pub fn unit_rmeta_finished(&mut self, id: u32, unlocked: Vec<&Unit<'a>>) {
|
||||
if !self.enabled {
|
||||
return;
|
||||
}
|
||||
// `id` may not always be active. "fresh" units unconditionally
|
||||
// generate `Message::Finish`, but this active map only tracks dirty
|
||||
// units.
|
||||
let unit_time = match self.active.get_mut(&id) {
|
||||
Some(ut) => ut,
|
||||
None => return,
|
||||
};
|
||||
let t = d_as_f64(self.start.elapsed());
|
||||
unit_time.rmeta_time = Some(t - unit_time.start);
|
||||
assert!(unit_time.unlocked_rmeta_units.is_empty());
|
||||
unit_time.unlocked_rmeta_units.extend(unlocked);
|
||||
}
|
||||
|
||||
/// Mark that a unit has finished running.
|
||||
pub fn unit_finished(&mut self, id: u32, unlocked: Vec<&Unit<'a>>) {
|
||||
if !self.enabled {
|
||||
return;
|
||||
}
|
||||
// See note above in `unit_rmeta_finished`, this may not always be active.
|
||||
let mut unit_time = match self.active.remove(&id) {
|
||||
Some(ut) => ut,
|
||||
None => return,
|
||||
};
|
||||
let t = d_as_f64(self.start.elapsed());
|
||||
unit_time.duration = t - unit_time.start;
|
||||
assert!(unit_time.unlocked_units.is_empty());
|
||||
unit_time.unlocked_units.extend(unlocked);
|
||||
if self.report_info {
|
||||
let msg = format!(
|
||||
"{}{} in {:.1}s",
|
||||
unit_time.name_ver(),
|
||||
unit_time.target,
|
||||
unit_time.duration
|
||||
);
|
||||
let _ = self
|
||||
.config
|
||||
.shell()
|
||||
.status_with_color("Completed", msg, termcolor::Color::Cyan);
|
||||
}
|
||||
if self.report_json {
|
||||
let msg = machine_message::TimingInfo {
|
||||
package_id: unit_time.unit.pkg.package_id(),
|
||||
target: unit_time.unit.target,
|
||||
mode: unit_time.unit.mode,
|
||||
duration: unit_time.duration,
|
||||
rmeta_time: unit_time.rmeta_time,
|
||||
}
|
||||
.to_json_string();
|
||||
self.config.shell().stdout_println(msg);
|
||||
}
|
||||
self.unit_times.push(unit_time);
|
||||
}
|
||||
|
||||
/// This is called periodically to mark the concurrency of internal structures.
|
||||
pub fn mark_concurrency(&mut self, active: usize, waiting: usize, inactive: usize) {
|
||||
if !self.enabled {
|
||||
return;
|
||||
}
|
||||
let c = Concurrency {
|
||||
t: d_as_f64(self.start.elapsed()),
|
||||
active,
|
||||
waiting,
|
||||
inactive,
|
||||
};
|
||||
self.concurrency.push(c);
|
||||
}
|
||||
|
||||
/// Mark that a fresh unit was encountered.
|
||||
pub fn add_fresh(&mut self) {
|
||||
self.total_fresh += 1;
|
||||
}
|
||||
|
||||
/// Mark that a dirty unit was encountered.
|
||||
pub fn add_dirty(&mut self) {
|
||||
self.total_dirty += 1;
|
||||
}
|
||||
|
||||
/// Call this when all units are finished.
|
||||
pub fn finished(&mut self) -> CargoResult<()> {
|
||||
if !self.enabled {
|
||||
return Ok(());
|
||||
}
|
||||
self.mark_concurrency(0, 0, 0);
|
||||
self.unit_times
|
||||
.sort_unstable_by(|a, b| a.start.partial_cmp(&b.start).unwrap());
|
||||
if self.report_html {
|
||||
self.report_html()?;
|
||||
}
|
||||
Ok(())
|
||||
}
|
||||
|
||||
/// Save HTML report to disk.
|
||||
fn report_html(&self) -> CargoResult<()> {
|
||||
let duration = self.start.elapsed().as_secs() as u32 + 1;
|
||||
let timestamp = self.start_str.replace(&['-', ':'][..], "");
|
||||
let filename = format!("cargo-timing-{}.html", timestamp);
|
||||
let mut f = BufWriter::new(File::create(&filename)?);
|
||||
let roots: Vec<&str> = self
|
||||
.root_targets
|
||||
.iter()
|
||||
.map(|(name, _targets)| name.as_str())
|
||||
.collect();
|
||||
f.write_all(HTML_TMPL.replace("{ROOTS}", &roots.join(", ")).as_bytes())?;
|
||||
self.write_summary_table(&mut f, duration)?;
|
||||
f.write_all(HTML_CANVAS.as_bytes())?;
|
||||
self.write_unit_table(&mut f)?;
|
||||
writeln!(
|
||||
f,
|
||||
"<script>\n\
|
||||
DURATION = {};",
|
||||
duration
|
||||
)?;
|
||||
self.write_js_data(&mut f)?;
|
||||
write!(
|
||||
f,
|
||||
"{}\n\
|
||||
</script>\n\
|
||||
</body>\n\
|
||||
</html>\n\
|
||||
",
|
||||
include_str!("timings.js")
|
||||
)?;
|
||||
drop(f);
|
||||
let msg = format!(
|
||||
"report saved to {}",
|
||||
std::env::current_dir()
|
||||
.unwrap_or_default()
|
||||
.join(&filename)
|
||||
.display()
|
||||
);
|
||||
paths::link_or_copy(&filename, "cargo-timing.html")?;
|
||||
self.config
|
||||
.shell()
|
||||
.status_with_color("Timing", msg, termcolor::Color::Cyan)?;
|
||||
Ok(())
|
||||
}
|
||||
|
||||
/// Render the summary table.
|
||||
fn write_summary_table(&self, f: &mut impl Write, duration: u32) -> CargoResult<()> {
|
||||
let targets: Vec<String> = self
|
||||
.root_targets
|
||||
.iter()
|
||||
.map(|(name, targets)| format!("{} ({})", name, targets.join(", ")))
|
||||
.collect();
|
||||
let targets = targets.join("<br>");
|
||||
let time_human = if duration > 60 {
|
||||
format!(" ({}m {:02}s)", duration / 60, duration % 60)
|
||||
} else {
|
||||
"".to_string()
|
||||
};
|
||||
let total_time = format!("{}s{}", duration, time_human);
|
||||
let max_concurrency = self.concurrency.iter().map(|c| c.active).max().unwrap();
|
||||
write!(
|
||||
f,
|
||||
r#"
|
||||
<table class="my-table summary-table">
|
||||
<tr>
|
||||
<td>Targets:</td><td>{}</td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td>Profile:</td><td>{}</td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td>Fresh units:</td><td>{}</td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td>Dirty units:</td><td>{}</td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td>Total units:</td><td>{}</td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td>Max concurrency:</td><td>{}</td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td>Build start:</td><td>{}</td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td>Total time:</td><td>{}</td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td>rustc:</td><td>{}</td>
|
||||
</tr>
|
||||
|
||||
</table>
|
||||
"#,
|
||||
targets,
|
||||
self.profile,
|
||||
self.total_fresh,
|
||||
self.total_dirty,
|
||||
self.total_fresh + self.total_dirty,
|
||||
max_concurrency,
|
||||
self.start_str,
|
||||
total_time,
|
||||
self.rustc_info,
|
||||
)?;
|
||||
Ok(())
|
||||
}
|
||||
|
||||
fn write_js_data(&self, f: &mut impl Write) -> CargoResult<()> {
|
||||
// Create a map to link indices of unlocked units.
|
||||
let unit_map: HashMap<Unit<'_>, usize> = self
|
||||
.unit_times
|
||||
.iter()
|
||||
.enumerate()
|
||||
.map(|(i, ut)| (ut.unit, i))
|
||||
.collect();
|
||||
#[derive(serde::Serialize)]
|
||||
struct UnitData {
|
||||
i: usize,
|
||||
name: String,
|
||||
version: String,
|
||||
mode: String,
|
||||
target: String,
|
||||
start: f64,
|
||||
duration: f64,
|
||||
rmeta_time: Option<f64>,
|
||||
unlocked_units: Vec<usize>,
|
||||
unlocked_rmeta_units: Vec<usize>,
|
||||
}
|
||||
let round = |x: f64| (x * 100.0).round() / 100.0;
|
||||
let unit_data: Vec<UnitData> = self
|
||||
.unit_times
|
||||
.iter()
|
||||
.enumerate()
|
||||
.map(|(i, ut)| {
|
||||
let mode = if ut.unit.mode.is_run_custom_build() {
|
||||
"run-custom-build"
|
||||
} else {
|
||||
"todo"
|
||||
}
|
||||
.to_string();
|
||||
let unlocked_units: Vec<usize> = ut
|
||||
.unlocked_units
|
||||
.iter()
|
||||
.map(|unit| unit_map[unit])
|
||||
.collect();
|
||||
let unlocked_rmeta_units: Vec<usize> = ut
|
||||
.unlocked_rmeta_units
|
||||
.iter()
|
||||
.map(|unit| unit_map[unit])
|
||||
.collect();
|
||||
UnitData {
|
||||
i,
|
||||
name: ut.unit.pkg.name().to_string(),
|
||||
version: ut.unit.pkg.version().to_string(),
|
||||
mode,
|
||||
target: ut.target.clone(),
|
||||
start: round(ut.start),
|
||||
duration: round(ut.duration),
|
||||
rmeta_time: ut.rmeta_time.map(|t| round(t)),
|
||||
unlocked_units,
|
||||
unlocked_rmeta_units,
|
||||
}
|
||||
})
|
||||
.collect();
|
||||
writeln!(
|
||||
f,
|
||||
"const UNIT_DATA = {};",
|
||||
serde_json::to_string_pretty(&unit_data)?
|
||||
)?;
|
||||
writeln!(
|
||||
f,
|
||||
"const CONCURRENCY_DATA = {};",
|
||||
serde_json::to_string_pretty(&self.concurrency)?
|
||||
)?;
|
||||
Ok(())
|
||||
}
|
||||
|
||||
/// Render the table of all units.
|
||||
fn write_unit_table(&self, f: &mut impl Write) -> CargoResult<()> {
|
||||
write!(
|
||||
f,
|
||||
r#"
|
||||
<table class="my-table">
|
||||
<thead>
|
||||
<tr>
|
||||
<th></th>
|
||||
<th>Unit</th>
|
||||
<th>Total</th>
|
||||
<th>Codegen</th>
|
||||
<th>Features</th>
|
||||
</tr>
|
||||
</thead>
|
||||
<tbody>
|
||||
"#
|
||||
)?;
|
||||
let mut units: Vec<&UnitTime<'_>> = self.unit_times.iter().collect();
|
||||
units.sort_unstable_by(|a, b| b.duration.partial_cmp(&a.duration).unwrap());
|
||||
for (i, unit) in units.iter().enumerate() {
|
||||
let codegen = match unit.codegen_time() {
|
||||
None => "".to_string(),
|
||||
Some((_rt, ctime, cent)) => format!("{:.1}s ({:.0}%)", ctime, cent),
|
||||
};
|
||||
let features = unit.unit.features.join(", ");
|
||||
write!(
|
||||
f,
|
||||
r#"
|
||||
<tr>
|
||||
<td>{}.</td>
|
||||
<td>{}{}</td>
|
||||
<td>{:.1}s</td>
|
||||
<td>{}</td>
|
||||
<td>{}</td>
|
||||
</tr>
|
||||
"#,
|
||||
i + 1,
|
||||
unit.name_ver(),
|
||||
unit.target,
|
||||
unit.duration,
|
||||
codegen,
|
||||
features,
|
||||
)?;
|
||||
}
|
||||
write!(f, "</tbody>\n</table>\n")?;
|
||||
Ok(())
|
||||
}
|
||||
}
|
||||
|
||||
impl<'a> UnitTime<'a> {
|
||||
/// Returns the codegen time as (rmeta_time, codegen_time, percent of total)
|
||||
fn codegen_time(&self) -> Option<(f64, f64, f64)> {
|
||||
self.rmeta_time.map(|rmeta_time| {
|
||||
let ctime = self.duration - rmeta_time;
|
||||
let cent = (ctime / self.duration) * 100.0;
|
||||
(rmeta_time, ctime, cent)
|
||||
})
|
||||
}
|
||||
|
||||
fn name_ver(&self) -> String {
|
||||
format!("{} v{}", self.unit.pkg.name(), self.unit.pkg.version())
|
||||
}
|
||||
}
|
||||
|
||||
// Replace with as_secs_f64 when 1.38 hits stable.
|
||||
fn d_as_f64(d: Duration) -> f64 {
|
||||
(d.as_secs() as f64) + f64::from(d.subsec_nanos()) / 1_000_000_000.0
|
||||
}
|
||||
|
||||
fn render_rustc_info(bcx: &BuildContext<'_, '_>) -> String {
|
||||
let version = bcx
|
||||
.rustc
|
||||
.verbose_version
|
||||
.lines()
|
||||
.next()
|
||||
.expect("rustc version");
|
||||
let requested_target = bcx
|
||||
.build_config
|
||||
.requested_target
|
||||
.as_ref()
|
||||
.map_or("Host", String::as_str);
|
||||
format!(
|
||||
"{}<br>Host: {}<br>Target: {}",
|
||||
version, bcx.rustc.host, requested_target
|
||||
)
|
||||
}
|
||||
|
||||
static HTML_TMPL: &str = r#"
|
||||
<html>
|
||||
<head>
|
||||
<title>Cargo Build Timings — {ROOTS}</title>
|
||||
<meta charset="utf-8">
|
||||
<style type="text/css">
|
||||
html {
|
||||
font-family: sans-serif;
|
||||
}
|
||||
|
||||
.canvas-container {
|
||||
position: relative;
|
||||
margin-top: 5px;
|
||||
margin-bottom: 5px;
|
||||
}
|
||||
|
||||
h1 {
|
||||
border-bottom: 1px solid #c0c0c0;
|
||||
}
|
||||
|
||||
.graph {
|
||||
display: block;
|
||||
}
|
||||
|
||||
.my-table {
|
||||
margin-top: 20px;
|
||||
margin-bottom: 20px;
|
||||
border-collapse: collapse;
|
||||
box-shadow: 0 5px 10px rgba(0, 0, 0, 0.1);
|
||||
}
|
||||
|
||||
.my-table th {
|
||||
color: #d5dde5;
|
||||
background: #1b1e24;
|
||||
border-bottom: 4px solid #9ea7af;
|
||||
border-right: 1px solid #343a45;
|
||||
font-size: 18px;
|
||||
font-weight: 100;
|
||||
padding: 12px;
|
||||
text-align: left;
|
||||
vertical-align: middle;
|
||||
}
|
||||
|
||||
.my-table th:first-child {
|
||||
border-top-left-radius: 3px;
|
||||
}
|
||||
|
||||
.my-table th:last-child {
|
||||
border-top-right-radius: 3px;
|
||||
border-right:none;
|
||||
}
|
||||
|
||||
.my-table tr {
|
||||
border-top: 1px solid #c1c3d1;
|
||||
border-bottom: 1px solid #c1c3d1;
|
||||
font-size: 16px;
|
||||
font-weight: normal;
|
||||
}
|
||||
|
||||
.my-table tr:first-child {
|
||||
border-top:none;
|
||||
}
|
||||
|
||||
.my-table tr:last-child {
|
||||
border-bottom:none;
|
||||
}
|
||||
|
||||
.my-table tr:nth-child(odd) td {
|
||||
background: #ebebeb;
|
||||
}
|
||||
|
||||
.my-table tr:last-child td:first-child {
|
||||
border-bottom-left-radius:3px;
|
||||
}
|
||||
|
||||
.my-table tr:last-child td:last-child {
|
||||
border-bottom-right-radius:3px;
|
||||
}
|
||||
|
||||
.my-table td {
|
||||
background: #ffffff;
|
||||
padding: 10px;
|
||||
text-align: left;
|
||||
vertical-align: middle;
|
||||
font-weight: 300;
|
||||
font-size: 14px;
|
||||
border-right: 1px solid #C1C3D1;
|
||||
}
|
||||
|
||||
.my-table td:last-child {
|
||||
border-right: 0px;
|
||||
}
|
||||
|
||||
.summary-table td:first-child {
|
||||
vertical-align: top;
|
||||
text-align: right;
|
||||
}
|
||||
|
||||
.input-table td {
|
||||
text-align: center;
|
||||
}
|
||||
|
||||
</style>
|
||||
</head>
|
||||
<body>
|
||||
|
||||
<h1>Cargo Build Timings</h1>
|
||||
"#;
|
||||
|
||||
static HTML_CANVAS: &str = r#"
|
||||
<table class="input-table">
|
||||
<tr>
|
||||
<td><label for="min-unit-time">Min unit time:</label></td>
|
||||
<td><label for="scale">Scale:</label></td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td><input type="range" min="0" max="30" step="0.1" value="0" id="min-unit-time"></td>
|
||||
<td><input type="range" min="1" max="50" value="20" id="scale"></td>
|
||||
</tr>
|
||||
<tr>
|
||||
<td><output for="min-unit-time" id="min-unit-time-output"></output></td>
|
||||
<td><output for="scale" id="scale-output"></output></td>
|
||||
</tr>
|
||||
</table>
|
||||
|
||||
<div id="pipeline-container" class="canvas-container">
|
||||
<canvas id="pipeline-graph" class="graph" style="position: absolute; left: 0; top: 0; z-index: 0;"></canvas>
|
||||
<canvas id="pipeline-graph-lines" style="position: absolute; left: 0; top: 0; z-index: 1; pointer-events:none;"></canvas>
|
||||
</div>
|
||||
<div class="canvas-container">
|
||||
<canvas id="timing-graph" class="graph"></canvas>
|
||||
</div>
|
||||
"#;
|
||||
|
|
@ -335,6 +335,7 @@ pub struct CliUnstable {
|
|||
pub cache_messages: bool,
|
||||
pub binary_dep_depinfo: bool,
|
||||
pub build_std: Option<Vec<String>>,
|
||||
pub timings: Option<Vec<String>>,
|
||||
}
|
||||
|
||||
impl CliUnstable {
|
||||
|
|
@ -367,6 +368,13 @@ impl CliUnstable {
|
|||
}
|
||||
}
|
||||
|
||||
fn parse_timings(value: Option<&str>) -> Vec<String> {
|
||||
match value {
|
||||
None => vec!["html".to_string(), "info".to_string()],
|
||||
Some(v) => v.split(',').map(|s| s.to_string()).collect(),
|
||||
}
|
||||
}
|
||||
|
||||
match k {
|
||||
"print-im-a-teapot" => self.print_im_a_teapot = parse_bool(v)?,
|
||||
"unstable-options" => self.unstable_options = true,
|
||||
|
|
@ -384,6 +392,7 @@ impl CliUnstable {
|
|||
"build-std" => {
|
||||
self.build_std = Some(crate::core::compiler::standard_lib::parse_unstable_flag(v))
|
||||
}
|
||||
"timings" => self.timings = Some(parse_timings(v)),
|
||||
_ => failure::bail!("unknown `-Z` flag specified: {}", k),
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -926,6 +926,19 @@ impl Target {
|
|||
self.doc = doc;
|
||||
self
|
||||
}
|
||||
|
||||
pub fn description_named(&self) -> String {
|
||||
match self.kind {
|
||||
TargetKind::Lib(..) => "lib".to_string(),
|
||||
TargetKind::Bin => format!("bin \"{}\"", self.name()),
|
||||
TargetKind::Test => format!("test \"{}\"", self.name()),
|
||||
TargetKind::Bench => format!("bench \"{}\"", self.name()),
|
||||
TargetKind::ExampleLib(..) | TargetKind::ExampleBin => {
|
||||
format!("example \"{}\"", self.name())
|
||||
}
|
||||
TargetKind::CustomBuild => "custom-build".to_string(),
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
impl fmt::Display for Target {
|
||||
|
|
|
|||
|
|
@ -111,6 +111,13 @@ impl Shell {
|
|||
}
|
||||
}
|
||||
|
||||
pub fn stdout_println(&mut self, message: impl fmt::Display) {
|
||||
if self.needs_clear {
|
||||
self.err_erase_line();
|
||||
}
|
||||
println!("{}", message);
|
||||
}
|
||||
|
||||
/// Sets whether the next print should clear the current line.
|
||||
pub fn set_needs_clear(&mut self, needs_clear: bool) {
|
||||
self.needs_clear = needs_clear;
|
||||
|
|
|
|||
|
|
@ -16,6 +16,7 @@
|
|||
#![allow(clippy::too_many_arguments)] // large project
|
||||
#![allow(clippy::type_complexity)] // there's an exceptionally complex type
|
||||
#![allow(clippy::wrong_self_convention)] // perhaps `Rc` should be special-cased in Clippy?
|
||||
#![allow(clippy::write_with_newline)] // too pedantic
|
||||
#![warn(clippy::needless_borrow)]
|
||||
#![warn(clippy::redundant_clone)]
|
||||
// Unit is now interned, and would probably be better as pass-by-copy, but
|
||||
|
|
|
|||
|
|
@ -159,16 +159,26 @@ impl<N: Hash + Eq + Clone, E: Eq + Hash + Clone, V> DependencyQueue<N, E, V> {
|
|||
/// Calling this function indicates that the `node` has produced `edge`. All
|
||||
/// remaining work items which only depend on this node/edge pair are now
|
||||
/// candidates to start their job.
|
||||
pub fn finish(&mut self, node: &N, edge: &E) {
|
||||
///
|
||||
/// Returns the nodes that are now allowed to be dequeued as a result of
|
||||
/// finishing this node.
|
||||
pub fn finish(&mut self, node: &N, edge: &E) -> Vec<&N> {
|
||||
// hashset<Node>
|
||||
let reverse_deps = self.reverse_dep_map.get(node).and_then(|map| map.get(edge));
|
||||
let reverse_deps = match reverse_deps {
|
||||
Some(deps) => deps,
|
||||
None => return,
|
||||
None => return Vec::new(),
|
||||
};
|
||||
let key = (node.clone(), edge.clone());
|
||||
let mut result = Vec::new();
|
||||
for dep in reverse_deps.iter() {
|
||||
assert!(self.dep_map.get_mut(dep).unwrap().0.remove(&key));
|
||||
let edges = &mut self.dep_map.get_mut(dep).unwrap().0;
|
||||
assert!(edges.remove(&key));
|
||||
if edges.is_empty() {
|
||||
result.push(dep);
|
||||
}
|
||||
}
|
||||
result
|
||||
}
|
||||
}
|
||||
|
||||
|
|
|
|||
|
|
@ -4,7 +4,7 @@ use serde::ser;
|
|||
use serde::Serialize;
|
||||
use serde_json::{self, json, value::RawValue};
|
||||
|
||||
use crate::core::{PackageId, Target};
|
||||
use crate::core::{compiler::CompileMode, PackageId, Target};
|
||||
|
||||
pub trait Message: ser::Serialize {
|
||||
fn reason(&self) -> &str;
|
||||
|
|
@ -73,3 +73,19 @@ impl<'a> Message for BuildScript<'a> {
|
|||
"build-script-executed"
|
||||
}
|
||||
}
|
||||
|
||||
#[derive(Serialize)]
|
||||
pub struct TimingInfo<'a> {
|
||||
pub package_id: PackageId,
|
||||
pub target: &'a Target,
|
||||
pub mode: CompileMode,
|
||||
pub duration: f64,
|
||||
#[serde(skip_serializing_if = "Option::is_none")]
|
||||
pub rmeta_time: Option<f64>,
|
||||
}
|
||||
|
||||
impl<'a> Message for TimingInfo<'a> {
|
||||
fn reason(&self) -> &str {
|
||||
"timing-info"
|
||||
}
|
||||
}
|
||||
|
|
|
|||
|
|
@ -340,3 +340,63 @@ fn set_not_readonly(p: &Path) -> io::Result<bool> {
|
|||
fs::set_permissions(p, perms)?;
|
||||
Ok(true)
|
||||
}
|
||||
|
||||
/// Hardlink (file) or symlink (dir) src to dst if possible, otherwise copy it.
|
||||
///
|
||||
/// If the destination already exists, it is removed before linking.
|
||||
pub fn link_or_copy(src: impl AsRef<Path>, dst: impl AsRef<Path>) -> CargoResult<()> {
|
||||
let src = src.as_ref();
|
||||
let dst = dst.as_ref();
|
||||
_link_or_copy(src, dst)
|
||||
}
|
||||
|
||||
fn _link_or_copy(src: &Path, dst: &Path) -> CargoResult<()> {
|
||||
log::debug!("linking {} to {}", src.display(), dst.display());
|
||||
if same_file::is_same_file(src, dst).unwrap_or(false) {
|
||||
return Ok(());
|
||||
}
|
||||
|
||||
// NB: we can't use dst.exists(), as if dst is a broken symlink,
|
||||
// dst.exists() will return false. This is problematic, as we still need to
|
||||
// unlink dst in this case. symlink_metadata(dst).is_ok() will tell us
|
||||
// whether dst exists *without* following symlinks, which is what we want.
|
||||
if fs::symlink_metadata(dst).is_ok() {
|
||||
remove_file(&dst)?;
|
||||
}
|
||||
|
||||
let link_result = if src.is_dir() {
|
||||
#[cfg(target_os = "redox")]
|
||||
use std::os::redox::fs::symlink;
|
||||
#[cfg(unix)]
|
||||
use std::os::unix::fs::symlink;
|
||||
#[cfg(windows)]
|
||||
// FIXME: This should probably panic or have a copy fallback. Symlinks
|
||||
// are not supported in all windows environments. Currently symlinking
|
||||
// is only used for .dSYM directories on macos, but this shouldn't be
|
||||
// accidentally relied upon.
|
||||
use std::os::windows::fs::symlink_dir as symlink;
|
||||
|
||||
let dst_dir = dst.parent().unwrap();
|
||||
let src = if src.starts_with(dst_dir) {
|
||||
src.strip_prefix(dst_dir).unwrap()
|
||||
} else {
|
||||
src
|
||||
};
|
||||
symlink(src, dst)
|
||||
} else {
|
||||
fs::hard_link(src, dst)
|
||||
};
|
||||
link_result
|
||||
.or_else(|err| {
|
||||
log::debug!("link failed {}. falling back to fs::copy", err);
|
||||
fs::copy(src, dst).map(|_| ())
|
||||
})
|
||||
.chain_err(|| {
|
||||
format!(
|
||||
"failed to link or copy `{}` to `{}`",
|
||||
src.display(),
|
||||
dst.display()
|
||||
)
|
||||
})?;
|
||||
Ok(())
|
||||
}
|
||||
|
|
|
|||
|
|
@ -336,3 +336,63 @@ Also if you'd like to see a feature that's not yet implemented and/or if
|
|||
something doesn't quite work the way you'd like it to, feel free to check out
|
||||
the [issue tracker](https://github.com/rust-lang/wg-cargo-std-aware/issues) of
|
||||
the tracking repository, and if it's not there please file a new issue!
|
||||
|
||||
### timings
|
||||
|
||||
The `timings` feature gives some information about how long each compilation
|
||||
takes, and tracks concurrency information over time.
|
||||
|
||||
```
|
||||
cargo +nightly build -Z timings
|
||||
```
|
||||
|
||||
The `-Ztimings` flag can optionally take a comma-separated list of the
|
||||
following values:
|
||||
|
||||
- `html` — Saves a file called `cargo-timing.html` to the current directory
|
||||
with a report of the compilation. Files are also saved with a timestamp in
|
||||
the filename if you want to look at older runs.
|
||||
- `info` — Displays a message to stdout after each compilation finishes with
|
||||
how long it took.
|
||||
- `json` — Emits some JSON information about timing information.
|
||||
|
||||
The default if none are specified is `html,info`.
|
||||
|
||||
#### Reading the graphs
|
||||
|
||||
There are two graphs in the output. The "unit" graph shows the duration of
|
||||
each unit over time. A "unit" is a single compiler invocation. There are lines
|
||||
that show which additional units are "unlocked" when a unit finishes. That is,
|
||||
it shows the new units that are now allowed to run because their dependencies
|
||||
are all finished. Hover the mouse over a unit to highlight the lines. This can
|
||||
help visualize the critical path of dependencies. This may change between runs
|
||||
because the units may finish in different orders.
|
||||
|
||||
The "codegen" times are highlighted in a lavender color. In some cases, build
|
||||
pipelining allows units to start when their dependencies are performing code
|
||||
generation. This information is not always displayed (for example, binary
|
||||
units do not show when code generation starts).
|
||||
|
||||
The "custom build" units are `build.rs` scripts, which when run are
|
||||
highlighted in orange.
|
||||
|
||||
The second graph shows Cargo's concurrency over time. The three lines are:
|
||||
- "Waiting" (red) — This is the number of units waiting for a CPU slot to
|
||||
open.
|
||||
- "Inactive" (blue) — This is the number of units that are waiting for their
|
||||
dependencies to finish.
|
||||
- "Active" (green) — This is the number of units currently running.
|
||||
|
||||
Note: This does not show the concurrency in the compiler itself. `rustc`
|
||||
coordinates with Cargo via the "job server" to stay within the concurrency
|
||||
limit. This currently mostly applies to the code generation phase.
|
||||
|
||||
Tips for addressing compile times:
|
||||
- Look for slow dependencies.
|
||||
- Check if they have features that you may wish to consider disabling.
|
||||
- Consider trying to remove the dependency completely.
|
||||
- Look for a crate being built multiple times with different versions. Try to
|
||||
remove the older versions from the dependency graph.
|
||||
- Split large crates into smaller pieces.
|
||||
- If there are a large number of crates bottlenecked on a single crate, focus
|
||||
your attention on improving that one crate to improve parallelism.
|
||||
|
|
|
|||
Loading…
Reference in a new issue