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