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
<'a
, '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
<'a
>>,
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
<'a
>>,
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
<'a
>>,
72 /// Same as `unlocked_units`, but unlocked by rmeta.
73 unlocked_rmeta_units
: Vec
<Unit
<'a
>>,
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<'a
, 'cfg
> Timings
<'a
, 'cfg
> {
95 pub fn new(bcx
: &BuildContext
<'a
, 'cfg
>, root_units
: &[Unit
<'_
>]) -> Timings
<'a
, '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
<'a
>) {
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
<'a
>>) {
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());
196 unit_time
.unlocked_rmeta_units
.extend(unlocked
);
199 /// Mark that a unit has finished running.
200 pub fn unit_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
<'a
>>) {
204 // See note above in `unit_rmeta_finished`, this may not always be active.
205 let mut unit_time
= match self.active
.remove(&id
) {
209 let t
= d_as_f64(self.start
.elapsed());
210 unit_time
.duration
= t
- unit_time
.start
;
211 assert
!(unit_time
.unlocked_units
.is_empty());
212 unit_time
.unlocked_units
.extend(unlocked
);
213 if self.report_info
{
216 unit_time
.name_ver(),
223 .status_with_color("Completed", msg
, termcolor
::Color
::Cyan
);
225 if self.report_json
{
226 let msg
= machine_message
::TimingInfo
{
227 package_id
: unit_time
.unit
.pkg
.package_id(),
228 target
: unit_time
.unit
.target
,
229 mode
: unit_time
.unit
.mode
,
230 duration
: unit_time
.duration
,
231 rmeta_time
: unit_time
.rmeta_time
,
234 self.config
.shell().stdout_println(msg
);
236 self.unit_times
.push(unit_time
);
239 /// This is called periodically to mark the concurrency of internal structures.
240 pub fn mark_concurrency(
245 rustc_parallelism
: usize,
250 let c
= Concurrency
{
251 t
: d_as_f64(self.start
.elapsed()),
257 self.concurrency
.push(c
);
260 /// Mark that a fresh unit was encountered.
261 pub fn add_fresh(&mut self) {
262 self.total_fresh
+= 1;
265 /// Mark that a dirty unit was encountered.
266 pub fn add_dirty(&mut self) {
267 self.total_dirty
+= 1;
270 /// Take a sample of CPU usage
271 pub fn record_cpu(&mut self) {
275 let prev
= match &mut self.last_cpu_state
{
276 Some(state
) => state
,
279 // Don't take samples too too frequently, even if requested.
280 let now
= Instant
::now();
281 if self.last_cpu_recording
.elapsed() < Duration
::from_millis(100) {
284 let current
= match State
::current() {
288 let pct_idle
= current
.idle_since(prev
);
290 self.last_cpu_recording
= now
;
291 let dur
= d_as_f64(now
.duration_since(self.start
));
292 self.cpu_usage
.push((dur
, 100.0 - pct_idle
));
295 /// Call this when all units are finished.
298 bcx
: &BuildContext
<'_
, '_
>,
299 error
: &Option
<anyhow
::Error
>,
300 ) -> CargoResult
<()> {
304 self.mark_concurrency(0, 0, 0, 0);
306 .sort_unstable_by(|a
, b
| a
.start
.partial_cmp(&b
.start
).unwrap());
307 if self.report_html
{
308 self.report_html(bcx
, error
)?
;
313 /// Save HTML report to disk.
316 bcx
: &BuildContext
<'_
, '_
>,
317 error
: &Option
<anyhow
::Error
>,
318 ) -> CargoResult
<()> {
319 let duration
= d_as_f64(self.start
.elapsed());
320 let timestamp
= self.start_str
.replace(&['
-'
, '
:'
][..], "");
321 let filename
= format
!("cargo-timing-{}.html", timestamp
);
322 let mut f
= BufWriter
::new(File
::create(&filename
)?
);
323 let roots
: Vec
<&str> = self
326 .map(|(name
, _targets
)| name
.as_str())
328 f
.write_all(HTML_TMPL
.replace("{ROOTS}", &roots
.join(", ")).as_bytes())?
;
329 self.write_summary_table(&mut f
, duration
, bcx
, error
)?
;
330 f
.write_all(HTML_CANVAS
.as_bytes())?
;
331 self.write_unit_table(&mut f
)?
;
332 // It helps with pixel alignment to use whole numbers.
337 f64::ceil(duration
) as u32
339 self.write_js_data(&mut f
)?
;
347 include_str
!("timings.js")
351 "report saved to {}",
352 std
::env
::current_dir()
357 paths
::link_or_copy(&filename
, "cargo-timing.html")?
;
360 .status_with_color("Timing", msg
, termcolor
::Color
::Cyan
)?
;
364 /// Render the summary table.
365 fn write_summary_table(
369 bcx
: &BuildContext
<'_
, '_
>,
370 error
: &Option
<anyhow
::Error
>,
371 ) -> CargoResult
<()> {
372 let targets
: Vec
<String
> = self
375 .map(|(name
, targets
)| format
!("{} ({})", name
, targets
.join(", ")))
377 let targets
= targets
.join("<br>");
378 let time_human
= if duration
> 60.0 {
379 format
!(" ({}m {:.1}s)", duration
as u32 / 60, duration
% 60.0)
383 let total_time
= format
!("{:.1}s{}", duration
, time_human
);
384 let max_concurrency
= self.concurrency
.iter().map(|c
| c
.active
).max().unwrap();
385 let max_rustc_concurrency
= self
388 .map(|c
| c
.rustc_parallelism
)
391 let rustc_info
= render_rustc_info(bcx
);
392 let error_msg
= match error
{
396 <td class="error-text">Error:</td><td>{}</td>
401 None
=> "".to_string(),
406 <table class="my-table summary-table">
408 <td>Targets:</td><td>{}</td>
411 <td>Profile:</td><td>{}</td>
414 <td>Fresh units:</td><td>{}</td>
417 <td>Dirty units:</td><td>{}</td>
420 <td>Total units:</td><td>{}</td>
423 <td>Max concurrency:</td><td>{} (jobs={} ncpu={})</td>
426 <td>Build start:</td><td>{}</td>
429 <td>Total time:</td><td>{}</td>
432 <td>rustc:</td><td>{}</td>
435 <td>Max (global) rustc threads concurrency:</td><td>{}</td>
444 self.total_fresh
+ self.total_dirty
,
446 bcx
.build_config
.jobs
,
451 max_rustc_concurrency
,
457 fn write_js_data(&self, f
: &mut impl Write
) -> CargoResult
<()> {
458 // Create a map to link indices of unlocked units.
459 let unit_map
: HashMap
<Unit
<'_
>, usize> = self
463 .map(|(i
, ut
)| (ut
.unit
, i
))
465 #[derive(serde::Serialize)]
474 rmeta_time
: Option
<f64>,
475 unlocked_units
: Vec
<usize>,
476 unlocked_rmeta_units
: Vec
<usize>,
478 let round
= |x
: f64| (x
* 100.0).round() / 100.0;
479 let unit_data
: Vec
<UnitData
> = self
484 let mode
= if ut
.unit
.mode
.is_run_custom_build() {
491 // These filter on the unlocked units because not all unlocked
492 // units are actually "built". For example, Doctest mode units
493 // don't actually generate artifacts.
494 let unlocked_units
: Vec
<usize> = ut
497 .filter_map(|unit
| unit_map
.get(unit
).copied())
499 let unlocked_rmeta_units
: Vec
<usize> = ut
500 .unlocked_rmeta_units
502 .filter_map(|unit
| unit_map
.get(unit
).copied())
506 name
: ut
.unit
.pkg
.name().to_string(),
507 version
: ut
.unit
.pkg
.version().to_string(),
509 target
: ut
.target
.clone(),
510 start
: round(ut
.start
),
511 duration
: round(ut
.duration
),
512 rmeta_time
: ut
.rmeta_time
.map(|t
| round(t
)),
514 unlocked_rmeta_units
,
520 "const UNIT_DATA = {};",
521 serde_json
::to_string_pretty(&unit_data
)?
525 "const CONCURRENCY_DATA = {};",
526 serde_json
::to_string_pretty(&self.concurrency
)?
530 "const CPU_USAGE = {};",
531 serde_json
::to_string_pretty(&self.cpu_usage
)?
536 /// Render the table of all units.
537 fn write_unit_table(&self, f
: &mut impl Write
) -> CargoResult
<()> {
541 <table class="my-table">
554 let mut units
: Vec
<&UnitTime
<'_
>> = self.unit_times
.iter().collect();
555 units
.sort_unstable_by(|a
, b
| b
.duration
.partial_cmp(&a
.duration
).unwrap());
556 for (i
, unit
) in units
.iter().enumerate() {
557 let codegen
= match unit
.codegen_time() {
558 None
=> "".to_string(),
559 Some((_rt
, ctime
, cent
)) => format
!("{:.1}s ({:.0}%)", ctime
, cent
),
561 let features
= unit
.unit
.features
.join(", ");
581 write
!(f
, "</tbody>\n</table>\n")?
;
586 impl<'a
> UnitTime
<'a
> {
587 /// Returns the codegen time as (rmeta_time, codegen_time, percent of total)
588 fn codegen_time(&self) -> Option
<(f64, f64, f64)> {
589 self.rmeta_time
.map(|rmeta_time
| {
590 let ctime
= self.duration
- rmeta_time
;
591 let cent
= (ctime
/ self.duration
) * 100.0;
592 (rmeta_time
, ctime
, cent
)
596 fn name_ver(&self) -> String
{
597 format
!("{} v{}", self.unit
.pkg
.name(), self.unit
.pkg
.version())
601 // Replace with as_secs_f64 when 1.38 hits stable.
602 fn d_as_f64(d
: Duration
) -> f64 {
603 (d
.as_secs() as f64) + f64::from(d
.subsec_nanos()) / 1_000_000_000.0
606 fn render_rustc_info(bcx
: &BuildContext
<'_
, '_
>) -> String
{
612 .expect("rustc version");
613 let requested_target
= bcx
.build_config
.requested_kind
.short_name(bcx
);
615 "{}<br>Host: {}<br>Target: {}",
616 version
, bcx
.rustc
.host
, requested_target
620 static HTML_TMPL
: &str = r
#"
623 <title>Cargo Build Timings — {ROOTS}</title>
624 <meta charset="utf-8">
625 <style type="text/css">
627 font-family: sans-serif;
637 border-bottom: 1px solid #c0c0c0;
647 border-collapse: collapse;
648 box-shadow: 0 5px 10px rgba(0, 0, 0, 0.1);
654 border-bottom: 4px solid #9ea7af;
655 border-right: 1px solid #343a45;
660 vertical-align: middle;
663 .my-table th:first-child {
664 border-top-left-radius: 3px;
667 .my-table th:last-child {
668 border-top-right-radius: 3px;
673 border-top: 1px solid #c1c3d1;
674 border-bottom: 1px solid #c1c3d1;
679 .my-table tr:first-child {
683 .my-table tr:last-child {
687 .my-table tr:nth-child(odd) td {
691 .my-table tr:last-child td:first-child {
692 border-bottom-left-radius:3px;
695 .my-table tr:last-child td:last-child {
696 border-bottom-right-radius:3px;
703 vertical-align: middle;
706 border-right: 1px solid #C1C3D1;
709 .my-table td:last-child {
713 .summary-table td:first-child {
730 <h1>Cargo Build Timings</h1>
733 static HTML_CANVAS
: &str = r
#"
734 <table class="input-table">
736 <td><label for="min-unit-time">Min unit time:</label></td>
737 <td><label for="scale">Scale:</label></td>
740 <td><input type="range" min="0" max="30" step="0.1" value="0" id="min-unit-time"></td>
741 <td><input type="range" min="1" max="50" value="20" id="scale"></td>
744 <td><output for="min-unit-time" id="min-unit-time-output"></output></td>
745 <td><output for="scale" id="scale-output"></output></td>
749 <div id="pipeline-container" class="canvas-container">
750 <canvas id="pipeline-graph" class="graph" style="position: absolute; left: 0; top: 0; z-index: 0;"></canvas>
751 <canvas id="pipeline-graph-lines" style="position: absolute; left: 0; top: 0; z-index: 1; pointer-events:none;"></canvas>
753 <div class="canvas-container">
754 <canvas id="timing-graph" class="graph"></canvas>