]> git.proxmox.com Git - cargo.git/blob - src/cargo/core/compiler/timings.rs
Auto merge of #10394 - dtolnay-contrib:displayerror, r=ehuss
[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, 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::thread::available_parallelism;
17 use std::time::{Duration, Instant, SystemTime};
18
19 pub struct Timings<'cfg> {
20 config: &'cfg Config,
21 /// Whether or not timings should be captured.
22 enabled: bool,
23 /// If true, saves an HTML report to disk.
24 report_html: 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>,
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
54 /// system.
55 cpu_usage: Vec<(f64, f64)>,
56 }
57
58 /// Tracking information for an individual unit.
59 struct UnitTime {
60 unit: Unit,
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>,
72 /// Same as `unlocked_units`, but unlocked by rmeta.
73 unlocked_rmeta_units: Vec<Unit>,
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<'cfg> Timings<'cfg> {
95 pub fn new(bcx: &BuildContext<'_, 'cfg>, root_units: &[Unit]) -> Timings<'cfg> {
96 let has_report = |what| bcx.build_config.timing_outputs.contains(&what);
97 let report_html = has_report(TimingOutput::Html);
98 let report_json = has_report(TimingOutput::Json);
99 let enabled = report_html | report_json;
100
101 let mut root_map: HashMap<PackageId, Vec<String>> = HashMap::new();
102 for unit in root_units {
103 let target_desc = unit.target.description_named();
104 root_map
105 .entry(unit.pkg.package_id())
106 .or_default()
107 .push(target_desc);
108 }
109 let root_targets = root_map
110 .into_iter()
111 .map(|(pkg_id, targets)| {
112 let pkg_desc = format!("{} {}", pkg_id.name(), pkg_id.version());
113 (pkg_desc, targets)
114 })
115 .collect();
116 let start_str = humantime::format_rfc3339_seconds(SystemTime::now()).to_string();
117 let profile = bcx.build_config.requested_profile.to_string();
118 let last_cpu_state = if enabled {
119 match State::current() {
120 Ok(state) => Some(state),
121 Err(e) => {
122 log::info!("failed to get CPU state, CPU tracking disabled: {:?}", e);
123 None
124 }
125 }
126 } else {
127 None
128 };
129
130 Timings {
131 config: bcx.config,
132 enabled,
133 report_html,
134 report_json,
135 start: bcx.config.creation_time(),
136 start_str,
137 root_targets,
138 profile,
139 total_fresh: 0,
140 total_dirty: 0,
141 unit_times: Vec::new(),
142 active: HashMap::new(),
143 concurrency: Vec::new(),
144 last_cpu_state,
145 last_cpu_recording: Instant::now(),
146 cpu_usage: Vec::new(),
147 }
148 }
149
150 /// Mark that a unit has started running.
151 pub fn unit_start(&mut self, id: JobId, unit: Unit) {
152 if !self.enabled {
153 return;
154 }
155 let mut target = if unit.target.is_lib() && unit.mode == CompileMode::Build {
156 // Special case for brevity, since most dependencies hit
157 // this path.
158 "".to_string()
159 } else {
160 format!(" {}", unit.target.description_named())
161 };
162 match unit.mode {
163 CompileMode::Test => target.push_str(" (test)"),
164 CompileMode::Build => {}
165 CompileMode::Check { test: true } => target.push_str(" (check-test)"),
166 CompileMode::Check { test: false } => target.push_str(" (check)"),
167 CompileMode::Bench => target.push_str(" (bench)"),
168 CompileMode::Doc { .. } => target.push_str(" (doc)"),
169 CompileMode::Doctest => target.push_str(" (doc test)"),
170 CompileMode::Docscrape => target.push_str(" (doc scrape)"),
171 CompileMode::RunCustomBuild => target.push_str(" (run)"),
172 }
173 let unit_time = UnitTime {
174 unit,
175 target,
176 start: self.start.elapsed().as_secs_f64(),
177 duration: 0.0,
178 rmeta_time: None,
179 unlocked_units: Vec::new(),
180 unlocked_rmeta_units: Vec::new(),
181 };
182 assert!(self.active.insert(id, unit_time).is_none());
183 }
184
185 /// Mark that the `.rmeta` file as generated.
186 pub fn unit_rmeta_finished(&mut self, id: JobId, unlocked: Vec<&Unit>) {
187 if !self.enabled {
188 return;
189 }
190 // `id` may not always be active. "fresh" units unconditionally
191 // generate `Message::Finish`, but this active map only tracks dirty
192 // units.
193 let unit_time = match self.active.get_mut(&id) {
194 Some(ut) => ut,
195 None => return,
196 };
197 let t = self.start.elapsed().as_secs_f64();
198 unit_time.rmeta_time = Some(t - unit_time.start);
199 assert!(unit_time.unlocked_rmeta_units.is_empty());
200 unit_time
201 .unlocked_rmeta_units
202 .extend(unlocked.iter().cloned().cloned());
203 }
204
205 /// Mark that a unit has finished running.
206 pub fn unit_finished(&mut self, id: JobId, unlocked: Vec<&Unit>) {
207 if !self.enabled {
208 return;
209 }
210 // See note above in `unit_rmeta_finished`, this may not always be active.
211 let mut unit_time = match self.active.remove(&id) {
212 Some(ut) => ut,
213 None => return,
214 };
215 let t = self.start.elapsed().as_secs_f64();
216 unit_time.duration = t - unit_time.start;
217 assert!(unit_time.unlocked_units.is_empty());
218 unit_time
219 .unlocked_units
220 .extend(unlocked.iter().cloned().cloned());
221 if self.report_json {
222 let msg = machine_message::TimingInfo {
223 package_id: unit_time.unit.pkg.package_id(),
224 target: &unit_time.unit.target,
225 mode: unit_time.unit.mode,
226 duration: unit_time.duration,
227 rmeta_time: unit_time.rmeta_time,
228 }
229 .to_json_string();
230 crate::drop_println!(self.config, "{}", msg);
231 }
232 self.unit_times.push(unit_time);
233 }
234
235 /// This is called periodically to mark the concurrency of internal structures.
236 pub fn mark_concurrency(
237 &mut self,
238 active: usize,
239 waiting: usize,
240 inactive: usize,
241 rustc_parallelism: usize,
242 ) {
243 if !self.enabled {
244 return;
245 }
246 let c = Concurrency {
247 t: self.start.elapsed().as_secs_f64(),
248 active,
249 waiting,
250 inactive,
251 rustc_parallelism,
252 };
253 self.concurrency.push(c);
254 }
255
256 /// Mark that a fresh unit was encountered.
257 pub fn add_fresh(&mut self) {
258 self.total_fresh += 1;
259 }
260
261 /// Mark that a dirty unit was encountered.
262 pub fn add_dirty(&mut self) {
263 self.total_dirty += 1;
264 }
265
266 /// Take a sample of CPU usage
267 pub fn record_cpu(&mut self) {
268 if !self.enabled {
269 return;
270 }
271 let prev = match &mut self.last_cpu_state {
272 Some(state) => state,
273 None => return,
274 };
275 // Don't take samples too too frequently, even if requested.
276 let now = Instant::now();
277 if self.last_cpu_recording.elapsed() < Duration::from_millis(100) {
278 return;
279 }
280 let current = match State::current() {
281 Ok(s) => s,
282 Err(e) => {
283 log::info!("failed to get CPU state: {:?}", e);
284 return;
285 }
286 };
287 let pct_idle = current.idle_since(prev);
288 *prev = current;
289 self.last_cpu_recording = now;
290 let dur = now.duration_since(self.start).as_secs_f64();
291 self.cpu_usage.push((dur, 100.0 - pct_idle));
292 }
293
294 /// Call this when all units are finished.
295 pub fn finished(
296 &mut self,
297 cx: &Context<'_, '_>,
298 error: &Option<anyhow::Error>,
299 ) -> CargoResult<()> {
300 if !self.enabled {
301 return Ok(());
302 }
303 self.mark_concurrency(0, 0, 0, 0);
304 self.unit_times
305 .sort_unstable_by(|a, b| a.start.partial_cmp(&b.start).unwrap());
306 if self.report_html {
307 self.report_html(cx, error)
308 .with_context(|| "failed to save timing report")?;
309 }
310 Ok(())
311 }
312
313 /// Save HTML report to disk.
314 fn report_html(&self, cx: &Context<'_, '_>, error: &Option<anyhow::Error>) -> CargoResult<()> {
315 let duration = self.start.elapsed().as_secs_f64();
316 let timestamp = self.start_str.replace(&['-', ':'][..], "");
317 let timings_path = cx.files().host_root().join("cargo-timings");
318 paths::create_dir_all(&timings_path)?;
319 let filename = timings_path.join(format!("cargo-timing-{}.html", timestamp));
320 let mut f = BufWriter::new(paths::create(&filename)?);
321 let roots: Vec<&str> = self
322 .root_targets
323 .iter()
324 .map(|(name, _targets)| name.as_str())
325 .collect();
326 f.write_all(HTML_TMPL.replace("{ROOTS}", &roots.join(", ")).as_bytes())?;
327 self.write_summary_table(&mut f, duration, cx.bcx, error)?;
328 f.write_all(HTML_CANVAS.as_bytes())?;
329 self.write_unit_table(&mut f)?;
330 // It helps with pixel alignment to use whole numbers.
331 writeln!(
332 f,
333 "<script>\n\
334 DURATION = {};",
335 f64::ceil(duration) as u32
336 )?;
337 self.write_js_data(&mut f)?;
338 write!(
339 f,
340 "{}\n\
341 </script>\n\
342 </body>\n\
343 </html>\n\
344 ",
345 include_str!("timings.js")
346 )?;
347 drop(f);
348 let msg = format!(
349 "report saved to {}",
350 std::env::current_dir()
351 .unwrap_or_default()
352 .join(&filename)
353 .display()
354 );
355 let unstamped_filename = timings_path.join("cargo-timing.html");
356 paths::link_or_copy(&filename, &unstamped_filename)?;
357 self.config
358 .shell()
359 .status_with_color("Timing", msg, termcolor::Color::Cyan)?;
360 Ok(())
361 }
362
363 /// Render the summary table.
364 fn write_summary_table(
365 &self,
366 f: &mut impl Write,
367 duration: f64,
368 bcx: &BuildContext<'_, '_>,
369 error: &Option<anyhow::Error>,
370 ) -> CargoResult<()> {
371 let targets: Vec<String> = self
372 .root_targets
373 .iter()
374 .map(|(name, targets)| format!("{} ({})", name, targets.join(", ")))
375 .collect();
376 let targets = targets.join("<br>");
377 let time_human = if duration > 60.0 {
378 format!(" ({}m {:.1}s)", duration as u32 / 60, duration % 60.0)
379 } else {
380 "".to_string()
381 };
382 let total_time = format!("{:.1}s{}", duration, time_human);
383 let max_concurrency = self.concurrency.iter().map(|c| c.active).max().unwrap();
384 let num_cpus = available_parallelism()
385 .map(|x| x.get().to_string())
386 .unwrap_or_else(|_| "n/a".into());
387 let max_rustc_concurrency = self
388 .concurrency
389 .iter()
390 .map(|c| c.rustc_parallelism)
391 .max()
392 .unwrap();
393 let rustc_info = render_rustc_info(bcx);
394 let error_msg = match error {
395 Some(e) => format!(
396 r#"\
397 <tr>
398 <td class="error-text">Error:</td><td>{}</td>
399 </tr>
400 "#,
401 e
402 ),
403 None => "".to_string(),
404 };
405 write!(
406 f,
407 r#"
408 <table class="my-table summary-table">
409 <tr>
410 <td>Targets:</td><td>{}</td>
411 </tr>
412 <tr>
413 <td>Profile:</td><td>{}</td>
414 </tr>
415 <tr>
416 <td>Fresh units:</td><td>{}</td>
417 </tr>
418 <tr>
419 <td>Dirty units:</td><td>{}</td>
420 </tr>
421 <tr>
422 <td>Total units:</td><td>{}</td>
423 </tr>
424 <tr>
425 <td>Max concurrency:</td><td>{} (jobs={} ncpu={})</td>
426 </tr>
427 <tr>
428 <td>Build start:</td><td>{}</td>
429 </tr>
430 <tr>
431 <td>Total time:</td><td>{}</td>
432 </tr>
433 <tr>
434 <td>rustc:</td><td>{}</td>
435 </tr>
436 <tr>
437 <td>Max (global) rustc threads concurrency:</td><td>{}</td>
438 </tr>
439 {}
440 </table>
441 "#,
442 targets,
443 self.profile,
444 self.total_fresh,
445 self.total_dirty,
446 self.total_fresh + self.total_dirty,
447 max_concurrency,
448 bcx.build_config.jobs,
449 num_cpus,
450 self.start_str,
451 total_time,
452 rustc_info,
453 max_rustc_concurrency,
454 error_msg,
455 )?;
456 Ok(())
457 }
458
459 fn write_js_data(&self, f: &mut impl Write) -> CargoResult<()> {
460 // Create a map to link indices of unlocked units.
461 let unit_map: HashMap<Unit, usize> = self
462 .unit_times
463 .iter()
464 .enumerate()
465 .map(|(i, ut)| (ut.unit.clone(), i))
466 .collect();
467 #[derive(serde::Serialize)]
468 struct UnitData {
469 i: usize,
470 name: String,
471 version: String,
472 mode: String,
473 target: String,
474 start: f64,
475 duration: f64,
476 rmeta_time: Option<f64>,
477 unlocked_units: Vec<usize>,
478 unlocked_rmeta_units: Vec<usize>,
479 }
480 let round = |x: f64| (x * 100.0).round() / 100.0;
481 let unit_data: Vec<UnitData> = self
482 .unit_times
483 .iter()
484 .enumerate()
485 .map(|(i, ut)| {
486 let mode = if ut.unit.mode.is_run_custom_build() {
487 "run-custom-build"
488 } else {
489 "todo"
490 }
491 .to_string();
492
493 // These filter on the unlocked units because not all unlocked
494 // units are actually "built". For example, Doctest mode units
495 // don't actually generate artifacts.
496 let unlocked_units: Vec<usize> = ut
497 .unlocked_units
498 .iter()
499 .filter_map(|unit| unit_map.get(unit).copied())
500 .collect();
501 let unlocked_rmeta_units: Vec<usize> = ut
502 .unlocked_rmeta_units
503 .iter()
504 .filter_map(|unit| unit_map.get(unit).copied())
505 .collect();
506 UnitData {
507 i,
508 name: ut.unit.pkg.name().to_string(),
509 version: ut.unit.pkg.version().to_string(),
510 mode,
511 target: ut.target.clone(),
512 start: round(ut.start),
513 duration: round(ut.duration),
514 rmeta_time: ut.rmeta_time.map(round),
515 unlocked_units,
516 unlocked_rmeta_units,
517 }
518 })
519 .collect();
520 writeln!(
521 f,
522 "const UNIT_DATA = {};",
523 serde_json::to_string_pretty(&unit_data)?
524 )?;
525 writeln!(
526 f,
527 "const CONCURRENCY_DATA = {};",
528 serde_json::to_string_pretty(&self.concurrency)?
529 )?;
530 writeln!(
531 f,
532 "const CPU_USAGE = {};",
533 serde_json::to_string_pretty(&self.cpu_usage)?
534 )?;
535 Ok(())
536 }
537
538 /// Render the table of all units.
539 fn write_unit_table(&self, f: &mut impl Write) -> CargoResult<()> {
540 write!(
541 f,
542 r#"
543 <table class="my-table">
544 <thead>
545 <tr>
546 <th></th>
547 <th>Unit</th>
548 <th>Total</th>
549 <th>Codegen</th>
550 <th>Features</th>
551 </tr>
552 </thead>
553 <tbody>
554 "#
555 )?;
556 let mut units: Vec<&UnitTime> = self.unit_times.iter().collect();
557 units.sort_unstable_by(|a, b| b.duration.partial_cmp(&a.duration).unwrap());
558 for (i, unit) in units.iter().enumerate() {
559 let codegen = match unit.codegen_time() {
560 None => "".to_string(),
561 Some((_rt, ctime, cent)) => format!("{:.1}s ({:.0}%)", ctime, cent),
562 };
563 let features = unit.unit.features.join(", ");
564 write!(
565 f,
566 r#"
567 <tr>
568 <td>{}.</td>
569 <td>{}{}</td>
570 <td>{:.1}s</td>
571 <td>{}</td>
572 <td>{}</td>
573 </tr>
574 "#,
575 i + 1,
576 unit.name_ver(),
577 unit.target,
578 unit.duration,
579 codegen,
580 features,
581 )?;
582 }
583 write!(f, "</tbody>\n</table>\n")?;
584 Ok(())
585 }
586 }
587
588 impl UnitTime {
589 /// Returns the codegen time as (rmeta_time, codegen_time, percent of total)
590 fn codegen_time(&self) -> Option<(f64, f64, f64)> {
591 self.rmeta_time.map(|rmeta_time| {
592 let ctime = self.duration - rmeta_time;
593 let cent = (ctime / self.duration) * 100.0;
594 (rmeta_time, ctime, cent)
595 })
596 }
597
598 fn name_ver(&self) -> String {
599 format!("{} v{}", self.unit.pkg.name(), self.unit.pkg.version())
600 }
601 }
602
603 fn render_rustc_info(bcx: &BuildContext<'_, '_>) -> String {
604 let version = bcx
605 .rustc()
606 .verbose_version
607 .lines()
608 .next()
609 .expect("rustc version");
610 let requested_target = bcx
611 .build_config
612 .requested_kinds
613 .iter()
614 .map(|kind| bcx.target_data.short_name(kind))
615 .collect::<Vec<_>>()
616 .join(", ");
617 format!(
618 "{}<br>Host: {}<br>Target: {}",
619 version,
620 bcx.rustc().host,
621 requested_target
622 )
623 }
624
625 static HTML_TMPL: &str = r#"
626 <html>
627 <head>
628 <title>Cargo Build Timings — {ROOTS}</title>
629 <meta charset="utf-8">
630 <style type="text/css">
631 html {
632 font-family: sans-serif;
633 }
634
635 .canvas-container {
636 position: relative;
637 margin-top: 5px;
638 margin-bottom: 5px;
639 }
640
641 h1 {
642 border-bottom: 1px solid #c0c0c0;
643 }
644
645 .graph {
646 display: block;
647 }
648
649 .my-table {
650 margin-top: 20px;
651 margin-bottom: 20px;
652 border-collapse: collapse;
653 box-shadow: 0 5px 10px rgba(0, 0, 0, 0.1);
654 }
655
656 .my-table th {
657 color: #d5dde5;
658 background: #1b1e24;
659 border-bottom: 4px solid #9ea7af;
660 border-right: 1px solid #343a45;
661 font-size: 18px;
662 font-weight: 100;
663 padding: 12px;
664 text-align: left;
665 vertical-align: middle;
666 }
667
668 .my-table th:first-child {
669 border-top-left-radius: 3px;
670 }
671
672 .my-table th:last-child {
673 border-top-right-radius: 3px;
674 border-right:none;
675 }
676
677 .my-table tr {
678 border-top: 1px solid #c1c3d1;
679 border-bottom: 1px solid #c1c3d1;
680 font-size: 16px;
681 font-weight: normal;
682 }
683
684 .my-table tr:first-child {
685 border-top:none;
686 }
687
688 .my-table tr:last-child {
689 border-bottom:none;
690 }
691
692 .my-table tr:nth-child(odd) td {
693 background: #ebebeb;
694 }
695
696 .my-table tr:last-child td:first-child {
697 border-bottom-left-radius:3px;
698 }
699
700 .my-table tr:last-child td:last-child {
701 border-bottom-right-radius:3px;
702 }
703
704 .my-table td {
705 background: #ffffff;
706 padding: 10px;
707 text-align: left;
708 vertical-align: middle;
709 font-weight: 300;
710 font-size: 14px;
711 border-right: 1px solid #C1C3D1;
712 }
713
714 .my-table td:last-child {
715 border-right: 0px;
716 }
717
718 .summary-table td:first-child {
719 vertical-align: top;
720 text-align: right;
721 }
722
723 .input-table td {
724 text-align: center;
725 }
726
727 .error-text {
728 color: #e80000;
729 }
730
731 </style>
732 </head>
733 <body>
734
735 <h1>Cargo Build Timings</h1>
736 "#;
737
738 static HTML_CANVAS: &str = r#"
739 <table class="input-table">
740 <tr>
741 <td><label for="min-unit-time">Min unit time:</label></td>
742 <td><label for="scale">Scale:</label></td>
743 </tr>
744 <tr>
745 <td><input type="range" min="0" max="30" step="0.1" value="0" id="min-unit-time"></td>
746 <td><input type="range" min="1" max="50" value="20" id="scale"></td>
747 </tr>
748 <tr>
749 <td><output for="min-unit-time" id="min-unit-time-output"></output></td>
750 <td><output for="scale" id="scale-output"></output></td>
751 </tr>
752 </table>
753
754 <div id="pipeline-container" class="canvas-container">
755 <canvas id="pipeline-graph" class="graph" style="position: absolute; left: 0; top: 0; z-index: 0;"></canvas>
756 <canvas id="pipeline-graph-lines" style="position: absolute; left: 0; top: 0; z-index: 1; pointer-events:none;"></canvas>
757 </div>
758 <div class="canvas-container">
759 <canvas id="timing-graph" class="graph"></canvas>
760 </div>
761 "#;