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