cargo/core/compiler/timings/
mod.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
6pub mod report;
7
8use super::CompileMode;
9use super::Unit;
10use super::UnitIndex;
11use crate::core::compiler::BuildContext;
12use crate::core::compiler::BuildRunner;
13use crate::core::compiler::job_queue::JobId;
14use crate::ops::cargo_report::timings::prepare_context;
15use crate::util::cpu::State;
16use crate::util::log_message::LogMessage;
17use crate::util::style;
18use crate::util::{CargoResult, GlobalContext};
19
20use cargo_util::paths;
21use std::collections::HashMap;
22use std::io::BufWriter;
23use std::time::{Duration, Instant};
24
25/// Tracking information for the entire build.
26///
27/// Methods on this structure are generally called from the main thread of a
28/// running [`JobQueue`] instance (`DrainState` in specific) when the queue
29/// receives messages from spawned off threads.
30///
31/// [`JobQueue`]: super::JobQueue
32pub struct Timings<'gctx> {
33    gctx: &'gctx GlobalContext,
34    /// Whether or not timings should be captured.
35    enabled: bool,
36    /// When Cargo started.
37    start: Instant,
38    /// A summary of the root units.
39    ///
40    /// A map from unit to index.
41    unit_to_index: HashMap<Unit, UnitIndex>,
42    /// Units that are in the process of being built.
43    /// When they finished, they are moved to `unit_times`.
44    active: HashMap<JobId, Unit>,
45    /// Last recorded state of the system's CPUs and when it happened
46    last_cpu_state: Option<State>,
47    last_cpu_recording: Instant,
48    /// Recorded CPU states, stored as tuples. First element is when the
49    /// recording was taken and second element is percentage usage of the
50    /// system.
51    cpu_usage: Vec<(f64, f64)>,
52}
53
54/// Section of compilation (e.g. frontend, backend, linking).
55#[derive(Copy, Clone, serde::Serialize)]
56pub struct CompilationSection {
57    /// Start of the section, as an offset in seconds from `UnitTime::start`.
58    pub start: f64,
59    /// End of the section, as an offset in seconds from `UnitTime::start`.
60    pub end: Option<f64>,
61}
62
63/// Data for a single compilation unit, prepared for serialization to JSON.
64///
65/// This is used by the HTML report's JavaScript to render the pipeline graph.
66#[derive(serde::Serialize)]
67pub struct UnitData {
68    pub i: UnitIndex,
69    pub name: String,
70    pub version: String,
71    pub mode: String,
72    pub target: String,
73    pub features: Vec<String>,
74    pub start: f64,
75    pub duration: f64,
76    pub unblocked_units: Vec<UnitIndex>,
77    pub unblocked_rmeta_units: Vec<UnitIndex>,
78    pub sections: Option<Vec<(report::SectionName, report::SectionData)>>,
79}
80
81impl<'gctx> Timings<'gctx> {
82    pub fn new(bcx: &BuildContext<'_, 'gctx>) -> Timings<'gctx> {
83        let start = bcx.gctx.creation_time();
84        let enabled = bcx.logger.is_some();
85
86        if !enabled {
87            return Timings {
88                gctx: bcx.gctx,
89                enabled,
90                start,
91                unit_to_index: HashMap::new(),
92                active: HashMap::new(),
93                last_cpu_state: None,
94                last_cpu_recording: Instant::now(),
95                cpu_usage: Vec::new(),
96            };
97        }
98
99        let last_cpu_state = match State::current() {
100            Ok(state) => Some(state),
101            Err(e) => {
102                tracing::info!("failed to get CPU state, CPU tracking disabled: {:?}", e);
103                None
104            }
105        };
106
107        Timings {
108            gctx: bcx.gctx,
109            enabled,
110            start,
111            unit_to_index: bcx.unit_to_index.clone(),
112            active: HashMap::new(),
113            last_cpu_state,
114            last_cpu_recording: Instant::now(),
115            cpu_usage: Vec::new(),
116        }
117    }
118
119    /// Mark that a unit has started running.
120    pub fn unit_start(&mut self, build_runner: &BuildRunner<'_, '_>, id: JobId, unit: Unit) {
121        let Some(logger) = build_runner.bcx.logger else {
122            return;
123        };
124        let mut target = if unit.target.is_lib()
125            && matches!(unit.mode, CompileMode::Build | CompileMode::Check { .. })
126        {
127            // Special case for brevity, since most dependencies hit this path.
128            "".to_string()
129        } else {
130            format!(" {}", unit.target.description_named())
131        };
132        match unit.mode {
133            CompileMode::Test => target.push_str(" (test)"),
134            CompileMode::Build => {}
135            CompileMode::Check { test: true } => target.push_str(" (check-test)"),
136            CompileMode::Check { test: false } => target.push_str(" (check)"),
137            CompileMode::Doc { .. } => target.push_str(" (doc)"),
138            CompileMode::Doctest => target.push_str(" (doc test)"),
139            CompileMode::Docscrape => target.push_str(" (doc scrape)"),
140            CompileMode::RunCustomBuild => target.push_str(" (run)"),
141        }
142        let start = self.start.elapsed().as_secs_f64();
143        logger.log(LogMessage::UnitStarted {
144            index: self.unit_to_index[&unit],
145            elapsed: start,
146        });
147
148        assert!(self.active.insert(id, unit).is_none());
149    }
150
151    /// Mark that the `.rmeta` file as generated.
152    pub fn unit_rmeta_finished(
153        &mut self,
154        build_runner: &BuildRunner<'_, '_>,
155        id: JobId,
156        unblocked: Vec<&Unit>,
157    ) {
158        let Some(logger) = build_runner.bcx.logger else {
159            return;
160        };
161        // `id` may not always be active. "fresh" units unconditionally
162        // generate `Message::Finish`, but this active map only tracks dirty
163        // units.
164        let Some(unit) = self.active.get(&id) else {
165            return;
166        };
167        let elapsed = self.start.elapsed().as_secs_f64();
168
169        let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
170        logger.log(LogMessage::UnitRmetaFinished {
171            index: self.unit_to_index[unit],
172            elapsed,
173            unblocked,
174        });
175    }
176
177    /// Mark that a unit has finished running.
178    pub fn unit_finished(
179        &mut self,
180        build_runner: &BuildRunner<'_, '_>,
181        id: JobId,
182        unblocked: Vec<&Unit>,
183    ) {
184        let Some(logger) = build_runner.bcx.logger else {
185            return;
186        };
187        // See note above in `unit_rmeta_finished`, this may not always be active.
188        let Some(unit) = self.active.remove(&id) else {
189            return;
190        };
191        let elapsed = self.start.elapsed().as_secs_f64();
192
193        let unblocked = unblocked.iter().map(|u| self.unit_to_index[u]).collect();
194        logger.log(LogMessage::UnitFinished {
195            index: self.unit_to_index[&unit],
196            elapsed,
197            unblocked,
198        });
199    }
200
201    /// Handle the start/end of a compilation section.
202    pub fn unit_section_timing(
203        &mut self,
204        build_runner: &BuildRunner<'_, '_>,
205        id: JobId,
206        section_timing: &SectionTiming,
207    ) {
208        let Some(logger) = build_runner.bcx.logger else {
209            return;
210        };
211        let Some(unit) = self.active.get(&id) else {
212            return;
213        };
214        let elapsed = self.start.elapsed().as_secs_f64();
215
216        let index = self.unit_to_index[&unit];
217        let section = section_timing.name.clone();
218        logger.log(match section_timing.event {
219            SectionTimingEvent::Start => LogMessage::UnitSectionStarted {
220                index,
221                elapsed,
222                section,
223            },
224            SectionTimingEvent::End => LogMessage::UnitSectionFinished {
225                index,
226                elapsed,
227                section,
228            },
229        })
230    }
231
232    /// Take a sample of CPU usage
233    pub fn record_cpu(&mut self) {
234        if !self.enabled {
235            return;
236        }
237        let Some(prev) = &mut self.last_cpu_state else {
238            return;
239        };
240        // Don't take samples too frequently, even if requested.
241        let now = Instant::now();
242        if self.last_cpu_recording.elapsed() < Duration::from_millis(100) {
243            return;
244        }
245        let current = match State::current() {
246            Ok(s) => s,
247            Err(e) => {
248                tracing::info!("failed to get CPU state: {:?}", e);
249                return;
250            }
251        };
252        let pct_idle = current.idle_since(prev);
253        *prev = current;
254        self.last_cpu_recording = now;
255        let dur = now.duration_since(self.start).as_secs_f64();
256        self.cpu_usage.push((dur, 100.0 - pct_idle));
257    }
258
259    /// Call this when all units are finished.
260    pub fn finished(
261        &mut self,
262        build_runner: &BuildRunner<'_, '_>,
263        error: &Option<anyhow::Error>,
264    ) -> CargoResult<()> {
265        if let Some(logger) = build_runner.bcx.logger
266            && let Some(logs) = logger.get_logs()
267        {
268            let timings_path = build_runner
269                .files()
270                .timings_dir()
271                .expect("artifact-dir was not locked");
272            paths::create_dir_all(&timings_path)?;
273            let run_id = logger.run_id();
274            let filename = timings_path.join(format!("cargo-timing-{run_id}.html"));
275            let mut f = BufWriter::new(paths::create(&filename)?);
276
277            let mut ctx = prepare_context(logs.into_iter(), run_id)?;
278            ctx.error = error;
279            ctx.cpu_usage = &self.cpu_usage;
280            report::write_html(ctx, &mut f)?;
281
282            let unstamped_filename = timings_path.join("cargo-timing.html");
283            paths::link_or_copy(&filename, &unstamped_filename)?;
284
285            let mut shell = self.gctx.shell();
286            let timing_path = std::env::current_dir().unwrap_or_default().join(&filename);
287            let link = shell.err_file_hyperlink(&timing_path);
288            let msg = format!("report saved to {link}{}{link:#}", timing_path.display(),);
289            shell.status_with_color("Timing", msg, &style::NOTE)?;
290        }
291        Ok(())
292    }
293}
294
295/// Start or end of a section timing.
296#[derive(serde::Deserialize, Debug)]
297#[serde(rename_all = "kebab-case")]
298pub enum SectionTimingEvent {
299    Start,
300    End,
301}
302
303/// Represents a certain section (phase) of rustc compilation.
304/// It is emitted by rustc when the `--json=timings` flag is used.
305#[derive(serde::Deserialize, Debug)]
306pub struct SectionTiming {
307    pub name: String,
308    pub event: SectionTimingEvent,
309}
cargo/core/compiler/timings/mod.rs

cargo/core/compiler/timings/
mod.rs
