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
::{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, reports unit completion to stderr.
26 /// If true, emits JSON information with timing information.
28 /// When Cargo started.
30 /// A rendered string of when compilation started.
32 /// A summary of the root units.
34 /// Tuples of `(package_description, target_descrptions)`.
35 root_targets
: Vec
<(String
, Vec
<String
>)>,
36 /// The build profile.
38 /// Total number of fresh units.
40 /// Total number of dirty units.
42 /// Time tracking for each individual unit.
43 unit_times
: Vec
<UnitTime
>,
44 /// Units that are in the process of being built.
45 /// When they finished, they are moved to `unit_times`.
46 active
: HashMap
<JobId
, UnitTime
>,
47 /// Concurrency-tracking information. This is periodically updated while
48 /// compilation progresses.
49 concurrency
: Vec
<Concurrency
>,
50 /// Last recorded state of the system's CPUs and when it happened
51 last_cpu_state
: Option
<State
>,
52 last_cpu_recording
: Instant
,
53 /// Recorded CPU states, stored as tuples. First element is when the
54 /// recording was taken and second element is percentage usage of the
56 cpu_usage
: Vec
<(f64, f64)>,
59 /// Tracking information for an individual unit.
62 /// A string describing the cargo target.
64 /// The time when this unit started as an offset in seconds from `Timings::start`.
66 /// Total time to build this unit in seconds.
68 /// The time when the `.rmeta` file was generated, an offset in seconds
70 rmeta_time
: Option
<f64>,
71 /// Reverse deps that are freed to run after this unit finished.
72 unlocked_units
: Vec
<Unit
>,
73 /// Same as `unlocked_units`, but unlocked by rmeta.
74 unlocked_rmeta_units
: Vec
<Unit
>,
77 /// Periodic concurrency tracking information.
78 #[derive(serde::Serialize)]
80 /// Time as an offset in seconds from `Timings::start`.
82 /// Number of units currently running.
84 /// Number of units that could run, but are waiting for a jobserver token.
86 /// Number of units that are not yet ready, because they are waiting for
87 /// dependencies to finish.
89 /// Number of rustc "extra" threads -- i.e., how many tokens have been
90 /// provided across all current rustc instances that are not the main thread
92 rustc_parallelism
: usize,
95 impl<'cfg
> Timings
<'cfg
> {
96 pub fn new(bcx
: &BuildContext
<'_
, 'cfg
>, root_units
: &[Unit
]) -> Timings
<'cfg
> {
97 let has_report
= |what
| {
102 .map_or(false, |t
| t
.iter().any(|opt
| opt
== what
))
104 let report_html
= has_report("html");
105 let report_info
= has_report("info");
106 let report_json
= has_report("json");
107 let enabled
= report_html
| report_info
| report_json
;
109 let mut root_map
: HashMap
<PackageId
, Vec
<String
>> = HashMap
::new();
110 for unit
in root_units
{
111 let target_desc
= unit
.target
.description_named();
113 .entry(unit
.pkg
.package_id())
117 let root_targets
= root_map
119 .map(|(pkg_id
, targets
)| {
120 let pkg_desc
= format
!("{} {}", pkg_id
.name(), pkg_id
.version());
124 let start_str
= humantime
::format_rfc3339_seconds(SystemTime
::now()).to_string();
125 let profile
= bcx
.build_config
.requested_profile
.to_string();
126 let last_cpu_state
= if enabled
{
127 match State
::current() {
128 Ok(state
) => Some(state
),
130 log
::info
!("failed to get CPU state, CPU tracking disabled: {:?}", e
);
144 start
: bcx
.config
.creation_time(),
150 unit_times
: Vec
::new(),
151 active
: HashMap
::new(),
152 concurrency
: Vec
::new(),
154 last_cpu_recording
: Instant
::now(),
155 cpu_usage
: Vec
::new(),
159 /// Mark that a unit has started running.
160 pub fn unit_start(&mut self, id
: JobId
, unit
: Unit
) {
164 let mut target
= if unit
.target
.is_lib() && unit
.mode
== CompileMode
::Build
{
165 // Special case for brevity, since most dependencies hit
169 format
!(" {}", unit
.target
.description_named())
172 CompileMode
::Test
=> target
.push_str(" (test)"),
173 CompileMode
::Build
=> {}
174 CompileMode
::Check { test: true }
=> target
.push_str(" (check-test)"),
175 CompileMode
::Check { test: false }
=> target
.push_str(" (check)"),
176 CompileMode
::Bench
=> target
.push_str(" (bench)"),
177 CompileMode
::Doc { .. }
=> target
.push_str(" (doc)"),
178 CompileMode
::Doctest
=> target
.push_str(" (doc test)"),
179 CompileMode
::RunCustomBuild
=> target
.push_str(" (run)"),
181 let unit_time
= UnitTime
{
184 start
: self.start
.elapsed().as_secs_f64(),
187 unlocked_units
: Vec
::new(),
188 unlocked_rmeta_units
: Vec
::new(),
190 assert
!(self.active
.insert(id
, unit_time
).is_none());
193 /// Mark that the `.rmeta` file as generated.
194 pub fn unit_rmeta_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
>) {
198 // `id` may not always be active. "fresh" units unconditionally
199 // generate `Message::Finish`, but this active map only tracks dirty
201 let unit_time
= match self.active
.get_mut(&id
) {
205 let t
= self.start
.elapsed().as_secs_f64();
206 unit_time
.rmeta_time
= Some(t
- unit_time
.start
);
207 assert
!(unit_time
.unlocked_rmeta_units
.is_empty());
209 .unlocked_rmeta_units
210 .extend(unlocked
.iter().cloned().cloned());
213 /// Mark that a unit has finished running.
214 pub fn unit_finished(&mut self, id
: JobId
, unlocked
: Vec
<&Unit
>) {
218 // See note above in `unit_rmeta_finished`, this may not always be active.
219 let mut unit_time
= match self.active
.remove(&id
) {
223 let t
= self.start
.elapsed().as_secs_f64();
224 unit_time
.duration
= t
- unit_time
.start
;
225 assert
!(unit_time
.unlocked_units
.is_empty());
228 .extend(unlocked
.iter().cloned().cloned());
229 if self.report_info
{
232 unit_time
.name_ver(),
239 .status_with_color("Completed", msg
, termcolor
::Color
::Cyan
);
241 if self.report_json
{
242 let msg
= machine_message
::TimingInfo
{
243 package_id
: unit_time
.unit
.pkg
.package_id(),
244 target
: &unit_time
.unit
.target
,
245 mode
: unit_time
.unit
.mode
,
246 duration
: unit_time
.duration
,
247 rmeta_time
: unit_time
.rmeta_time
,
250 crate::drop_println
!(self.config
, "{}", msg
);
252 self.unit_times
.push(unit_time
);
255 /// This is called periodically to mark the concurrency of internal structures.
256 pub fn mark_concurrency(
261 rustc_parallelism
: usize,
266 let c
= Concurrency
{
267 t
: self.start
.elapsed().as_secs_f64(),
273 self.concurrency
.push(c
);
276 /// Mark that a fresh unit was encountered.
277 pub fn add_fresh(&mut self) {
278 self.total_fresh
+= 1;
281 /// Mark that a dirty unit was encountered.
282 pub fn add_dirty(&mut self) {
283 self.total_dirty
+= 1;
286 /// Take a sample of CPU usage
287 pub fn record_cpu(&mut self) {
291 let prev
= match &mut self.last_cpu_state
{
292 Some(state
) => state
,
295 // Don't take samples too too frequently, even if requested.
296 let now
= Instant
::now();
297 if self.last_cpu_recording
.elapsed() < Duration
::from_millis(100) {
300 let current
= match State
::current() {
303 log
::info
!("failed to get CPU state: {:?}", e
);
307 let pct_idle
= current
.idle_since(prev
);
309 self.last_cpu_recording
= now
;
310 let dur
= now
.duration_since(self.start
).as_secs_f64();
311 self.cpu_usage
.push((dur
, 100.0 - pct_idle
));
314 /// Call this when all units are finished.
317 bcx
: &BuildContext
<'_
, '_
>,
318 error
: &Option
<anyhow
::Error
>,
319 ) -> CargoResult
<()> {
323 self.mark_concurrency(0, 0, 0, 0);
325 .sort_unstable_by(|a
, b
| a
.start
.partial_cmp(&b
.start
).unwrap());
326 if self.report_html
{
327 self.report_html(bcx
, error
)
328 .with_context(|| "failed to save timing report")?
;
333 /// Save HTML report to disk.
336 bcx
: &BuildContext
<'_
, '_
>,
337 error
: &Option
<anyhow
::Error
>,
338 ) -> CargoResult
<()> {
339 let duration
= self.start
.elapsed().as_secs_f64();
340 let timestamp
= self.start_str
.replace(&['
-'
, '
:'
][..], "");
341 let filename
= format
!("cargo-timing-{}.html", timestamp
);
342 let mut f
= BufWriter
::new(paths
::create(&filename
)?
);
343 let roots
: Vec
<&str> = self
346 .map(|(name
, _targets
)| name
.as_str())
348 f
.write_all(HTML_TMPL
.replace("{ROOTS}", &roots
.join(", ")).as_bytes())?
;
349 self.write_summary_table(&mut f
, duration
, bcx
, error
)?
;
350 f
.write_all(HTML_CANVAS
.as_bytes())?
;
351 self.write_unit_table(&mut f
)?
;
352 // It helps with pixel alignment to use whole numbers.
357 f64::ceil(duration
) as u32
359 self.write_js_data(&mut f
)?
;
367 include_str
!("timings.js")
371 "report saved to {}",
372 std
::env
::current_dir()
377 paths
::link_or_copy(&filename
, "cargo-timing.html")?
;
380 .status_with_color("Timing", msg
, termcolor
::Color
::Cyan
)?
;
384 /// Render the summary table.
385 fn write_summary_table(
389 bcx
: &BuildContext
<'_
, '_
>,
390 error
: &Option
<anyhow
::Error
>,
391 ) -> CargoResult
<()> {
392 let targets
: Vec
<String
> = self
395 .map(|(name
, targets
)| format
!("{} ({})", name
, targets
.join(", ")))
397 let targets
= targets
.join("<br>");
398 let time_human
= if duration
> 60.0 {
399 format
!(" ({}m {:.1}s)", duration
as u32 / 60, duration
% 60.0)
403 let total_time
= format
!("{:.1}s{}", duration
, time_human
);
404 let max_concurrency
= self.concurrency
.iter().map(|c
| c
.active
).max().unwrap();
405 let max_rustc_concurrency
= self
408 .map(|c
| c
.rustc_parallelism
)
411 let rustc_info
= render_rustc_info(bcx
);
412 let error_msg
= match error
{
416 <td class="error-text">Error:</td><td>{}</td>
421 None
=> "".to_string(),
426 <table class="my-table summary-table">
428 <td>Targets:</td><td>{}</td>
431 <td>Profile:</td><td>{}</td>
434 <td>Fresh units:</td><td>{}</td>
437 <td>Dirty units:</td><td>{}</td>
440 <td>Total units:</td><td>{}</td>
443 <td>Max concurrency:</td><td>{} (jobs={} ncpu={})</td>
446 <td>Build start:</td><td>{}</td>
449 <td>Total time:</td><td>{}</td>
452 <td>rustc:</td><td>{}</td>
455 <td>Max (global) rustc threads concurrency:</td><td>{}</td>
464 self.total_fresh
+ self.total_dirty
,
466 bcx
.build_config
.jobs
,
471 max_rustc_concurrency
,
477 fn write_js_data(&self, f
: &mut impl Write
) -> CargoResult
<()> {
478 // Create a map to link indices of unlocked units.
479 let unit_map
: HashMap
<Unit
, usize> = self
483 .map(|(i
, ut
)| (ut
.unit
.clone(), i
))
485 #[derive(serde::Serialize)]
494 rmeta_time
: Option
<f64>,
495 unlocked_units
: Vec
<usize>,
496 unlocked_rmeta_units
: Vec
<usize>,
498 let round
= |x
: f64| (x
* 100.0).round() / 100.0;
499 let unit_data
: Vec
<UnitData
> = self
504 let mode
= if ut
.unit
.mode
.is_run_custom_build() {
511 // These filter on the unlocked units because not all unlocked
512 // units are actually "built". For example, Doctest mode units
513 // don't actually generate artifacts.
514 let unlocked_units
: Vec
<usize> = ut
517 .filter_map(|unit
| unit_map
.get(unit
).copied())
519 let unlocked_rmeta_units
: Vec
<usize> = ut
520 .unlocked_rmeta_units
522 .filter_map(|unit
| unit_map
.get(unit
).copied())
526 name
: ut
.unit
.pkg
.name().to_string(),
527 version
: ut
.unit
.pkg
.version().to_string(),
529 target
: ut
.target
.clone(),
530 start
: round(ut
.start
),
531 duration
: round(ut
.duration
),
532 rmeta_time
: ut
.rmeta_time
.map(round
),
534 unlocked_rmeta_units
,
540 "const UNIT_DATA = {};",
541 serde_json
::to_string_pretty(&unit_data
)?
545 "const CONCURRENCY_DATA = {};",
546 serde_json
::to_string_pretty(&self.concurrency
)?
550 "const CPU_USAGE = {};",
551 serde_json
::to_string_pretty(&self.cpu_usage
)?
556 /// Render the table of all units.
557 fn write_unit_table(&self, f
: &mut impl Write
) -> CargoResult
<()> {
561 <table class="my-table">
574 let mut units
: Vec
<&UnitTime
> = self.unit_times
.iter().collect();
575 units
.sort_unstable_by(|a
, b
| b
.duration
.partial_cmp(&a
.duration
).unwrap());
576 for (i
, unit
) in units
.iter().enumerate() {
577 let codegen
= match unit
.codegen_time() {
578 None
=> "".to_string(),
579 Some((_rt
, ctime
, cent
)) => format
!("{:.1}s ({:.0}%)", ctime
, cent
),
581 let features
= unit
.unit
.features
.join(", ");
601 write
!(f
, "</tbody>\n</table>\n")?
;
607 /// Returns the codegen time as (rmeta_time, codegen_time, percent of total)
608 fn codegen_time(&self) -> Option
<(f64, f64, f64)> {
609 self.rmeta_time
.map(|rmeta_time
| {
610 let ctime
= self.duration
- rmeta_time
;
611 let cent
= (ctime
/ self.duration
) * 100.0;
612 (rmeta_time
, ctime
, cent
)
616 fn name_ver(&self) -> String
{
617 format
!("{} v{}", self.unit
.pkg
.name(), self.unit
.pkg
.version())
621 fn render_rustc_info(bcx
: &BuildContext
<'_
, '_
>) -> String
{
627 .expect("rustc version");
628 let requested_target
= bcx
632 .map(|kind
| bcx
.target_data
.short_name(kind
))
636 "{}<br>Host: {}<br>Target: {}",
643 static HTML_TMPL
: &str = r
#"
646 <title>Cargo Build Timings — {ROOTS}</title>
647 <meta charset="utf-8">
648 <style type="text/css">
650 font-family: sans-serif;
660 border-bottom: 1px solid #c0c0c0;
670 border-collapse: collapse;
671 box-shadow: 0 5px 10px rgba(0, 0, 0, 0.1);
677 border-bottom: 4px solid #9ea7af;
678 border-right: 1px solid #343a45;
683 vertical-align: middle;
686 .my-table th:first-child {
687 border-top-left-radius: 3px;
690 .my-table th:last-child {
691 border-top-right-radius: 3px;
696 border-top: 1px solid #c1c3d1;
697 border-bottom: 1px solid #c1c3d1;
702 .my-table tr:first-child {
706 .my-table tr:last-child {
710 .my-table tr:nth-child(odd) td {
714 .my-table tr:last-child td:first-child {
715 border-bottom-left-radius:3px;
718 .my-table tr:last-child td:last-child {
719 border-bottom-right-radius:3px;
726 vertical-align: middle;
729 border-right: 1px solid #C1C3D1;
732 .my-table td:last-child {
736 .summary-table td:first-child {
753 <h1>Cargo Build Timings</h1>
756 static HTML_CANVAS
: &str = r
#"
757 <table class="input-table">
759 <td><label for="min-unit-time">Min unit time:</label></td>
760 <td><label for="scale">Scale:</label></td>
763 <td><input type="range" min="0" max="30" step="0.1" value="0" id="min-unit-time"></td>
764 <td><input type="range" min="1" max="50" value="20" id="scale"></td>
767 <td><output for="min-unit-time" id="min-unit-time-output"></output></td>
768 <td><output for="scale" id="scale-output"></output></td>
772 <div id="pipeline-container" class="canvas-container">
773 <canvas id="pipeline-graph" class="graph" style="position: absolute; left: 0; top: 0; z-index: 0;"></canvas>
774 <canvas id="pipeline-graph-lines" style="position: absolute; left: 0; top: 0; z-index: 1; pointer-events:none;"></canvas>
776 <div class="canvas-container">
777 <canvas id="timing-graph" class="graph"></canvas>