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
::time
::{Duration, Instant, SystemTime}
;
18 pub struct Timings
<'cfg
> {
20 /// Whether or not timings should be captured.
22 /// If true, saves an HTML report to disk.
24 /// If true, emits JSON information with timing information.
26 /// When Cargo started.
28 /// A rendered string of when compilation started.
30 /// A summary of the root units.
32 /// Tuples of `(package_description, target_descrptions)`.
33 root_targets
: Vec
<(String
, Vec
<String
>)>,
34 /// The build profile.
36 /// Total number of fresh units.
38 /// Total number of dirty units.
40 /// Time tracking for each individual unit.
41 unit_times
: Vec
<UnitTime
>,
42 /// Units that are in the process of being built.
43 /// When they finished, they are moved to `unit_times`.
44 active
: HashMap
<JobId
, UnitTime
>,
45 /// Concurrency-tracking information. This is periodically updated while
46 /// compilation progresses.
47 concurrency
: Vec
<Concurrency
>,
48 /// Last recorded state of the system's CPUs and when it happened
49 last_cpu_state
: Option
<State
>,
50 last_cpu_recording
: Instant
,
51 /// Recorded CPU states, stored as tuples. First element is when the
52 /// recording was taken and second element is percentage usage of the
54 cpu_usage
: Vec
<(f64, f64)>,
57 /// Tracking information for an individual unit.
60 /// A string describing the cargo target.
62 /// The time when this unit started as an offset in seconds from `Timings::start`.
64 /// Total time to build this unit in seconds.
66 /// The time when the `.rmeta` file was generated, an offset in seconds
68 rmeta_time
: Option
<f64>,
69 /// Reverse deps that are freed to run after this unit finished.
70 unlocked_units
: Vec
<Unit
>,
71 /// Same as `unlocked_units`, but unlocked by rmeta.
72 unlocked_rmeta_units
: Vec
<Unit
>,
75 /// Periodic concurrency tracking information.
76 #[derive(serde::Serialize)]
78 /// Time as an offset in seconds from `Timings::start`.
80 /// Number of units currently running.
82 /// Number of units that could run, but are waiting for a jobserver token.
84 /// Number of units that are not yet ready, because they are waiting for
85 /// dependencies to finish.
87 /// Number of rustc "extra" threads -- i.e., how many tokens have been
88 /// provided across all current rustc instances that are not the main thread
90 rustc_parallelism
: usize,
93 impl<'cfg
> Timings
<'cfg
> {
94 pub fn new(bcx
: &BuildContext
<'_
, 'cfg
>, root_units
: &[Unit
]) -> Timings
<'cfg
> {
95 let has_report
= |what
| bcx
.build_config
.timing_outputs
.contains(&what
);
96 let report_html
= has_report(TimingOutput
::Html
);
97 let report_json
= has_report(TimingOutput
::Json
);
98 let enabled
= report_html
| report_json
;
100 let mut root_map
: HashMap
<PackageId
, Vec
<String
>> = HashMap
::new();
101 for unit
in root_units
{
102 let target_desc
= unit
.target
.description_named();
104 .entry(unit
.pkg
.package_id())
108 let root_targets
= root_map
110 .map(|(pkg_id
, targets
)| {
111 let pkg_desc
= format
!("{} {}", pkg_id
.name(), pkg_id
.version());
115 let start_str
= humantime
::format_rfc3339_seconds(SystemTime
::now()).to_string();
116 let profile
= bcx
.build_config
.requested_profile
.to_string();
117 let last_cpu_state
= if enabled
{
118 match State
::current() {
119 Ok(state
) => Some(state
),
121 log
::info
!("failed to get CPU state, CPU tracking disabled: {:?}", e
);
134 start
: bcx
.config
.creation_time(),
140 unit_times
: Vec
::new(),
141 active
: HashMap
::new(),
142 concurrency
: Vec
::new(),
144 last_cpu_recording
: Instant
::now(),
145 cpu_usage
: Vec
::new(),
149 /// Mark that a unit has started running.
150 pub fn unit_start(&mut self, id
: JobId
, unit
: Unit
) {
154 let mut target
= if unit
.target
.is_lib() && unit
.mode
== CompileMode
::Build
{
155 // Special case for brevity, since most dependencies hit
159 format
!(" {}", unit
.target
.description_named())
162 CompileMode
::Test
=> target
.push_str(" (test)"),
163 CompileMode
::Build
=> {}
164 CompileMode
::Check { test: true }
=> target
.push_str(" (check-test)"),
165 CompileMode
::Check { test: false }
=> target
.push_str(" (check)"),
166 CompileMode
::Bench
=> target
.push_str(" (bench)"),
167 CompileMode
::Doc { .. }
=> target
.push_str(" (doc)"),
168 CompileMode
::Doctest
=> target
.push_str(" (doc test)"),
169 CompileMode
::Docscrape
=> target
.push_str(" (doc scrape)"),
170 CompileMode
::RunCustomBuild
=> target
.push_str(" (run)"),
172 let unit_time
= UnitTime
{
175 start
: self.start
.elapsed().as_secs_f64(),
178 unlocked_units
: Vec
::new(),
179 unlocked_rmeta_units
: Vec
::new(),
181 assert
!(self.active
.insert(id
, unit_time
).is_none());
184 /// Mark that the `.rmeta` file as generated.
185 pub fn unit_rmeta_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
>) {
189 // `id` may not always be active. "fresh" units unconditionally
190 // generate `Message::Finish`, but this active map only tracks dirty
192 let unit_time
= match self.active
.get_mut(&id
) {
196 let t
= self.start
.elapsed().as_secs_f64();
197 unit_time
.rmeta_time
= Some(t
- unit_time
.start
);
198 assert
!(unit_time
.unlocked_rmeta_units
.is_empty());
200 .unlocked_rmeta_units
201 .extend(unlocked
.iter().cloned().cloned());
204 /// Mark that a unit has finished running.
205 pub fn unit_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
>) {
209 // See note above in `unit_rmeta_finished`, this may not always be active.
210 let mut unit_time
= match self.active
.remove(&id
) {
214 let t
= self.start
.elapsed().as_secs_f64();
215 unit_time
.duration
= t
- unit_time
.start
;
216 assert
!(unit_time
.unlocked_units
.is_empty());
219 .extend(unlocked
.iter().cloned().cloned());
220 if self.report_json
{
221 let msg
= machine_message
::TimingInfo
{
222 package_id
: unit_time
.unit
.pkg
.package_id(),
223 target
: &unit_time
.unit
.target
,
224 mode
: unit_time
.unit
.mode
,
225 duration
: unit_time
.duration
,
226 rmeta_time
: unit_time
.rmeta_time
,
229 crate::drop_println
!(self.config
, "{}", msg
);
231 self.unit_times
.push(unit_time
);
234 /// This is called periodically to mark the concurrency of internal structures.
235 pub fn mark_concurrency(
240 rustc_parallelism
: usize,
245 let c
= Concurrency
{
246 t
: self.start
.elapsed().as_secs_f64(),
252 self.concurrency
.push(c
);
255 /// Mark that a fresh unit was encountered.
256 pub fn add_fresh(&mut self) {
257 self.total_fresh
+= 1;
260 /// Mark that a dirty unit was encountered.
261 pub fn add_dirty(&mut self) {
262 self.total_dirty
+= 1;
265 /// Take a sample of CPU usage
266 pub fn record_cpu(&mut self) {
270 let prev
= match &mut self.last_cpu_state
{
271 Some(state
) => state
,
274 // Don't take samples too too frequently, even if requested.
275 let now
= Instant
::now();
276 if self.last_cpu_recording
.elapsed() < Duration
::from_millis(100) {
279 let current
= match State
::current() {
282 log
::info
!("failed to get CPU state: {:?}", e
);
286 let pct_idle
= current
.idle_since(prev
);
288 self.last_cpu_recording
= now
;
289 let dur
= now
.duration_since(self.start
).as_secs_f64();
290 self.cpu_usage
.push((dur
, 100.0 - pct_idle
));
293 /// Call this when all units are finished.
296 cx
: &Context
<'_
, '_
>,
297 error
: &Option
<anyhow
::Error
>,
298 ) -> CargoResult
<()> {
302 self.mark_concurrency(0, 0, 0, 0);
304 .sort_unstable_by(|a
, b
| a
.start
.partial_cmp(&b
.start
).unwrap());
305 if self.report_html
{
306 self.report_html(cx
, error
)
307 .with_context(|| "failed to save timing report")?
;
312 /// Save HTML report to disk.
313 fn report_html(&self, cx
: &Context
<'_
, '_
>, error
: &Option
<anyhow
::Error
>) -> CargoResult
<()> {
314 let duration
= self.start
.elapsed().as_secs_f64();
315 let timestamp
= self.start_str
.replace(&['
-'
, '
:'
][..], "");
316 let timings_path
= cx
.files().host_root().join("cargo-timings");
317 paths
::create_dir_all(&timings_path
)?
;
318 let filename
= timings_path
.join(format
!("cargo-timing-{}.html", timestamp
));
319 let mut f
= BufWriter
::new(paths
::create(&filename
)?
);
320 let roots
: Vec
<&str> = self
323 .map(|(name
, _targets
)| name
.as_str())
325 f
.write_all(HTML_TMPL
.replace("{ROOTS}", &roots
.join(", ")).as_bytes())?
;
326 self.write_summary_table(&mut f
, duration
, cx
.bcx
, error
)?
;
327 f
.write_all(HTML_CANVAS
.as_bytes())?
;
328 self.write_unit_table(&mut f
)?
;
329 // It helps with pixel alignment to use whole numbers.
334 f64::ceil(duration
) as u32
336 self.write_js_data(&mut f
)?
;
344 include_str
!("timings.js")
348 "report saved to {}",
349 std
::env
::current_dir()
354 let unstamped_filename
= timings_path
.join("cargo-timing.html");
355 paths
::link_or_copy(&filename
, &unstamped_filename
)?
;
358 .status_with_color("Timing", msg
, termcolor
::Color
::Cyan
)?
;
362 /// Render the summary table.
363 fn write_summary_table(
367 bcx
: &BuildContext
<'_
, '_
>,
368 error
: &Option
<anyhow
::Error
>,
369 ) -> CargoResult
<()> {
370 let targets
: Vec
<String
> = self
373 .map(|(name
, targets
)| format
!("{} ({})", name
, targets
.join(", ")))
375 let targets
= targets
.join("<br>");
376 let time_human
= if duration
> 60.0 {
377 format
!(" ({}m {:.1}s)", duration
as u32 / 60, duration
% 60.0)
381 let total_time
= format
!("{:.1}s{}", duration
, time_human
);
382 let max_concurrency
= self.concurrency
.iter().map(|c
| c
.active
).max().unwrap();
383 let max_rustc_concurrency
= self
386 .map(|c
| c
.rustc_parallelism
)
389 let rustc_info
= render_rustc_info(bcx
);
390 let error_msg
= match error
{
394 <td class="error-text">Error:</td><td>{}</td>
399 None
=> "".to_string(),
404 <table class="my-table summary-table">
406 <td>Targets:</td><td>{}</td>
409 <td>Profile:</td><td>{}</td>
412 <td>Fresh units:</td><td>{}</td>
415 <td>Dirty units:</td><td>{}</td>
418 <td>Total units:</td><td>{}</td>
421 <td>Max concurrency:</td><td>{} (jobs={} ncpu={})</td>
424 <td>Build start:</td><td>{}</td>
427 <td>Total time:</td><td>{}</td>
430 <td>rustc:</td><td>{}</td>
433 <td>Max (global) rustc threads concurrency:</td><td>{}</td>
442 self.total_fresh
+ self.total_dirty
,
444 bcx
.build_config
.jobs
,
449 max_rustc_concurrency
,
455 fn write_js_data(&self, f
: &mut impl Write
) -> CargoResult
<()> {
456 // Create a map to link indices of unlocked units.
457 let unit_map
: HashMap
<Unit
, usize> = self
461 .map(|(i
, ut
)| (ut
.unit
.clone(), i
))
463 #[derive(serde::Serialize)]
472 rmeta_time
: Option
<f64>,
473 unlocked_units
: Vec
<usize>,
474 unlocked_rmeta_units
: Vec
<usize>,
476 let round
= |x
: f64| (x
* 100.0).round() / 100.0;
477 let unit_data
: Vec
<UnitData
> = self
482 let mode
= if ut
.unit
.mode
.is_run_custom_build() {
489 // These filter on the unlocked units because not all unlocked
490 // units are actually "built". For example, Doctest mode units
491 // don't actually generate artifacts.
492 let unlocked_units
: Vec
<usize> = ut
495 .filter_map(|unit
| unit_map
.get(unit
).copied())
497 let unlocked_rmeta_units
: Vec
<usize> = ut
498 .unlocked_rmeta_units
500 .filter_map(|unit
| unit_map
.get(unit
).copied())
504 name
: ut
.unit
.pkg
.name().to_string(),
505 version
: ut
.unit
.pkg
.version().to_string(),
507 target
: ut
.target
.clone(),
508 start
: round(ut
.start
),
509 duration
: round(ut
.duration
),
510 rmeta_time
: ut
.rmeta_time
.map(round
),
512 unlocked_rmeta_units
,
518 "const UNIT_DATA = {};",
519 serde_json
::to_string_pretty(&unit_data
)?
523 "const CONCURRENCY_DATA = {};",
524 serde_json
::to_string_pretty(&self.concurrency
)?
528 "const CPU_USAGE = {};",
529 serde_json
::to_string_pretty(&self.cpu_usage
)?
534 /// Render the table of all units.
535 fn write_unit_table(&self, f
: &mut impl Write
) -> CargoResult
<()> {
539 <table class="my-table">
552 let mut units
: Vec
<&UnitTime
> = self.unit_times
.iter().collect();
553 units
.sort_unstable_by(|a
, b
| b
.duration
.partial_cmp(&a
.duration
).unwrap());
554 for (i
, unit
) in units
.iter().enumerate() {
555 let codegen
= match unit
.codegen_time() {
556 None
=> "".to_string(),
557 Some((_rt
, ctime
, cent
)) => format
!("{:.1}s ({:.0}%)", ctime
, cent
),
559 let features
= unit
.unit
.features
.join(", ");
579 write
!(f
, "</tbody>\n</table>\n")?
;
585 /// Returns the codegen time as (rmeta_time, codegen_time, percent of total)
586 fn codegen_time(&self) -> Option
<(f64, f64, f64)> {
587 self.rmeta_time
.map(|rmeta_time
| {
588 let ctime
= self.duration
- rmeta_time
;
589 let cent
= (ctime
/ self.duration
) * 100.0;
590 (rmeta_time
, ctime
, cent
)
594 fn name_ver(&self) -> String
{
595 format
!("{} v{}", self.unit
.pkg
.name(), self.unit
.pkg
.version())
599 fn render_rustc_info(bcx
: &BuildContext
<'_
, '_
>) -> String
{
605 .expect("rustc version");
606 let requested_target
= bcx
610 .map(|kind
| bcx
.target_data
.short_name(kind
))
614 "{}<br>Host: {}<br>Target: {}",
621 static HTML_TMPL
: &str = r
#"
624 <title>Cargo Build Timings — {ROOTS}</title>
625 <meta charset="utf-8">
626 <style type="text/css">
628 font-family: sans-serif;
638 border-bottom: 1px solid #c0c0c0;
648 border-collapse: collapse;
649 box-shadow: 0 5px 10px rgba(0, 0, 0, 0.1);
655 border-bottom: 4px solid #9ea7af;
656 border-right: 1px solid #343a45;
661 vertical-align: middle;
664 .my-table th:first-child {
665 border-top-left-radius: 3px;
668 .my-table th:last-child {
669 border-top-right-radius: 3px;
674 border-top: 1px solid #c1c3d1;
675 border-bottom: 1px solid #c1c3d1;
680 .my-table tr:first-child {
684 .my-table tr:last-child {
688 .my-table tr:nth-child(odd) td {
692 .my-table tr:last-child td:first-child {
693 border-bottom-left-radius:3px;
696 .my-table tr:last-child td:last-child {
697 border-bottom-right-radius:3px;
704 vertical-align: middle;
707 border-right: 1px solid #C1C3D1;
710 .my-table td:last-child {
714 .summary-table td:first-child {
731 <h1>Cargo Build Timings</h1>
734 static HTML_CANVAS
: &str = r
#"
735 <table class="input-table">
737 <td><label for="min-unit-time">Min unit time:</label></td>
738 <td><label for="scale">Scale:</label></td>
741 <td><input type="range" min="0" max="30" step="0.1" value="0" id="min-unit-time"></td>
742 <td><input type="range" min="1" max="50" value="20" id="scale"></td>
745 <td><output for="min-unit-time" id="min-unit-time-output"></output></td>
746 <td><output for="scale" id="scale-output"></output></td>
750 <div id="pipeline-container" class="canvas-container">
751 <canvas id="pipeline-graph" class="graph" style="position: absolute; left: 0; top: 0; z-index: 0;"></canvas>
752 <canvas id="pipeline-graph-lines" style="position: absolute; left: 0; top: 0; z-index: 1; pointer-events:none;"></canvas>
754 <div class="canvas-container">
755 <canvas id="timing-graph" class="graph"></canvas>