Skip to content

Commit 6c1b610

Browse files
authored
feat(build-analysis): JSONL-based logging infra (#16150)
### What does this PR try to resolve? This adds A new JSONL-based logging infrastructure for `-Zbuild-analysis`. Some highlights: - JSONL logs stored in `~/.cargo/log/`. - Unique log file for each cargo invocation, with a run ID based on workspace hash and timestamp. - Uses background thread for non-blocking log writes. Open to use some other battle-tested crates in the future. - A example `build-started` log message is added. Note that this is completely different than the original SQLite based design. I realized this is better as we do writes and zero read during the build. We shouldn't pay the cost if we don't read those metrics. See the design doc <https://hackmd.io/K5-sGEJeR5mLGsJLXqsHrw> and #15844 ### How to test and review this PR? `CARGO_BUILD_ANALYSIS_ENABLED=true cargo -Zbuild-analysis check`
2 parents a5566ce + d0f58cd commit 6c1b610

File tree

7 files changed

+260
-16
lines changed

7 files changed

+260
-16
lines changed

Cargo.toml

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -183,7 +183,7 @@ ignore.workspace = true
183183
im-rc.workspace = true
184184
indexmap.workspace = true
185185
itertools.workspace = true
186-
jiff.workspace = true
186+
jiff = { workspace = true, features = ["serde", "std"] }
187187
jobserver.workspace = true
188188
lazycell.workspace = true
189189
libgit2-sys.workspace = true

src/cargo/core/compiler/build_config.rs

Lines changed: 1 addition & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -115,18 +115,6 @@ impl BuildConfig {
115115
(None, _) => false,
116116
};
117117

118-
let timing_outputs = match (cfg.analysis.as_ref(), gctx.cli_unstable().build_analysis) {
119-
// Enable HTML output to pretend we are persisting timing data for now.
120-
(Some(analysis), true) if analysis.enabled => vec![TimingOutput::Html],
121-
(Some(_), false) => {
122-
gctx.shell().warn(
123-
"ignoring 'build.analysis' config, pass `-Zbuild-analysis` to enable it",
124-
)?;
125-
Vec::new()
126-
}
127-
_ => Vec::new(),
128-
};
129-
130118
Ok(BuildConfig {
131119
requested_kinds,
132120
jobs,
@@ -142,7 +130,7 @@ impl BuildConfig {
142130
rustfix_diagnostic_server: Rc::new(RefCell::new(None)),
143131
export_dir: None,
144132
future_incompat_report: false,
145-
timing_outputs,
133+
timing_outputs: Vec::new(),
146134
sbom,
147135
compile_time_deps_only: false,
148136
})

src/cargo/ops/cargo_compile/mod.rs

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -53,8 +53,10 @@ use crate::core::{PackageId, PackageSet, SourceId, TargetKind, Workspace};
5353
use crate::drop_println;
5454
use crate::ops;
5555
use crate::ops::resolve::{SpecsAndResolvedFeatures, WorkspaceResolve};
56+
use crate::util::BuildLogger;
5657
use crate::util::context::{GlobalContext, WarningHandling};
5758
use crate::util::interning::InternedString;
59+
use crate::util::log_message::LogMessage;
5860
use crate::util::{CargoResult, StableHasher};
5961

6062
mod compile_filter;
@@ -155,7 +157,24 @@ pub fn compile_ws<'a>(
155157
exec: &Arc<dyn Executor>,
156158
) -> CargoResult<Compilation<'a>> {
157159
let interner = UnitInterner::new();
160+
let logger = BuildLogger::maybe_new(ws)?;
161+
162+
if let Some(ref logger) = logger {
163+
let rustc = ws.gctx().load_global_rustc(Some(ws))?;
164+
logger.log(LogMessage::BuildStarted {
165+
cwd: ws.gctx().cwd().to_path_buf(),
166+
host: rustc.host.to_string(),
167+
jobs: options.build_config.jobs,
168+
profile: options.build_config.requested_profile.to_string(),
169+
rustc_version: rustc.version.to_string(),
170+
rustc_version_verbose: rustc.verbose_version.clone(),
171+
target_dir: ws.target_dir().as_path_unlocked().to_path_buf(),
172+
workspace_root: ws.root().to_path_buf(),
173+
});
174+
}
175+
158176
let bcx = create_bcx(ws, options, &interner)?;
177+
159178
if options.build_config.unit_graph {
160179
unit_graph::emit_serialized_unit_graph(&bcx.roots, &bcx.unit_graph, ws.gctx())?;
161180
return Compilation::new(&bcx);

src/cargo/util/log_message.rs

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,49 @@
1+
//! Messages for logging.
2+
3+
use std::io::Write;
4+
use std::path::PathBuf;
5+
6+
use jiff::Timestamp;
7+
use serde::Serialize;
8+
9+
/// A log message.
10+
///
11+
/// Each variant represents a different type of event.
12+
#[derive(Serialize)]
13+
#[serde(tag = "reason", rename_all = "kebab-case")]
14+
pub enum LogMessage {
15+
/// Emitted when a build starts.
16+
BuildStarted {
17+
cwd: PathBuf,
18+
host: String,
19+
jobs: u32,
20+
profile: String,
21+
rustc_version: String,
22+
rustc_version_verbose: String,
23+
target_dir: PathBuf,
24+
workspace_root: PathBuf,
25+
},
26+
}
27+
28+
impl LogMessage {
29+
/// Serializes this message as a JSON log line directly to the writer.
30+
pub fn write_json_log<W: Write>(&self, writer: &mut W, run_id: &str) -> std::io::Result<()> {
31+
#[derive(Serialize)]
32+
struct LogEntry<'a> {
33+
run_id: &'a str,
34+
timestamp: Timestamp,
35+
#[serde(flatten)]
36+
msg: &'a LogMessage,
37+
}
38+
39+
let entry = LogEntry {
40+
run_id,
41+
timestamp: Timestamp::now(),
42+
msg: self,
43+
};
44+
45+
serde_json::to_writer(&mut *writer, &entry)?;
46+
writer.write_all(b"\n")?;
47+
Ok(())
48+
}
49+
}

src/cargo/util/logger.rs

Lines changed: 105 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,105 @@
1+
//! Build analysis logging infrastructure.
2+
3+
use std::io::{BufWriter, Write};
4+
use std::mem::ManuallyDrop;
5+
use std::path::Path;
6+
use std::sync::mpsc;
7+
use std::sync::mpsc::Sender;
8+
use std::thread::JoinHandle;
9+
10+
use cargo_util::paths;
11+
12+
use crate::CargoResult;
13+
use crate::core::Workspace;
14+
use crate::util::log_message::LogMessage;
15+
use crate::util::short_hash;
16+
17+
/// Logger for `-Zbuild-analysis`.
18+
pub struct BuildLogger {
19+
tx: ManuallyDrop<Sender<LogMessage>>,
20+
run_id: String,
21+
handle: Option<JoinHandle<()>>,
22+
}
23+
24+
impl BuildLogger {
25+
/// Creates a logger if `-Zbuild-analysis` is enabled.
26+
pub fn maybe_new(ws: &Workspace<'_>) -> CargoResult<Option<Self>> {
27+
let analysis = ws.gctx().build_config()?.analysis.as_ref();
28+
match (analysis, ws.gctx().cli_unstable().build_analysis) {
29+
(Some(analysis), true) if analysis.enabled => Ok(Some(Self::new(ws)?)),
30+
(Some(_), false) => {
31+
ws.gctx().shell().warn(
32+
"ignoring 'build.analysis' config, pass `-Zbuild-analysis` to enable it",
33+
)?;
34+
Ok(None)
35+
}
36+
_ => Ok(None),
37+
}
38+
}
39+
40+
fn new(ws: &Workspace<'_>) -> CargoResult<Self> {
41+
let run_id = Self::generate_run_id(ws)?;
42+
43+
let log_dir = ws.gctx().home().join("log");
44+
paths::create_dir_all(log_dir.as_path_unlocked())?;
45+
46+
let filename = format!("{run_id}.jsonl");
47+
let log_file = log_dir.open_rw_exclusive_create(
48+
Path::new(&filename),
49+
ws.gctx(),
50+
"build analysis log",
51+
)?;
52+
53+
let (tx, rx) = mpsc::channel::<LogMessage>();
54+
55+
let run_id_clone = run_id.clone();
56+
let handle = std::thread::spawn(move || {
57+
let mut writer = BufWriter::new(log_file);
58+
for msg in rx {
59+
let _ = msg.write_json_log(&mut writer, &run_id_clone);
60+
}
61+
let _ = writer.flush();
62+
});
63+
64+
Ok(Self {
65+
tx: ManuallyDrop::new(tx),
66+
run_id,
67+
handle: Some(handle),
68+
})
69+
}
70+
71+
/// Generates a unique run ID.
72+
///
73+
/// The format is `{timestamp}-{hash}`, with `:` and `.` in the timestamp
74+
/// removed to make it safe for filenames.
75+
/// For example, `20251024T194502773638Z-f891d525d52ecab3`.
76+
pub fn generate_run_id(ws: &Workspace<'_>) -> CargoResult<String> {
77+
let hash = short_hash(&ws.root());
78+
let timestamp = jiff::Timestamp::now().to_string().replace([':', '.'], "");
79+
Ok(format!("{timestamp}-{hash}"))
80+
}
81+
82+
/// Returns the run ID for this build session.
83+
pub fn run_id(&self) -> &str {
84+
&self.run_id
85+
}
86+
87+
/// Logs a message.
88+
pub fn log(&self, msg: LogMessage) {
89+
let _ = self.tx.send(msg);
90+
}
91+
}
92+
93+
impl Drop for BuildLogger {
94+
fn drop(&mut self) {
95+
// SAFETY: tx is dropped exactly once here to signal thread shutdown.
96+
// ManuallyDrop prevents automatic drop after this impl runs.
97+
unsafe {
98+
ManuallyDrop::drop(&mut self.tx);
99+
}
100+
101+
if let Some(handle) = self.handle.take() {
102+
let _ = handle.join();
103+
}
104+
}
105+
}

src/cargo/util/mod.rs

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -18,6 +18,7 @@ pub use self::into_url::IntoUrl;
1818
pub use self::into_url_with_base::IntoUrlWithBase;
1919
pub(crate) use self::io::LimitErrorReader;
2020
pub use self::lockserver::{LockServer, LockServerClient, LockServerStarted};
21+
pub use self::logger::BuildLogger;
2122
pub use self::once::OnceExt;
2223
pub use self::progress::{Progress, ProgressStyle};
2324
pub use self::queue::Queue;
@@ -55,6 +56,8 @@ mod io;
5556
pub mod job;
5657
pub mod lints;
5758
mod lockserver;
59+
pub mod log_message;
60+
mod logger;
5861
pub mod machine_message;
5962
pub mod network;
6063
mod once;

tests/testsuite/build_analysis.rs

Lines changed: 82 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,8 @@
33
use crate::prelude::*;
44

55
use cargo_test_support::basic_manifest;
6+
use cargo_test_support::compare::assert_e2e;
7+
use cargo_test_support::paths;
68
use cargo_test_support::project;
79
use cargo_test_support::str;
810

@@ -26,20 +28,98 @@ fn gated() {
2628
}
2729

2830
#[cargo_test]
29-
fn simple() {
31+
fn one_logfile_per_invocation() {
3032
let p = project()
3133
.file("Cargo.toml", &basic_manifest("foo", "0.0.0"))
3234
.file("src/lib.rs", "")
3335
.build();
3436

37+
let cargo_home = paths::cargo_home();
38+
let log_dir = cargo_home.join("log");
39+
40+
// First invocation
3541
p.cargo("check -Zbuild-analysis")
3642
.env("CARGO_BUILD_ANALYSIS_ENABLED", "true")
3743
.masquerade_as_nightly_cargo(&["build-analysis"])
3844
.with_stderr_data(str![[r#"
3945
[CHECKING] foo v0.0.0 ([ROOT]/foo)
40-
Timing report saved to [ROOT]/foo/target/cargo-timings/cargo-timing-[..].html
4146
[FINISHED] `dev` profile [unoptimized + debuginfo] target(s) in [ELAPSED]s
4247
4348
"#]])
4449
.run();
50+
51+
assert!(log_dir.exists());
52+
let entries = std::fs::read_dir(&log_dir).unwrap();
53+
let log_files: Vec<_> = entries
54+
.filter_map(Result::ok)
55+
.filter(|e| e.path().extension().and_then(|s| s.to_str()) == Some("jsonl"))
56+
.collect();
57+
58+
assert_eq!(log_files.len(), 1);
59+
60+
// Second invocation
61+
p.cargo("check -Zbuild-analysis")
62+
.env("CARGO_BUILD_ANALYSIS_ENABLED", "true")
63+
.masquerade_as_nightly_cargo(&["build-analysis"])
64+
.with_stderr_data(str![[r#"
65+
[FINISHED] `dev` profile [unoptimized + debuginfo] target(s) in [ELAPSED]s
66+
67+
"#]])
68+
.run();
69+
70+
let entries = std::fs::read_dir(&log_dir).unwrap();
71+
let log_files: Vec<_> = entries
72+
.filter_map(Result::ok)
73+
.filter(|e| e.path().extension().and_then(|s| s.to_str()) == Some("jsonl"))
74+
.collect();
75+
76+
assert_eq!(log_files.len(), 2);
77+
}
78+
79+
#[cargo_test]
80+
fn log_msg_build_started() {
81+
let p = project()
82+
.file("Cargo.toml", &basic_manifest("foo", "0.0.0"))
83+
.file("src/lib.rs", "")
84+
.build();
85+
86+
p.cargo("check -Zbuild-analysis")
87+
.env("CARGO_BUILD_ANALYSIS_ENABLED", "true")
88+
.masquerade_as_nightly_cargo(&["build-analysis"])
89+
.run();
90+
91+
let cargo_home = paths::cargo_home();
92+
let log_dir = cargo_home.join("log");
93+
assert!(log_dir.exists());
94+
95+
let entries = std::fs::read_dir(&log_dir).unwrap();
96+
let log_file = entries
97+
.filter_map(Result::ok)
98+
.find(|e| e.path().extension().and_then(|s| s.to_str()) == Some("jsonl"))
99+
.unwrap();
100+
101+
let content = std::fs::read_to_string(log_file.path()).unwrap();
102+
103+
assert_e2e().eq(
104+
&content,
105+
str![[r#"
106+
[
107+
{
108+
"cwd": "[ROOT]/foo",
109+
"host": "[HOST_TARGET]",
110+
"jobs": "{...}",
111+
"profile": "dev",
112+
"reason": "build-started",
113+
"run_id": "[..]T[..]Z-[..]",
114+
"rustc_version": "1.[..]",
115+
"rustc_version_verbose": "{...}",
116+
"target_dir": "[ROOT]/foo/target",
117+
"timestamp": "[..]T[..]Z",
118+
"workspace_root": "[ROOT]/foo"
119+
}
120+
]
121+
"#]]
122+
.is_json()
123+
.against_jsonlines(),
124+
);
45125
}

0 commit comments

Comments
 (0)