]> git.proxmox.com Git - cargo.git/blob - src/cargo/core/compiler/timings.rs
Auto merge of #7857 - ehuss:fix-build-script-dupe, r=alexcrichton
[cargo.git] / src / cargo / core / compiler / timings.rs
1 //! Timing tracking.
2 //!
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;
13 use std::fs::File;
14 use std::io::{BufWriter, Write};
15 use std::time::{Duration, Instant, SystemTime};
16
17 pub struct Timings<'a, 'cfg> {
18 config: &'cfg Config,
19 /// Whether or not timings should be captured.
20 enabled: bool,
21 /// If true, saves an HTML report to disk.
22 report_html: bool,
23 /// If true, reports unit completion to stderr.
24 report_info: bool,
25 /// If true, emits JSON information with timing information.
26 report_json: bool,
27 /// When Cargo started.
28 start: Instant,
29 /// A rendered string of when compilation started.
30 start_str: String,
31 /// A summary of the root units.
32 ///
33 /// Tuples of `(package_description, target_descrptions)`.
34 root_targets: Vec<(String, Vec<String>)>,
35 /// The build profile.
36 profile: String,
37 /// Total number of fresh units.
38 total_fresh: u32,
39 /// Total number of dirty units.
40 total_dirty: u32,
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
54 /// system.
55 cpu_usage: Vec<(f64, f64)>,
56 }
57
58 /// Tracking information for an individual unit.
59 struct UnitTime<'a> {
60 unit: Unit<'a>,
61 /// A string describing the cargo target.
62 target: String,
63 /// The time when this unit started as an offset in seconds from `Timings::start`.
64 start: f64,
65 /// Total time to build this unit in seconds.
66 duration: f64,
67 /// The time when the `.rmeta` file was generated, an offset in seconds
68 /// from `start`.
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>>,
74 }
75
76 /// Periodic concurrency tracking information.
77 #[derive(serde::Serialize)]
78 struct Concurrency {
79 /// Time as an offset in seconds from `Timings::start`.
80 t: f64,
81 /// Number of units currently running.
82 active: usize,
83 /// Number of units that could run, but are waiting for a jobserver token.
84 waiting: usize,
85 /// Number of units that are not yet ready, because they are waiting for
86 /// dependencies to finish.
87 inactive: usize,
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
90 /// tokens.
91 rustc_parallelism: usize,
92 }
93
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| {
97 bcx.config
98 .cli_unstable()
99 .timings
100 .as_ref()
101 .map_or(false, |t| t.iter().any(|opt| opt == what))
102 };
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;
107
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();
111 root_map
112 .entry(unit.pkg.package_id())
113 .or_default()
114 .push(target_desc);
115 }
116 let root_targets = root_map
117 .into_iter()
118 .map(|(pkg_id, targets)| {
119 let pkg_desc = format!("{} {}", pkg_id.name(), pkg_id.version());
120 (pkg_desc, targets)
121 })
122 .collect();
123 let start_str = humantime::format_rfc3339_seconds(SystemTime::now()).to_string();
124 let profile = bcx.build_config.requested_profile.to_string();
125
126 Timings {
127 config: bcx.config,
128 enabled,
129 report_html,
130 report_info,
131 report_json,
132 start: bcx.config.creation_time(),
133 start_str,
134 root_targets,
135 profile,
136 total_fresh: 0,
137 total_dirty: 0,
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(),
144 }
145 }
146
147 /// Mark that a unit has started running.
148 pub fn unit_start(&mut self, id: JobId, unit: Unit<'a>) {
149 if !self.enabled {
150 return;
151 }
152 let mut target = if unit.target.is_lib() && unit.mode == CompileMode::Build {
153 // Special case for brevity, since most dependencies hit
154 // this path.
155 "".to_string()
156 } else {
157 format!(" {}", unit.target.description_named())
158 };
159 match unit.mode {
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)"),
168 }
169 let unit_time = UnitTime {
170 unit,
171 target,
172 start: d_as_f64(self.start.elapsed()),
173 duration: 0.0,
174 rmeta_time: None,
175 unlocked_units: Vec::new(),
176 unlocked_rmeta_units: Vec::new(),
177 };
178 assert!(self.active.insert(id, unit_time).is_none());
179 }
180
181 /// Mark that the `.rmeta` file as generated.
182 pub fn unit_rmeta_finished(&mut self, id: JobId, unlocked: Vec<&Unit<'a>>) {
183 if !self.enabled {
184 return;
185 }
186 // `id` may not always be active. "fresh" units unconditionally
187 // generate `Message::Finish`, but this active map only tracks dirty
188 // units.
189 let unit_time = match self.active.get_mut(&id) {
190 Some(ut) => ut,
191 None => return,
192 };
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);
197 }
198
199 /// Mark that a unit has finished running.
200 pub fn unit_finished(&mut self, id: JobId, unlocked: Vec<&Unit<'a>>) {
201 if !self.enabled {
202 return;
203 }
204 // See note above in `unit_rmeta_finished`, this may not always be active.
205 let mut unit_time = match self.active.remove(&id) {
206 Some(ut) => ut,
207 None => return,
208 };
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 {
214 let msg = format!(
215 "{}{} in {:.1}s",
216 unit_time.name_ver(),
217 unit_time.target,
218 unit_time.duration
219 );
220 let _ = self
221 .config
222 .shell()
223 .status_with_color("Completed", msg, termcolor::Color::Cyan);
224 }
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,
232 }
233 .to_json_string();
234 self.config.shell().stdout_println(msg);
235 }
236 self.unit_times.push(unit_time);
237 }
238
239 /// This is called periodically to mark the concurrency of internal structures.
240 pub fn mark_concurrency(
241 &mut self,
242 active: usize,
243 waiting: usize,
244 inactive: usize,
245 rustc_parallelism: usize,
246 ) {
247 if !self.enabled {
248 return;
249 }
250 let c = Concurrency {
251 t: d_as_f64(self.start.elapsed()),
252 active,
253 waiting,
254 inactive,
255 rustc_parallelism,
256 };
257 self.concurrency.push(c);
258 }
259
260 /// Mark that a fresh unit was encountered.
261 pub fn add_fresh(&mut self) {
262 self.total_fresh += 1;
263 }
264
265 /// Mark that a dirty unit was encountered.
266 pub fn add_dirty(&mut self) {
267 self.total_dirty += 1;
268 }
269
270 /// Take a sample of CPU usage
271 pub fn record_cpu(&mut self) {
272 if !self.enabled {
273 return;
274 }
275 let prev = match &mut self.last_cpu_state {
276 Some(state) => state,
277 None => return,
278 };
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) {
282 return;
283 }
284 let current = match State::current() {
285 Ok(s) => s,
286 Err(_) => return,
287 };
288 let pct_idle = current.idle_since(prev);
289 *prev = current;
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));
293 }
294
295 /// Call this when all units are finished.
296 pub fn finished(
297 &mut self,
298 bcx: &BuildContext<'_, '_>,
299 error: &Option<anyhow::Error>,
300 ) -> CargoResult<()> {
301 if !self.enabled {
302 return Ok(());
303 }
304 self.mark_concurrency(0, 0, 0, 0);
305 self.unit_times
306 .sort_unstable_by(|a, b| a.start.partial_cmp(&b.start).unwrap());
307 if self.report_html {
308 self.report_html(bcx, error)?;
309 }
310 Ok(())
311 }
312
313 /// Save HTML report to disk.
314 fn report_html(
315 &self,
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
324 .root_targets
325 .iter()
326 .map(|(name, _targets)| name.as_str())
327 .collect();
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.
333 writeln!(
334 f,
335 "<script>\n\
336 DURATION = {};",
337 f64::ceil(duration) as u32
338 )?;
339 self.write_js_data(&mut f)?;
340 write!(
341 f,
342 "{}\n\
343 </script>\n\
344 </body>\n\
345 </html>\n\
346 ",
347 include_str!("timings.js")
348 )?;
349 drop(f);
350 let msg = format!(
351 "report saved to {}",
352 std::env::current_dir()
353 .unwrap_or_default()
354 .join(&filename)
355 .display()
356 );
357 paths::link_or_copy(&filename, "cargo-timing.html")?;
358 self.config
359 .shell()
360 .status_with_color("Timing", msg, termcolor::Color::Cyan)?;
361 Ok(())
362 }
363
364 /// Render the summary table.
365 fn write_summary_table(
366 &self,
367 f: &mut impl Write,
368 duration: f64,
369 bcx: &BuildContext<'_, '_>,
370 error: &Option<anyhow::Error>,
371 ) -> CargoResult<()> {
372 let targets: Vec<String> = self
373 .root_targets
374 .iter()
375 .map(|(name, targets)| format!("{} ({})", name, targets.join(", ")))
376 .collect();
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)
380 } else {
381 "".to_string()
382 };
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
386 .concurrency
387 .iter()
388 .map(|c| c.rustc_parallelism)
389 .max()
390 .unwrap();
391 let rustc_info = render_rustc_info(bcx);
392 let error_msg = match error {
393 Some(e) => format!(
394 r#"\
395 <tr>
396 <td class="error-text">Error:</td><td>{}</td>
397 </tr>
398 "#,
399 e
400 ),
401 None => "".to_string(),
402 };
403 write!(
404 f,
405 r#"
406 <table class="my-table summary-table">
407 <tr>
408 <td>Targets:</td><td>{}</td>
409 </tr>
410 <tr>
411 <td>Profile:</td><td>{}</td>
412 </tr>
413 <tr>
414 <td>Fresh units:</td><td>{}</td>
415 </tr>
416 <tr>
417 <td>Dirty units:</td><td>{}</td>
418 </tr>
419 <tr>
420 <td>Total units:</td><td>{}</td>
421 </tr>
422 <tr>
423 <td>Max concurrency:</td><td>{} (jobs={} ncpu={})</td>
424 </tr>
425 <tr>
426 <td>Build start:</td><td>{}</td>
427 </tr>
428 <tr>
429 <td>Total time:</td><td>{}</td>
430 </tr>
431 <tr>
432 <td>rustc:</td><td>{}</td>
433 </tr>
434 <tr>
435 <td>Max (global) rustc threads concurrency:</td><td>{}</td>
436 </tr>
437 {}
438 </table>
439 "#,
440 targets,
441 self.profile,
442 self.total_fresh,
443 self.total_dirty,
444 self.total_fresh + self.total_dirty,
445 max_concurrency,
446 bcx.build_config.jobs,
447 num_cpus::get(),
448 self.start_str,
449 total_time,
450 rustc_info,
451 max_rustc_concurrency,
452 error_msg,
453 )?;
454 Ok(())
455 }
456
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
460 .unit_times
461 .iter()
462 .enumerate()
463 .map(|(i, ut)| (ut.unit, i))
464 .collect();
465 #[derive(serde::Serialize)]
466 struct UnitData {
467 i: usize,
468 name: String,
469 version: String,
470 mode: String,
471 target: String,
472 start: f64,
473 duration: f64,
474 rmeta_time: Option<f64>,
475 unlocked_units: Vec<usize>,
476 unlocked_rmeta_units: Vec<usize>,
477 }
478 let round = |x: f64| (x * 100.0).round() / 100.0;
479 let unit_data: Vec<UnitData> = self
480 .unit_times
481 .iter()
482 .enumerate()
483 .map(|(i, ut)| {
484 let mode = if ut.unit.mode.is_run_custom_build() {
485 "run-custom-build"
486 } else {
487 "todo"
488 }
489 .to_string();
490
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
495 .unlocked_units
496 .iter()
497 .filter_map(|unit| unit_map.get(unit).copied())
498 .collect();
499 let unlocked_rmeta_units: Vec<usize> = ut
500 .unlocked_rmeta_units
501 .iter()
502 .filter_map(|unit| unit_map.get(unit).copied())
503 .collect();
504 UnitData {
505 i,
506 name: ut.unit.pkg.name().to_string(),
507 version: ut.unit.pkg.version().to_string(),
508 mode,
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)),
513 unlocked_units,
514 unlocked_rmeta_units,
515 }
516 })
517 .collect();
518 writeln!(
519 f,
520 "const UNIT_DATA = {};",
521 serde_json::to_string_pretty(&unit_data)?
522 )?;
523 writeln!(
524 f,
525 "const CONCURRENCY_DATA = {};",
526 serde_json::to_string_pretty(&self.concurrency)?
527 )?;
528 writeln!(
529 f,
530 "const CPU_USAGE = {};",
531 serde_json::to_string_pretty(&self.cpu_usage)?
532 )?;
533 Ok(())
534 }
535
536 /// Render the table of all units.
537 fn write_unit_table(&self, f: &mut impl Write) -> CargoResult<()> {
538 write!(
539 f,
540 r#"
541 <table class="my-table">
542 <thead>
543 <tr>
544 <th></th>
545 <th>Unit</th>
546 <th>Total</th>
547 <th>Codegen</th>
548 <th>Features</th>
549 </tr>
550 </thead>
551 <tbody>
552 "#
553 )?;
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),
560 };
561 let features = unit.unit.features.join(", ");
562 write!(
563 f,
564 r#"
565 <tr>
566 <td>{}.</td>
567 <td>{}{}</td>
568 <td>{:.1}s</td>
569 <td>{}</td>
570 <td>{}</td>
571 </tr>
572 "#,
573 i + 1,
574 unit.name_ver(),
575 unit.target,
576 unit.duration,
577 codegen,
578 features,
579 )?;
580 }
581 write!(f, "</tbody>\n</table>\n")?;
582 Ok(())
583 }
584 }
585
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)
593 })
594 }
595
596 fn name_ver(&self) -> String {
597 format!("{} v{}", self.unit.pkg.name(), self.unit.pkg.version())
598 }
599 }
600
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
604 }
605
606 fn render_rustc_info(bcx: &BuildContext<'_, '_>) -> String {
607 let version = bcx
608 .rustc
609 .verbose_version
610 .lines()
611 .next()
612 .expect("rustc version");
613 let requested_target = bcx.build_config.requested_kind.short_name(bcx);
614 format!(
615 "{}<br>Host: {}<br>Target: {}",
616 version, bcx.rustc.host, requested_target
617 )
618 }
619
620 static HTML_TMPL: &str = r#"
621 <html>
622 <head>
623 <title>Cargo Build Timings — {ROOTS}</title>
624 <meta charset="utf-8">
625 <style type="text/css">
626 html {
627 font-family: sans-serif;
628 }
629
630 .canvas-container {
631 position: relative;
632 margin-top: 5px;
633 margin-bottom: 5px;
634 }
635
636 h1 {
637 border-bottom: 1px solid #c0c0c0;
638 }
639
640 .graph {
641 display: block;
642 }
643
644 .my-table {
645 margin-top: 20px;
646 margin-bottom: 20px;
647 border-collapse: collapse;
648 box-shadow: 0 5px 10px rgba(0, 0, 0, 0.1);
649 }
650
651 .my-table th {
652 color: #d5dde5;
653 background: #1b1e24;
654 border-bottom: 4px solid #9ea7af;
655 border-right: 1px solid #343a45;
656 font-size: 18px;
657 font-weight: 100;
658 padding: 12px;
659 text-align: left;
660 vertical-align: middle;
661 }
662
663 .my-table th:first-child {
664 border-top-left-radius: 3px;
665 }
666
667 .my-table th:last-child {
668 border-top-right-radius: 3px;
669 border-right:none;
670 }
671
672 .my-table tr {
673 border-top: 1px solid #c1c3d1;
674 border-bottom: 1px solid #c1c3d1;
675 font-size: 16px;
676 font-weight: normal;
677 }
678
679 .my-table tr:first-child {
680 border-top:none;
681 }
682
683 .my-table tr:last-child {
684 border-bottom:none;
685 }
686
687 .my-table tr:nth-child(odd) td {
688 background: #ebebeb;
689 }
690
691 .my-table tr:last-child td:first-child {
692 border-bottom-left-radius:3px;
693 }
694
695 .my-table tr:last-child td:last-child {
696 border-bottom-right-radius:3px;
697 }
698
699 .my-table td {
700 background: #ffffff;
701 padding: 10px;
702 text-align: left;
703 vertical-align: middle;
704 font-weight: 300;
705 font-size: 14px;
706 border-right: 1px solid #C1C3D1;
707 }
708
709 .my-table td:last-child {
710 border-right: 0px;
711 }
712
713 .summary-table td:first-child {
714 vertical-align: top;
715 text-align: right;
716 }
717
718 .input-table td {
719 text-align: center;
720 }
721
722 .error-text {
723 color: #e80000;
724 }
725
726 </style>
727 </head>
728 <body>
729
730 <h1>Cargo Build Timings</h1>
731 "#;
732
733 static HTML_CANVAS: &str = r#"
734 <table class="input-table">
735 <tr>
736 <td><label for="min-unit-time">Min unit time:</label></td>
737 <td><label for="scale">Scale:</label></td>
738 </tr>
739 <tr>
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>
742 </tr>
743 <tr>
744 <td><output for="min-unit-time" id="min-unit-time-output"></output></td>
745 <td><output for="scale" id="scale-output"></output></td>
746 </tr>
747 </table>
748
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>
752 </div>
753 <div class="canvas-container">
754 <canvas id="timing-graph" class="graph"></canvas>
755 </div>
756 "#;