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