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
;
8 use crate::core
::PackageId
;
9 use crate::util
::cpu
::State
;
10 use crate::util
::machine_message
::{self, Message}
;
11 use crate::util
::{paths, CargoResult, Config}
;
12 use std
::collections
::HashMap
;
14 use std
::io
::{BufWriter, Write}
;
15 use std
::time
::{Duration, Instant, SystemTime}
;
17 pub struct Timings
<'cfg
> {
19 /// Whether or not timings should be captured.
21 /// If true, saves an HTML report to disk.
23 /// If true, reports unit completion to stderr.
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
| {
101 .map_or(false, |t
| t
.iter().any(|opt
| opt
== what
))
103 let report_html
= has_report("html");
104 let report_info
= has_report("info");
105 let report_json
= has_report("json");
106 let enabled
= report_html
| report_info
| report_json
;
108 let mut root_map
: HashMap
<PackageId
, Vec
<String
>> = HashMap
::new();
109 for unit
in root_units
{
110 let target_desc
= unit
.target
.description_named();
112 .entry(unit
.pkg
.package_id())
116 let root_targets
= root_map
118 .map(|(pkg_id
, targets
)| {
119 let pkg_desc
= format
!("{} {}", pkg_id
.name(), pkg_id
.version());
123 let start_str
= humantime
::format_rfc3339_seconds(SystemTime
::now()).to_string();
124 let profile
= bcx
.build_config
.requested_profile
.to_string();
132 start
: bcx
.config
.creation_time(),
138 unit_times
: Vec
::new(),
139 active
: HashMap
::new(),
140 concurrency
: Vec
::new(),
141 last_cpu_state
: if enabled { State::current().ok() }
else { None }
,
142 last_cpu_recording
: Instant
::now(),
143 cpu_usage
: Vec
::new(),
147 /// Mark that a unit has started running.
148 pub fn unit_start(&mut self, id
: JobId
, unit
: Unit
) {
152 let mut target
= if unit
.target
.is_lib() && unit
.mode
== CompileMode
::Build
{
153 // Special case for brevity, since most dependencies hit
157 format
!(" {}", unit
.target
.description_named())
160 CompileMode
::Test
=> target
.push_str(" (test)"),
161 CompileMode
::Build
=> {}
162 CompileMode
::Check { test: true }
=> target
.push_str(" (check-test)"),
163 CompileMode
::Check { test: false }
=> target
.push_str(" (check)"),
164 CompileMode
::Bench
=> target
.push_str(" (bench)"),
165 CompileMode
::Doc { .. }
=> target
.push_str(" (doc)"),
166 CompileMode
::Doctest
=> target
.push_str(" (doc test)"),
167 CompileMode
::RunCustomBuild
=> target
.push_str(" (run)"),
169 let unit_time
= UnitTime
{
172 start
: d_as_f64(self.start
.elapsed()),
175 unlocked_units
: Vec
::new(),
176 unlocked_rmeta_units
: Vec
::new(),
178 assert
!(self.active
.insert(id
, unit_time
).is_none());
181 /// Mark that the `.rmeta` file as generated.
182 pub fn unit_rmeta_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
>) {
186 // `id` may not always be active. "fresh" units unconditionally
187 // generate `Message::Finish`, but this active map only tracks dirty
189 let unit_time
= match self.active
.get_mut(&id
) {
193 let t
= d_as_f64(self.start
.elapsed());
194 unit_time
.rmeta_time
= Some(t
- unit_time
.start
);
195 assert
!(unit_time
.unlocked_rmeta_units
.is_empty());
197 .unlocked_rmeta_units
198 .extend(unlocked
.iter().cloned().cloned());
201 /// Mark that a unit has finished running.
202 pub fn unit_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
>) {
206 // See note above in `unit_rmeta_finished`, this may not always be active.
207 let mut unit_time
= match self.active
.remove(&id
) {
211 let t
= d_as_f64(self.start
.elapsed());
212 unit_time
.duration
= t
- unit_time
.start
;
213 assert
!(unit_time
.unlocked_units
.is_empty());
216 .extend(unlocked
.iter().cloned().cloned());
217 if self.report_info
{
220 unit_time
.name_ver(),
227 .status_with_color("Completed", msg
, termcolor
::Color
::Cyan
);
229 if self.report_json
{
230 let msg
= machine_message
::TimingInfo
{
231 package_id
: unit_time
.unit
.pkg
.package_id(),
232 target
: &unit_time
.unit
.target
,
233 mode
: unit_time
.unit
.mode
,
234 duration
: unit_time
.duration
,
235 rmeta_time
: unit_time
.rmeta_time
,
238 self.config
.shell().stdout_println(msg
);
240 self.unit_times
.push(unit_time
);
243 /// This is called periodically to mark the concurrency of internal structures.
244 pub fn mark_concurrency(
249 rustc_parallelism
: usize,
254 let c
= Concurrency
{
255 t
: d_as_f64(self.start
.elapsed()),
261 self.concurrency
.push(c
);
264 /// Mark that a fresh unit was encountered.
265 pub fn add_fresh(&mut self) {
266 self.total_fresh
+= 1;
269 /// Mark that a dirty unit was encountered.
270 pub fn add_dirty(&mut self) {
271 self.total_dirty
+= 1;
274 /// Take a sample of CPU usage
275 pub fn record_cpu(&mut self) {
279 let prev
= match &mut self.last_cpu_state
{
280 Some(state
) => state
,
283 // Don't take samples too too frequently, even if requested.
284 let now
= Instant
::now();
285 if self.last_cpu_recording
.elapsed() < Duration
::from_millis(100) {
288 let current
= match State
::current() {
292 let pct_idle
= current
.idle_since(prev
);
294 self.last_cpu_recording
= now
;
295 let dur
= d_as_f64(now
.duration_since(self.start
));
296 self.cpu_usage
.push((dur
, 100.0 - pct_idle
));
299 /// Call this when all units are finished.
302 bcx
: &BuildContext
<'_
, '_
>,
303 error
: &Option
<anyhow
::Error
>,
304 ) -> CargoResult
<()> {
308 self.mark_concurrency(0, 0, 0, 0);
310 .sort_unstable_by(|a
, b
| a
.start
.partial_cmp(&b
.start
).unwrap());
311 if self.report_html
{
312 self.report_html(bcx
, error
)?
;
317 /// Save HTML report to disk.
320 bcx
: &BuildContext
<'_
, '_
>,
321 error
: &Option
<anyhow
::Error
>,
322 ) -> CargoResult
<()> {
323 let duration
= d_as_f64(self.start
.elapsed());
324 let timestamp
= self.start_str
.replace(&['
-'
, '
:'
][..], "");
325 let filename
= format
!("cargo-timing-{}.html", timestamp
);
326 let mut f
= BufWriter
::new(File
::create(&filename
)?
);
327 let roots
: Vec
<&str> = self
330 .map(|(name
, _targets
)| name
.as_str())
332 f
.write_all(HTML_TMPL
.replace("{ROOTS}", &roots
.join(", ")).as_bytes())?
;
333 self.write_summary_table(&mut f
, duration
, bcx
, error
)?
;
334 f
.write_all(HTML_CANVAS
.as_bytes())?
;
335 self.write_unit_table(&mut f
)?
;
336 // It helps with pixel alignment to use whole numbers.
341 f64::ceil(duration
) as u32
343 self.write_js_data(&mut f
)?
;
351 include_str
!("timings.js")
355 "report saved to {}",
356 std
::env
::current_dir()
361 paths
::link_or_copy(&filename
, "cargo-timing.html")?
;
364 .status_with_color("Timing", msg
, termcolor
::Color
::Cyan
)?
;
368 /// Render the summary table.
369 fn write_summary_table(
373 bcx
: &BuildContext
<'_
, '_
>,
374 error
: &Option
<anyhow
::Error
>,
375 ) -> CargoResult
<()> {
376 let targets
: Vec
<String
> = self
379 .map(|(name
, targets
)| format
!("{} ({})", name
, targets
.join(", ")))
381 let targets
= targets
.join("<br>");
382 let time_human
= if duration
> 60.0 {
383 format
!(" ({}m {:.1}s)", duration
as u32 / 60, duration
% 60.0)
387 let total_time
= format
!("{:.1}s{}", duration
, time_human
);
388 let max_concurrency
= self.concurrency
.iter().map(|c
| c
.active
).max().unwrap();
389 let max_rustc_concurrency
= self
392 .map(|c
| c
.rustc_parallelism
)
395 let rustc_info
= render_rustc_info(bcx
);
396 let error_msg
= match error
{
400 <td class="error-text">Error:</td><td>{}</td>
405 None
=> "".to_string(),
410 <table class="my-table summary-table">
412 <td>Targets:</td><td>{}</td>
415 <td>Profile:</td><td>{}</td>
418 <td>Fresh units:</td><td>{}</td>
421 <td>Dirty units:</td><td>{}</td>
424 <td>Total units:</td><td>{}</td>
427 <td>Max concurrency:</td><td>{} (jobs={} ncpu={})</td>
430 <td>Build start:</td><td>{}</td>
433 <td>Total time:</td><td>{}</td>
436 <td>rustc:</td><td>{}</td>
439 <td>Max (global) rustc threads concurrency:</td><td>{}</td>
448 self.total_fresh
+ self.total_dirty
,
450 bcx
.build_config
.jobs
,
455 max_rustc_concurrency
,
461 fn write_js_data(&self, f
: &mut impl Write
) -> CargoResult
<()> {
462 // Create a map to link indices of unlocked units.
463 let unit_map
: HashMap
<Unit
, usize> = self
467 .map(|(i
, ut
)| (ut
.unit
.clone(), i
))
469 #[derive(serde::Serialize)]
478 rmeta_time
: Option
<f64>,
479 unlocked_units
: Vec
<usize>,
480 unlocked_rmeta_units
: Vec
<usize>,
482 let round
= |x
: f64| (x
* 100.0).round() / 100.0;
483 let unit_data
: Vec
<UnitData
> = self
488 let mode
= if ut
.unit
.mode
.is_run_custom_build() {
495 // These filter on the unlocked units because not all unlocked
496 // units are actually "built". For example, Doctest mode units
497 // don't actually generate artifacts.
498 let unlocked_units
: Vec
<usize> = ut
501 .filter_map(|unit
| unit_map
.get(unit
).copied())
503 let unlocked_rmeta_units
: Vec
<usize> = ut
504 .unlocked_rmeta_units
506 .filter_map(|unit
| unit_map
.get(unit
).copied())
510 name
: ut
.unit
.pkg
.name().to_string(),
511 version
: ut
.unit
.pkg
.version().to_string(),
513 target
: ut
.target
.clone(),
514 start
: round(ut
.start
),
515 duration
: round(ut
.duration
),
516 rmeta_time
: ut
.rmeta_time
.map(|t
| round(t
)),
518 unlocked_rmeta_units
,
524 "const UNIT_DATA = {};",
525 serde_json
::to_string_pretty(&unit_data
)?
529 "const CONCURRENCY_DATA = {};",
530 serde_json
::to_string_pretty(&self.concurrency
)?
534 "const CPU_USAGE = {};",
535 serde_json
::to_string_pretty(&self.cpu_usage
)?
540 /// Render the table of all units.
541 fn write_unit_table(&self, f
: &mut impl Write
) -> CargoResult
<()> {
545 <table class="my-table">
558 let mut units
: Vec
<&UnitTime
> = self.unit_times
.iter().collect();
559 units
.sort_unstable_by(|a
, b
| b
.duration
.partial_cmp(&a
.duration
).unwrap());
560 for (i
, unit
) in units
.iter().enumerate() {
561 let codegen
= match unit
.codegen_time() {
562 None
=> "".to_string(),
563 Some((_rt
, ctime
, cent
)) => format
!("{:.1}s ({:.0}%)", ctime
, cent
),
565 let features
= unit
.unit
.features
.join(", ");
585 write
!(f
, "</tbody>\n</table>\n")?
;
591 /// Returns the codegen time as (rmeta_time, codegen_time, percent of total)
592 fn codegen_time(&self) -> Option
<(f64, f64, f64)> {
593 self.rmeta_time
.map(|rmeta_time
| {
594 let ctime
= self.duration
- rmeta_time
;
595 let cent
= (ctime
/ self.duration
) * 100.0;
596 (rmeta_time
, ctime
, cent
)
600 fn name_ver(&self) -> String
{
601 format
!("{} v{}", self.unit
.pkg
.name(), self.unit
.pkg
.version())
605 // Replace with as_secs_f64 when 1.38 hits stable.
606 fn d_as_f64(d
: Duration
) -> f64 {
607 (d
.as_secs() as f64) + f64::from(d
.subsec_nanos()) / 1_000_000_000.0
610 fn render_rustc_info(bcx
: &BuildContext
<'_
, '_
>) -> String
{
616 .expect("rustc version");
617 let requested_target
= bcx
621 .map(|kind
| bcx
.target_data
.short_name(kind
))
625 "{}<br>Host: {}<br>Target: {}",
632 static HTML_TMPL
: &str = r
#"
635 <title>Cargo Build Timings — {ROOTS}</title>
636 <meta charset="utf-8">
637 <style type="text/css">
639 font-family: sans-serif;
649 border-bottom: 1px solid #c0c0c0;
659 border-collapse: collapse;
660 box-shadow: 0 5px 10px rgba(0, 0, 0, 0.1);
666 border-bottom: 4px solid #9ea7af;
667 border-right: 1px solid #343a45;
672 vertical-align: middle;
675 .my-table th:first-child {
676 border-top-left-radius: 3px;
679 .my-table th:last-child {
680 border-top-right-radius: 3px;
685 border-top: 1px solid #c1c3d1;
686 border-bottom: 1px solid #c1c3d1;
691 .my-table tr:first-child {
695 .my-table tr:last-child {
699 .my-table tr:nth-child(odd) td {
703 .my-table tr:last-child td:first-child {
704 border-bottom-left-radius:3px;
707 .my-table tr:last-child td:last-child {
708 border-bottom-right-radius:3px;
715 vertical-align: middle;
718 border-right: 1px solid #C1C3D1;
721 .my-table td:last-child {
725 .summary-table td:first-child {
742 <h1>Cargo Build Timings</h1>
745 static HTML_CANVAS
: &str = r
#"
746 <table class="input-table">
748 <td><label for="min-unit-time">Min unit time:</label></td>
749 <td><label for="scale">Scale:</label></td>
752 <td><input type="range" min="0" max="30" step="0.1" value="0" id="min-unit-time"></td>
753 <td><input type="range" min="1" max="50" value="20" id="scale"></td>
756 <td><output for="min-unit-time" id="min-unit-time-output"></output></td>
757 <td><output for="scale" id="scale-output"></output></td>
761 <div id="pipeline-container" class="canvas-container">
762 <canvas id="pipeline-graph" class="graph" style="position: absolute; left: 0; top: 0; z-index: 0;"></canvas>
763 <canvas id="pipeline-graph-lines" style="position: absolute; left: 0; top: 0; z-index: 1; pointer-events:none;"></canvas>
765 <div class="canvas-container">
766 <canvas id="timing-graph" class="graph"></canvas>