3 //! This module implements some simple tracking information for timing of how
4 //! long it takes for different units to compile.
5 use super::{CompileMode, Unit}
;
6 use crate::core
::compiler
::job_queue
::JobId
;
7 use crate::core
::compiler
::{BuildContext, Context, TimingOutput}
;
8 use crate::core
::PackageId
;
9 use crate::util
::cpu
::State
;
10 use crate::util
::machine_message
::{self, Message}
;
11 use crate::util
::{CargoResult, Config}
;
12 use anyhow
::Context
as _
;
13 use cargo_util
::paths
;
14 use std
::collections
::HashMap
;
15 use std
::io
::{BufWriter, Write}
;
16 use std
::thread
::available_parallelism
;
17 use std
::time
::{Duration, Instant, SystemTime}
;
19 pub struct Timings
<'cfg
> {
21 /// Whether or not timings should be captured.
23 /// If true, saves an HTML report to disk.
25 /// If true, emits JSON information with timing information.
27 /// When Cargo started.
29 /// A rendered string of when compilation started.
31 /// A summary of the root units.
33 /// Tuples of `(package_description, target_descrptions)`.
34 root_targets
: Vec
<(String
, Vec
<String
>)>,
35 /// The build profile.
37 /// Total number of fresh units.
39 /// Total number of dirty units.
41 /// Time tracking for each individual unit.
42 unit_times
: Vec
<UnitTime
>,
43 /// Units that are in the process of being built.
44 /// When they finished, they are moved to `unit_times`.
45 active
: HashMap
<JobId
, UnitTime
>,
46 /// Concurrency-tracking information. This is periodically updated while
47 /// compilation progresses.
48 concurrency
: Vec
<Concurrency
>,
49 /// Last recorded state of the system's CPUs and when it happened
50 last_cpu_state
: Option
<State
>,
51 last_cpu_recording
: Instant
,
52 /// Recorded CPU states, stored as tuples. First element is when the
53 /// recording was taken and second element is percentage usage of the
55 cpu_usage
: Vec
<(f64, f64)>,
58 /// Tracking information for an individual unit.
61 /// A string describing the cargo target.
63 /// The time when this unit started as an offset in seconds from `Timings::start`.
65 /// Total time to build this unit in seconds.
67 /// The time when the `.rmeta` file was generated, an offset in seconds
69 rmeta_time
: Option
<f64>,
70 /// Reverse deps that are freed to run after this unit finished.
71 unlocked_units
: Vec
<Unit
>,
72 /// Same as `unlocked_units`, but unlocked by rmeta.
73 unlocked_rmeta_units
: Vec
<Unit
>,
76 /// Periodic concurrency tracking information.
77 #[derive(serde::Serialize)]
79 /// Time as an offset in seconds from `Timings::start`.
81 /// Number of units currently running.
83 /// Number of units that could run, but are waiting for a jobserver token.
85 /// Number of units that are not yet ready, because they are waiting for
86 /// dependencies to finish.
88 /// Number of rustc "extra" threads -- i.e., how many tokens have been
89 /// provided across all current rustc instances that are not the main thread
91 rustc_parallelism
: usize,
94 impl<'cfg
> Timings
<'cfg
> {
95 pub fn new(bcx
: &BuildContext
<'_
, 'cfg
>, root_units
: &[Unit
]) -> Timings
<'cfg
> {
96 let has_report
= |what
| bcx
.build_config
.timing_outputs
.contains(&what
);
97 let report_html
= has_report(TimingOutput
::Html
);
98 let report_json
= has_report(TimingOutput
::Json
);
99 let enabled
= report_html
| report_json
;
101 let mut root_map
: HashMap
<PackageId
, Vec
<String
>> = HashMap
::new();
102 for unit
in root_units
{
103 let target_desc
= unit
.target
.description_named();
105 .entry(unit
.pkg
.package_id())
109 let root_targets
= root_map
111 .map(|(pkg_id
, targets
)| {
112 let pkg_desc
= format
!("{} {}", pkg_id
.name(), pkg_id
.version());
116 let start_str
= humantime
::format_rfc3339_seconds(SystemTime
::now()).to_string();
117 let profile
= bcx
.build_config
.requested_profile
.to_string();
118 let last_cpu_state
= if enabled
{
119 match State
::current() {
120 Ok(state
) => Some(state
),
122 log
::info
!("failed to get CPU state, CPU tracking disabled: {:?}", e
);
135 start
: bcx
.config
.creation_time(),
141 unit_times
: Vec
::new(),
142 active
: HashMap
::new(),
143 concurrency
: Vec
::new(),
145 last_cpu_recording
: Instant
::now(),
146 cpu_usage
: Vec
::new(),
150 /// Mark that a unit has started running.
151 pub fn unit_start(&mut self, id
: JobId
, unit
: Unit
) {
155 let mut target
= if unit
.target
.is_lib() && unit
.mode
== CompileMode
::Build
{
156 // Special case for brevity, since most dependencies hit
160 format
!(" {}", unit
.target
.description_named())
163 CompileMode
::Test
=> target
.push_str(" (test)"),
164 CompileMode
::Build
=> {}
165 CompileMode
::Check { test: true }
=> target
.push_str(" (check-test)"),
166 CompileMode
::Check { test: false }
=> target
.push_str(" (check)"),
167 CompileMode
::Bench
=> target
.push_str(" (bench)"),
168 CompileMode
::Doc { .. }
=> target
.push_str(" (doc)"),
169 CompileMode
::Doctest
=> target
.push_str(" (doc test)"),
170 CompileMode
::Docscrape
=> target
.push_str(" (doc scrape)"),
171 CompileMode
::RunCustomBuild
=> target
.push_str(" (run)"),
173 let unit_time
= UnitTime
{
176 start
: self.start
.elapsed().as_secs_f64(),
179 unlocked_units
: Vec
::new(),
180 unlocked_rmeta_units
: Vec
::new(),
182 assert
!(self.active
.insert(id
, unit_time
).is_none());
185 /// Mark that the `.rmeta` file as generated.
186 pub fn unit_rmeta_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
>) {
190 // `id` may not always be active. "fresh" units unconditionally
191 // generate `Message::Finish`, but this active map only tracks dirty
193 let unit_time
= match self.active
.get_mut(&id
) {
197 let t
= self.start
.elapsed().as_secs_f64();
198 unit_time
.rmeta_time
= Some(t
- unit_time
.start
);
199 assert
!(unit_time
.unlocked_rmeta_units
.is_empty());
201 .unlocked_rmeta_units
202 .extend(unlocked
.iter().cloned().cloned());
205 /// Mark that a unit has finished running.
206 pub fn unit_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
>) {
210 // See note above in `unit_rmeta_finished`, this may not always be active.
211 let mut unit_time
= match self.active
.remove(&id
) {
215 let t
= self.start
.elapsed().as_secs_f64();
216 unit_time
.duration
= t
- unit_time
.start
;
217 assert
!(unit_time
.unlocked_units
.is_empty());
220 .extend(unlocked
.iter().cloned().cloned());
221 if self.report_json
{
222 let msg
= machine_message
::TimingInfo
{
223 package_id
: unit_time
.unit
.pkg
.package_id(),
224 target
: &unit_time
.unit
.target
,
225 mode
: unit_time
.unit
.mode
,
226 duration
: unit_time
.duration
,
227 rmeta_time
: unit_time
.rmeta_time
,
230 crate::drop_println
!(self.config
, "{}", msg
);
232 self.unit_times
.push(unit_time
);
235 /// This is called periodically to mark the concurrency of internal structures.
236 pub fn mark_concurrency(
241 rustc_parallelism
: usize,
246 let c
= Concurrency
{
247 t
: self.start
.elapsed().as_secs_f64(),
253 self.concurrency
.push(c
);
256 /// Mark that a fresh unit was encountered.
257 pub fn add_fresh(&mut self) {
258 self.total_fresh
+= 1;
261 /// Mark that a dirty unit was encountered.
262 pub fn add_dirty(&mut self) {
263 self.total_dirty
+= 1;
266 /// Take a sample of CPU usage
267 pub fn record_cpu(&mut self) {
271 let prev
= match &mut self.last_cpu_state
{
272 Some(state
) => state
,
275 // Don't take samples too too frequently, even if requested.
276 let now
= Instant
::now();
277 if self.last_cpu_recording
.elapsed() < Duration
::from_millis(100) {
280 let current
= match State
::current() {
283 log
::info
!("failed to get CPU state: {:?}", e
);
287 let pct_idle
= current
.idle_since(prev
);
289 self.last_cpu_recording
= now
;
290 let dur
= now
.duration_since(self.start
).as_secs_f64();
291 self.cpu_usage
.push((dur
, 100.0 - pct_idle
));
294 /// Call this when all units are finished.
297 cx
: &Context
<'_
, '_
>,
298 error
: &Option
<anyhow
::Error
>,
299 ) -> CargoResult
<()> {
303 self.mark_concurrency(0, 0, 0, 0);
305 .sort_unstable_by(|a
, b
| a
.start
.partial_cmp(&b
.start
).unwrap());
306 if self.report_html
{
307 self.report_html(cx
, error
)
308 .with_context(|| "failed to save timing report")?
;
313 /// Save HTML report to disk.
314 fn report_html(&self, cx
: &Context
<'_
, '_
>, error
: &Option
<anyhow
::Error
>) -> CargoResult
<()> {
315 let duration
= self.start
.elapsed().as_secs_f64();
316 let timestamp
= self.start_str
.replace(&['
-'
, '
:'
][..], "");
317 let timings_path
= cx
.files().host_root().join("cargo-timings");
318 paths
::create_dir_all(&timings_path
)?
;
319 let filename
= timings_path
.join(format
!("cargo-timing-{}.html", timestamp
));
320 let mut f
= BufWriter
::new(paths
::create(&filename
)?
);
321 let roots
: Vec
<&str> = self
324 .map(|(name
, _targets
)| name
.as_str())
326 f
.write_all(HTML_TMPL
.replace("{ROOTS}", &roots
.join(", ")).as_bytes())?
;
327 self.write_summary_table(&mut f
, duration
, cx
.bcx
, error
)?
;
328 f
.write_all(HTML_CANVAS
.as_bytes())?
;
329 self.write_unit_table(&mut f
)?
;
330 // It helps with pixel alignment to use whole numbers.
335 f64::ceil(duration
) as u32
337 self.write_js_data(&mut f
)?
;
345 include_str
!("timings.js")
349 "report saved to {}",
350 std
::env
::current_dir()
355 let unstamped_filename
= timings_path
.join("cargo-timing.html");
356 paths
::link_or_copy(&filename
, &unstamped_filename
)?
;
359 .status_with_color("Timing", msg
, termcolor
::Color
::Cyan
)?
;
363 /// Render the summary table.
364 fn write_summary_table(
368 bcx
: &BuildContext
<'_
, '_
>,
369 error
: &Option
<anyhow
::Error
>,
370 ) -> CargoResult
<()> {
371 let targets
: Vec
<String
> = self
374 .map(|(name
, targets
)| format
!("{} ({})", name
, targets
.join(", ")))
376 let targets
= targets
.join("<br>");
377 let time_human
= if duration
> 60.0 {
378 format
!(" ({}m {:.1}s)", duration
as u32 / 60, duration
% 60.0)
382 let total_time
= format
!("{:.1}s{}", duration
, time_human
);
383 let max_concurrency
= self.concurrency
.iter().map(|c
| c
.active
).max().unwrap();
384 let num_cpus
= available_parallelism()
385 .map(|x
| x
.get().to_string())
386 .unwrap_or_else(|_
| "n/a".into());
387 let max_rustc_concurrency
= self
390 .map(|c
| c
.rustc_parallelism
)
393 let rustc_info
= render_rustc_info(bcx
);
394 let error_msg
= match error
{
398 <td class="error-text">Error:</td><td>{}</td>
403 None
=> "".to_string(),
408 <table class="my-table summary-table">
410 <td>Targets:</td><td>{}</td>
413 <td>Profile:</td><td>{}</td>
416 <td>Fresh units:</td><td>{}</td>
419 <td>Dirty units:</td><td>{}</td>
422 <td>Total units:</td><td>{}</td>
425 <td>Max concurrency:</td><td>{} (jobs={} ncpu={})</td>
428 <td>Build start:</td><td>{}</td>
431 <td>Total time:</td><td>{}</td>
434 <td>rustc:</td><td>{}</td>
437 <td>Max (global) rustc threads concurrency:</td><td>{}</td>
446 self.total_fresh
+ self.total_dirty
,
448 bcx
.build_config
.jobs
,
453 max_rustc_concurrency
,
459 fn write_js_data(&self, f
: &mut impl Write
) -> CargoResult
<()> {
460 // Create a map to link indices of unlocked units.
461 let unit_map
: HashMap
<Unit
, usize> = self
465 .map(|(i
, ut
)| (ut
.unit
.clone(), i
))
467 #[derive(serde::Serialize)]
476 rmeta_time
: Option
<f64>,
477 unlocked_units
: Vec
<usize>,
478 unlocked_rmeta_units
: Vec
<usize>,
480 let round
= |x
: f64| (x
* 100.0).round() / 100.0;
481 let unit_data
: Vec
<UnitData
> = self
486 let mode
= if ut
.unit
.mode
.is_run_custom_build() {
493 // These filter on the unlocked units because not all unlocked
494 // units are actually "built". For example, Doctest mode units
495 // don't actually generate artifacts.
496 let unlocked_units
: Vec
<usize> = ut
499 .filter_map(|unit
| unit_map
.get(unit
).copied())
501 let unlocked_rmeta_units
: Vec
<usize> = ut
502 .unlocked_rmeta_units
504 .filter_map(|unit
| unit_map
.get(unit
).copied())
508 name
: ut
.unit
.pkg
.name().to_string(),
509 version
: ut
.unit
.pkg
.version().to_string(),
511 target
: ut
.target
.clone(),
512 start
: round(ut
.start
),
513 duration
: round(ut
.duration
),
514 rmeta_time
: ut
.rmeta_time
.map(round
),
516 unlocked_rmeta_units
,
522 "const UNIT_DATA = {};",
523 serde_json
::to_string_pretty(&unit_data
)?
527 "const CONCURRENCY_DATA = {};",
528 serde_json
::to_string_pretty(&self.concurrency
)?
532 "const CPU_USAGE = {};",
533 serde_json
::to_string_pretty(&self.cpu_usage
)?
538 /// Render the table of all units.
539 fn write_unit_table(&self, f
: &mut impl Write
) -> CargoResult
<()> {
543 <table class="my-table">
556 let mut units
: Vec
<&UnitTime
> = self.unit_times
.iter().collect();
557 units
.sort_unstable_by(|a
, b
| b
.duration
.partial_cmp(&a
.duration
).unwrap());
558 for (i
, unit
) in units
.iter().enumerate() {
559 let codegen
= match unit
.codegen_time() {
560 None
=> "".to_string(),
561 Some((_rt
, ctime
, cent
)) => format
!("{:.1}s ({:.0}%)", ctime
, cent
),
563 let features
= unit
.unit
.features
.join(", ");
583 write
!(f
, "</tbody>\n</table>\n")?
;
589 /// Returns the codegen time as (rmeta_time, codegen_time, percent of total)
590 fn codegen_time(&self) -> Option
<(f64, f64, f64)> {
591 self.rmeta_time
.map(|rmeta_time
| {
592 let ctime
= self.duration
- rmeta_time
;
593 let cent
= (ctime
/ self.duration
) * 100.0;
594 (rmeta_time
, ctime
, cent
)
598 fn name_ver(&self) -> String
{
599 format
!("{} v{}", self.unit
.pkg
.name(), self.unit
.pkg
.version())
603 fn render_rustc_info(bcx
: &BuildContext
<'_
, '_
>) -> String
{
609 .expect("rustc version");
610 let requested_target
= bcx
614 .map(|kind
| bcx
.target_data
.short_name(kind
))
618 "{}<br>Host: {}<br>Target: {}",
625 static HTML_TMPL
: &str = r
#"
628 <title>Cargo Build Timings — {ROOTS}</title>
629 <meta charset="utf-8">
630 <style type="text/css">
632 font-family: sans-serif;
642 border-bottom: 1px solid #c0c0c0;
652 border-collapse: collapse;
653 box-shadow: 0 5px 10px rgba(0, 0, 0, 0.1);
659 border-bottom: 4px solid #9ea7af;
660 border-right: 1px solid #343a45;
665 vertical-align: middle;
668 .my-table th:first-child {
669 border-top-left-radius: 3px;
672 .my-table th:last-child {
673 border-top-right-radius: 3px;
678 border-top: 1px solid #c1c3d1;
679 border-bottom: 1px solid #c1c3d1;
684 .my-table tr:first-child {
688 .my-table tr:last-child {
692 .my-table tr:nth-child(odd) td {
696 .my-table tr:last-child td:first-child {
697 border-bottom-left-radius:3px;
700 .my-table tr:last-child td:last-child {
701 border-bottom-right-radius:3px;
708 vertical-align: middle;
711 border-right: 1px solid #C1C3D1;
714 .my-table td:last-child {
718 .summary-table td:first-child {
735 <h1>Cargo Build Timings</h1>
738 static HTML_CANVAS
: &str = r
#"
739 <table class="input-table">
741 <td><label for="min-unit-time">Min unit time:</label></td>
742 <td><label for="scale">Scale:</label></td>
745 <td><input type="range" min="0" max="30" step="0.1" value="0" id="min-unit-time"></td>
746 <td><input type="range" min="1" max="50" value="20" id="scale"></td>
749 <td><output for="min-unit-time" id="min-unit-time-output"></output></td>
750 <td><output for="scale" id="scale-output"></output></td>
754 <div id="pipeline-container" class="canvas-container">
755 <canvas id="pipeline-graph" class="graph" style="position: absolute; left: 0; top: 0; z-index: 0;"></canvas>
756 <canvas id="pipeline-graph-lines" style="position: absolute; left: 0; top: 0; z-index: 1; pointer-events:none;"></canvas>
758 <div class="canvas-container">
759 <canvas id="timing-graph" class="graph"></canvas>