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