From b63a7e3d8436bd2f2b6c316c1ce3855709d73f25 Mon Sep 17 00:00:00 2001 From: Lalit Maganti Date: Wed, 16 Sep 2026 02:41:57 +0100 Subject: [PATCH] macos: record the files each process opens The kernel reports each path as the program passed it, without resolving it. A path can be relative to a working directory or to a directory descriptor. Opening the root reports no path at all. Buildprof therefore follows each process's working directory and the paths behind its open descriptors, and resolves each path against them. Open flags are stored with Linux's numbers, so the UI reads them the same way on both platforms. Recordings now carry file events, so --no-file-events makes a smaller recording on macOS. Collection costs about the same either way, because the same kernel events carry the working directories. --- src/macos.rs | 8 +- src/macos/event.rs | 58 +++- src/macos/kdebug.rs | 6 +- src/macos/recon.rs | 663 +++++++++++++++++++++++++++++++++---------- src/macos/tracker.rs | 82 ++++-- src/main.rs | 10 +- 6 files changed, 654 insertions(+), 173 deletions(-) diff --git a/src/macos.rs b/src/macos.rs index 0b779bb..bea3f24 100644 --- a/src/macos.rs +++ b/src/macos.rs @@ -249,6 +249,7 @@ pub fn record( command: &[OsString], writer: &mut Writer, blind_spots: &mut BlindSpots, + file_events: bool, ) -> io::Result { let Prepared { mut session, @@ -270,7 +271,12 @@ pub fn record( // written at the end. The recorder therefore outlives an interrupted build. ignore_interrupts(); let root_pid = build.id() as i32; - let mut collector = recon::Collector::new(root_pid, clock); + let mut collector = recon::Collector::new( + root_pid, + std::env::current_dir()?.to_string_lossy().into_owned(), + clock, + file_events, + ); collector.set_root_command( command .iter() diff --git a/src/macos/event.rs b/src/macos/event.rs index 457ca2e..8c609c3 100644 --- a/src/macos/event.rs +++ b/src/macos/event.rs @@ -2,7 +2,7 @@ // SPDX-License-Identifier: Apache-2.0 //! What the collector observed. The tracker turns these into the trace's -//! process segments. +//! process segments and file events. /// One thing a followed process did. #[derive(Debug, PartialEq)] @@ -20,13 +20,67 @@ pub enum Event { Fork { child: i32, }, - /// What a process is now running. Exec { argv: Vec, + cwd: String, executable: String, }, /// A `wait(2)` status. Exit { stat: i32, }, + /// `flags` are `open(2)` flags in Linux's numbering. The trace format and + /// the UI then read the same on both platforms. `fd` is -1 when the + /// collector does not report one. + Open { + path: String, + flags: u64, + fd: i32, + }, +} + +/// Converts Darwin `open(2)` flags to the Linux numbers the trace format +/// stores. +pub fn linux_open_flags(flags: u64) -> u64 { + const DARWIN_APPEND: u64 = 0x8; + const DARWIN_CREAT: u64 = 0x200; + const DARWIN_TRUNC: u64 = 0x400; + const DARWIN_EXCL: u64 = 0x800; + const DARWIN_DIRECTORY: u64 = 0x0010_0000; + const LINUX_CREAT: u64 = 0o100; + const LINUX_EXCL: u64 = 0o200; + const LINUX_TRUNC: u64 = 0o1000; + const LINUX_APPEND: u64 = 0o2000; + const LINUX_DIRECTORY: u64 = 0o200_000; + + // The access mode is the low two bits on both. + let mut linux = flags & 0o3; + for (darwin, linux_bit) in [ + (DARWIN_APPEND, LINUX_APPEND), + (DARWIN_CREAT, LINUX_CREAT), + (DARWIN_TRUNC, LINUX_TRUNC), + (DARWIN_EXCL, LINUX_EXCL), + (DARWIN_DIRECTORY, LINUX_DIRECTORY), + ] { + if flags & darwin != 0 { + linux |= linux_bit; + } + } + linux +} + +#[cfg(test)] +mod tests { + use super::linux_open_flags; + + #[test] + fn translates_open_flags() { + assert_eq!(linux_open_flags(0x0), 0); + // O_WRONLY | O_CREAT | O_TRUNC + assert_eq!(linux_open_flags(0x1 | 0x200 | 0x400), 0o1 | 0o100 | 0o1000); + // O_RDWR | O_APPEND | O_EXCL + assert_eq!(linux_open_flags(0x2 | 0x8 | 0x800), 0o2 | 0o2000 | 0o200); + // O_RDONLY | O_DIRECTORY + assert_eq!(linux_open_flags(0x0010_0000), 0o200_000); + } } diff --git a/src/macos/kdebug.rs b/src/macos/kdebug.rs index 800ae53..51ee93d 100644 --- a/src/macos/kdebug.rs +++ b/src/macos/kdebug.rs @@ -57,6 +57,10 @@ impl Event { self.debugid & !3 } + pub fn is_start(&self) -> bool { + self.debugid & 1 != 0 + } + pub fn is_end(&self) -> bool { self.debugid & 2 != 0 } @@ -315,7 +319,7 @@ mod tests { assert_eq!(event.args[0], 7); assert_eq!(event.thread, 99); assert_eq!(event.code(), 0x0401_0004); - assert!(event.is_end()); + assert!(event.is_end() && !event.is_start()); } #[test] diff --git a/src/macos/recon.rs b/src/macos/recon.rs index c5308c9..1e5f775 100644 --- a/src/macos/recon.rs +++ b/src/macos/recon.rs @@ -2,28 +2,76 @@ // SPDX-License-Identifier: Apache-2.0 //! Turns kernel trace events into what the build did. -//! //! The kernel reports every process on the machine. This follows only the ones //! the build started. A process belongs to the build if the process that -//! created it does. Command lines are not in the trace. They are read from the -//! process itself as soon as its execution appears. +//! created it does. +//! +//! The kernel reports each path as the program passed it. A path can be +//! relative to a working directory or to a directory descriptor. It can also +//! restart at the target of a symbolic link. This therefore keeps each +//! process's working directory and the paths behind its open descriptors. +//! +//! Command lines are not in the trace. They are read from the process itself as +//! soon as its execution appears. -use super::event::{Event, Message}; +use super::event::{Event, Message, linux_open_flags}; use super::kdebug; use super::tracker::Clock; use std::collections::{HashMap, HashSet}; use std::io; +// Process lifecycle, always traced. const NEWTHREAD: u32 = 0x0700_0004; const DATA_EXEC: u32 = 0x0700_0008; const STRING_EXEC: u32 = 0x0701_0008; const LOST_EVENTS: u32 = 0x0702_0008; const PROC_EXIT: u32 = 0x0401_0004; +const VFS_LOOKUP: u32 = 0x0301_0090; + +// The syscalls whose paths, descriptors and results are followed. +const OPEN: u32 = 0x040c_0014; +const OPEN_NOCANCEL: u32 = 0x040c_0638; +const OPEN_EXTENDED: u32 = 0x040c_0454; +const OPEN_DPROTECTED: u32 = 0x040c_0360; +const GUARDED_OPEN: u32 = 0x040c_06e4; +const GUARDED_OPEN_DPROTECTED: u32 = 0x040c_0790; +const OPENAT: u32 = 0x040c_073c; +const OPENAT_NOCANCEL: u32 = 0x040c_0740; +const OPENAT_DPROTECTED: u32 = 0x040c_0368; +const CHDIR: u32 = 0x040c_0030; +const FCHDIR: u32 = 0x040c_0034; +const CLOSE: u32 = 0x040c_0018; +const CLOSE_NOCANCEL: u32 = 0x040c_063c; +const GUARDED_CLOSE: u32 = 0x040c_06e8; +const DUP: u32 = 0x040c_00a4; +const DUP2: u32 = 0x040c_0168; +const FCNTL: u32 = 0x040c_0170; +const FCNTL_NOCANCEL: u32 = 0x040c_0658; + +const AT_FDCWD: i32 = -2; +const O_CLOEXEC: u64 = 0x0100_0000; +const O_DIRECTORY: u64 = 0x0010_0000; +const F_DUPFD: u64 = 0; +const F_SETFD: u64 = 2; +const F_DUPFD_CLOEXEC: u64 = 67; /// How long, in trace time after a program starts, to keep trying to read its /// command line. A read can land before the new program is ready. const ARGV_RETRY_NS: u64 = 50_000_000; +#[derive(Clone, Default)] +struct Process { + cwd: Option, + /// Descriptor to (path, close-on-exec). + fds: HashMap, bool)>, +} + +struct Call { + code: u32, + args: [u64; 4], + lookups: Vec, +} + /// What a process reports about itself. This is when it started, in trace time, /// its command line, and the file id of the program it is running now. pub struct Inspection { @@ -94,10 +142,10 @@ struct HeldExit { pub struct Collector { root: i32, clock: Clock, - processes: HashSet, + processes: HashMap, threads: HashMap, - /// The program each process is running, as the kernel names it. A process - /// whose command line could not be read is named after it. + lookups: HashMap>, + calls: HashMap, names: HashMap, /// Exits that wait for their process's command line to be read. held_exits: Vec, @@ -118,6 +166,7 @@ pub struct Collector { /// it. latest: u64, argv_buffer: Vec, + file_events: bool, /// Messages that happened after a program whose command line is still /// unread. They wait so that its execution reaches the tracker first. queued: Vec, @@ -132,12 +181,20 @@ pub struct Collector { } impl Collector { - pub fn new(root: i32, clock: Clock) -> Self { + pub fn new(root: i32, root_cwd: String, clock: Clock, file_events: bool) -> Self { Self { root, clock, - processes: HashSet::from([root]), + processes: HashMap::from([( + root, + Process { + cwd: Some(normalize(&root_cwd)), + fds: HashMap::new(), + }, + )]), threads: HashMap::new(), + lookups: HashMap::new(), + calls: HashMap::new(), names: HashMap::new(), held_exits: Vec::new(), new_tasks: HashMap::new(), @@ -147,6 +204,7 @@ impl Collector { inspect: Box::new(inspect), latest: 0, argv_buffer: vec![0; kdebug::command_line_space()], + file_events, queued: Vec::new(), dropped: 0, started: 0, @@ -242,22 +300,27 @@ impl Collector { if let Some(parent) = parent && parent != pid { - if self.processes.contains(&parent) { - self.started += 1; - self.cancel_exit(pid); - self.processes.insert(pid); - out(Message { - mach_time: event.timestamp, - pid: parent, - ppid: 0, - event: Event::Fork { child: pid }, - })?; - } else if pid != self.root && parent != 0 { + match self.processes.get(&parent).cloned() { + // A new process inherits its parent's directory and descriptors. + Some(state) => { + self.started += 1; + self.cancel_exit(pid); + self.processes.insert(pid, state); + out(Message { + mach_time: event.timestamp, + pid: parent, + ppid: 0, + event: Event::Fork { child: pid }, + })?; + } // Another process now has this pid, so stop following // it. The kernel itself (pid 0) also starts worker // threads in existing processes. Those are not new // processes. - self.processes.remove(&pid); + None if pid != self.root && parent != 0 => { + self.processes.remove(&pid); + } + None => {} } } return Ok(()); @@ -272,22 +335,11 @@ impl Collector { let Some(&pid) = self.threads.get(&thread) else { return Ok(()); }; - if !self.processes.contains(&pid) { + if !self.processes.contains_key(&pid) { return Ok(()); } match code { - // The kernel reports the new program's file id as the third argument. - DATA_EXEC => { - self.started += 1; - // The new program runs on the new task's thread. A start that - // failed has no such exec, and the old program carries on. - if let Some(asker) = self.new_tasks.remove(&thread) { - self.replaced.insert(asker); - } - return self.exec(pid, event.timestamp, args[2], out); - } - // The kernel names the new program right after the execution. STRING_EXEC => { self.names.insert(pid, decode_string(&args)); for pending in self @@ -297,6 +349,17 @@ impl Collector { { pending.named = true; } + return Ok(()); + } + // The kernel reports the new program's file id as the third argument. + DATA_EXEC => { + self.started += 1; + // The new program runs on the new task's thread. A start that + // failed has no such exec, and the old program carries on. + if let Some(asker) = self.new_tasks.remove(&thread) { + self.replaced.insert(asker); + } + return self.exec(pid, event.timestamp, args[2], out); } // The old program's end, not the process's. PROC_EXIT if event.is_end() && self.replaced.remove(&thread) => return Ok(()), @@ -314,9 +377,54 @@ impl Collector { }); return self.believe_exits(out); } + VFS_LOOKUP => { + let words = self.lookups.entry(thread).or_default(); + if event.is_start() { + words.clear(); + words.extend_from_slice(&args[1..]); + } else { + words.extend_from_slice(&args); + } + if event.is_end() { + let path = decode_string(&std::mem::take(words)); + if let Some(call) = self.calls.get_mut(&thread) { + call.lookups.push(path); + } + } + return Ok(()); + } _ => {} } - Ok(()) + + if !is_followed(code) { + return Ok(()); + } + if event.is_start() { + self.calls.insert( + thread, + Call { + code, + args, + lookups: Vec::new(), + }, + ); + return Ok(()); + } + if !event.is_end() { + return Ok(()); + } + let Some(call) = self.calls.remove(&thread) else { + return Ok(()); + }; + // The first argument of a syscall's end is its errno. + if call.code != code { + return Ok(()); + } + if args[0] != 0 { + return Ok(()); + } + let returned = args[1] as i64; + self.finish_call(pid, event.timestamp, &call, returned, out) } fn flush_held(&mut self, out: &mut dyn FnMut(Message) -> io::Result<()>) -> io::Result<()> { @@ -331,7 +439,7 @@ impl Collector { /// Pids the build started that have not been seen to exit. pub fn live_pids(&self) -> impl Iterator + '_ { - self.processes.iter().copied() + self.processes.keys().copied() } fn ticks(&self, nanoseconds: u64) -> u64 { @@ -365,6 +473,42 @@ impl Collector { Ok((inspection.executable, inspection.argv)) } + fn cancel_exit(&mut self, pid: i32) { + self.held_exits.retain(|exit| exit.pid != pid); + } + + fn believe_exits(&mut self, out: &mut dyn FnMut(Message) -> io::Result<()>) -> io::Result<()> { + // An exit waits for its process's command line. The execution then + // reaches the trace first, even if only named after its program. + while let Some(index) = self.held_exits.iter().position(|exit| { + !self + .argv_retries + .iter() + .any(|pending| pending.pid == exit.pid) + }) { + let exit = self.held_exits.remove(index); + self.emit_exit(exit, out)?; + } + Ok(()) + } + + fn emit_exit( + &mut self, + exit: HeldExit, + out: &mut dyn FnMut(Message) -> io::Result<()>, + ) -> io::Result<()> { + if exit.pid != self.root { + self.processes.remove(&exit.pid); + } + self.names.remove(&exit.pid); + out(Message { + mach_time: exit.mach_time, + pid: exit.pid, + ppid: 0, + event: Event::Exit { stat: exit.stat }, + }) + } + fn exec( &mut self, pid: i32, @@ -372,6 +516,9 @@ impl Collector { image: u64, out: &mut dyn FnMut(Message) -> io::Result<()>, ) -> io::Result<()> { + if let Some(state) = self.processes.get_mut(&pid) { + state.fds.retain(|_, (_, close_on_exec)| !*close_on_exec); + } // An earlier program whose command line is still unread can no longer // be read, because the process has started another one since. It is // named after its own program before the kernel names this one. @@ -510,52 +657,167 @@ impl Collector { argv: Vec, out: &mut dyn FnMut(Message) -> io::Result<()>, ) -> io::Result<()> { + let cwd = self + .processes + .get(&pid) + .and_then(|state| state.cwd.clone()) + .unwrap_or_default(); out(Message { mach_time, pid, ppid: 0, - event: Event::Exec { argv, executable }, + event: Event::Exec { + argv, + cwd, + executable, + }, }) } - fn cancel_exit(&mut self, pid: i32) { - self.held_exits.retain(|exit| exit.pid != pid); - } - - fn believe_exits(&mut self, out: &mut dyn FnMut(Message) -> io::Result<()>) -> io::Result<()> { - // An exit waits for its process's command line. The execution then - // reaches the trace first, even if only named after its program. - while let Some(index) = self.held_exits.iter().position(|exit| { - !self - .argv_retries - .iter() - .any(|pending| pending.pid == exit.pid) - }) { - let exit = self.held_exits.remove(index); - self.emit_exit(exit, out)?; + fn finish_call( + &mut self, + pid: i32, + mach_time: u64, + call: &Call, + returned: i64, + out: &mut dyn FnMut(Message) -> io::Result<()>, + ) -> io::Result<()> { + let code = call.code; + if is_open(code) { + let at = matches!(code, OPENAT | OPENAT_NOCANCEL | OPENAT_DPROTECTED); + let flags = match code { + GUARDED_OPEN | GUARDED_OPEN_DPROTECTED => call.args[3], + _ if at => call.args[2], + _ => call.args[1], + }; + let directory = at.then(|| call.args[0]).filter(|fd| *fd as i32 != AT_FDCWD); + let path = match call.lookups.first() { + Some(raw) => self.resolve(pid, raw, directory), + // Opening "/" is the one open the kernel logs no lookup for. + None if flags & O_DIRECTORY != 0 => Some("/".to_owned()), + None => return Ok(()), + }; + if let Some(state) = self.processes.get_mut(&pid) { + state + .fds + .insert(returned as i32, (path.clone(), flags & O_CLOEXEC != 0)); + } + if let Some(path) = path + && self.file_events + { + out(Message { + mach_time, + pid, + ppid: 0, + event: Event::Open { + path, + flags: linux_open_flags(flags), + fd: returned as i32, + }, + })?; + } + return Ok(()); + } + match code { + CHDIR => { + if let Some(raw) = call.lookups.first().cloned() { + let resolved = self.resolve(pid, &raw, None); + if let Some(state) = self.processes.get_mut(&pid) { + state.cwd = resolved; + } + } + } + FCHDIR => { + let path = self.fd_path(pid, call.args[0]); + if let Some(state) = self.processes.get_mut(&pid) { + state.cwd = path; + } + } + CLOSE | CLOSE_NOCANCEL | GUARDED_CLOSE => { + if let Some(state) = self.processes.get_mut(&pid) { + state.fds.remove(&(call.args[0] as i32)); + } + } + DUP | DUP2 | FCNTL | FCNTL_NOCANCEL => { + let (from, to, close_on_exec) = match code { + DUP => (call.args[0], returned, false), + DUP2 => (call.args[0], call.args[1] as i64, false), + _ => match call.args[1] { + F_DUPFD => (call.args[0], returned, false), + F_DUPFD_CLOEXEC => (call.args[0], returned, true), + F_SETFD => { + if let Some(state) = self.processes.get_mut(&pid) + && let Some(entry) = state.fds.get_mut(&(call.args[0] as i32)) + { + entry.1 = call.args[2] & 1 != 0; + } + return Ok(()); + } + _ => return Ok(()), + }, + }; + let path = self.fd_path(pid, from); + if let Some(state) = self.processes.get_mut(&pid) { + state.fds.insert(to as i32, (path, close_on_exec)); + } + } + _ => {} } Ok(()) } - fn emit_exit( - &mut self, - exit: HeldExit, - out: &mut dyn FnMut(Message) -> io::Result<()>, - ) -> io::Result<()> { - if exit.pid != self.root { - self.processes.remove(&exit.pid); + fn fd_path(&self, pid: i32, fd: u64) -> Option { + self.processes + .get(&pid)? + .fds + .get(&(fd as i32)) + .and_then(|(path, _)| path.clone()) + } + + /// Resolves a path as the kernel reported it. + fn resolve(&self, pid: i32, raw: &str, directory: Option) -> Option { + if raw.starts_with('/') { + return Some(normalize(raw)); } - self.names.remove(&exit.pid); - out(Message { - mach_time: exit.mach_time, - pid: exit.pid, - ppid: 0, - event: Event::Exit { stat: exit.stat }, - }) + let base = match directory { + Some(fd) => self.fd_path(pid, fd)?, + None => self.processes.get(&pid)?.cwd.clone()?, + }; + Some(normalize(&format!("{base}/{raw}"))) } } -/// Names arrive as little-endian words packed with the bytes of the name. +fn is_open(code: u32) -> bool { + matches!( + code, + OPEN | OPEN_NOCANCEL + | OPEN_EXTENDED + | OPEN_DPROTECTED + | GUARDED_OPEN + | GUARDED_OPEN_DPROTECTED + | OPENAT + | OPENAT_NOCANCEL + | OPENAT_DPROTECTED + ) +} + +fn is_followed(code: u32) -> bool { + is_open(code) + || matches!( + code, + CHDIR + | FCHDIR + | CLOSE + | CLOSE_NOCANCEL + | GUARDED_CLOSE + | DUP + | DUP2 + | FCNTL + | FCNTL_NOCANCEL + ) +} + +/// Paths arrive as little-endian words packed with the bytes of the name. fn decode_string(words: &[u64]) -> String { let mut bytes = Vec::with_capacity(words.len() * 8); for word in words { @@ -568,11 +830,39 @@ fn decode_string(words: &[u64]) -> String { String::from_utf8_lossy(&bytes[..end]).into_owned() } +/// Resolves `.` and `..` textually. It also maps the data volume's firmlinked +/// spelling to the path it names. +fn normalize(path: &str) -> String { + let path = path + .strip_prefix("/System/Volumes/Data") + .filter(|rest| rest.starts_with('/')) + .unwrap_or(path); + let mut parts: Vec<&str> = Vec::new(); + for part in path.split('/') { + match part { + "" | "." => {} + ".." => { + parts.pop(); + } + part => parts.push(part), + } + } + let mut resolved = String::with_capacity(path.len() + 1); + for part in parts { + resolved.push('/'); + resolved.push_str(part); + } + if resolved.is_empty() { + resolved.push('/'); + } + resolved +} + #[cfg(test)] mod tests { use super::*; - /// Builds the trace events a build produces, for tests. + /// Builds the trace events a syscall produces, for tests. struct Stream { events: Vec, time: u64, @@ -597,16 +887,38 @@ mod tests { self } - /// An execution: the kernel reports it, then names the program. - fn exec(&mut self, thread: u64, pid: i32, name: &str) -> &mut Self { - let mut bytes = name.as_bytes().to_vec(); - bytes.resize(32, 0); - let mut words = [0; 4]; - for (word, chunk) in words.iter_mut().zip(bytes.chunks(8)) { - *word = u64::from_le_bytes(chunk.try_into().expect("8 bytes")); + fn lookup(&mut self, thread: u64, vnode: u64, path: &str) -> &mut Self { + let mut words = vec![vnode]; + let mut bytes = path.as_bytes().to_vec(); + bytes.push(0); + while !bytes.len().is_multiple_of(8) { + bytes.push(0); + } + words.extend( + bytes + .chunks(8) + .map(|chunk| u64::from_le_bytes(chunk.try_into().expect("8 bytes"))), + ); + // A lookup is one start record and then continuations. + let first: [u64; 4] = [ + words[0], + words[1], + *words.get(2).unwrap_or(&0), + *words.get(3).unwrap_or(&0), + ]; + if words.len() <= 4 { + self.push(thread, VFS_LOOKUP | 3, first) + } else { + self.push(thread, VFS_LOOKUP | 1, first); + let rest = &words[4..]; + for (index, chunk) in rest.chunks(4).enumerate() { + let mut args = [0; 4]; + args[..chunk.len()].copy_from_slice(chunk); + let last = (index + 1) * 4 >= rest.len(); + self.push(thread, VFS_LOOKUP | if last { 2 } else { 0 }, args); + } + self } - self.push(thread, DATA_EXEC, [pid as u64, 0, 0, 0]); - self.push(thread, STRING_EXEC, words) } fn collect(&self, collector: &mut Collector) -> Vec { @@ -638,37 +950,44 @@ mod tests { numer: 1, denom: 1, }; - let mut collector = Collector::new(100, clock); + let mut collector = Collector::new(100, "/src".into(), clock, true); collector.seed_threads([(10, 100)]); collector } #[test] - fn an_execution_whose_command_line_is_gone_is_named_after_its_program() { + fn resolves_a_relative_open_against_the_working_directory() { let mut stream = Stream::new(); - stream.exec(10, 100, "make"); - let mut collector = collector(); - let messages = stream.collect(&mut collector); + stream + .push(10, OPEN | 1, [0, 0x601, 0o644, 0]) + .lookup(10, 0x1111, "out/a.o") + .push(10, OPEN | 2, [0, 5, 0, 0]); + let messages = stream.collect(&mut collector()); assert_eq!( messages, [Message { - mach_time: 1_010, + mach_time: 1_030, pid: 100, ppid: 0, - event: Event::Exec { - argv: vec!["make".into()], - executable: "make".into(), + event: Event::Open { + path: "/src/out/a.o".into(), + // O_WRONLY | O_CREAT | O_TRUNC + flags: 0o1101, + fd: 5, }, }] ); - assert_eq!(collector.unnamed, 1); } #[test] fn the_build_command_is_known_without_reading_it() { // `true` exits before anything can read it. let mut stream = Stream::new(); - stream.exec(10, 100, "true").exec(10, 100, "sh"); + stream + .push(10, DATA_EXEC, [100, 0, 0, 0]) + .push(10, STRING_EXEC, program_name("true")) + .push(10, DATA_EXEC, [100, 0, 0, 0]) + .push(10, STRING_EXEC, program_name("sh")); let mut collector = collector(); collector.set_root_command(vec!["true".into(), "--flag".into()]); let messages = stream.collect(&mut collector); @@ -681,38 +1000,63 @@ mod tests { } #[test] - fn a_new_process_is_followed_and_its_parent_reported() { + fn follows_chdir_and_directory_descriptors() { + let mut stream = Stream::new(); + // chdir("sub"), then openat(fd of "/src/dir", "b.o"). + stream + .push(10, CHDIR | 1, [0, 0, 0, 0]) + .lookup(10, 0x2222, "sub") + .push(10, CHDIR | 2, [0, 0, 0, 0]) + .push(10, OPEN | 1, [0, O_DIRECTORY, 0, 0]) + .lookup(10, 0x3333, "/src/dir") + .push(10, OPEN | 2, [0, 7, 0, 0]) + .push(10, OPENAT | 1, [7, 0, 0, 0]) + .lookup(10, 0x4444, "b.o") + .push(10, OPENAT | 2, [0, 8, 0, 0]) + // A plain open resolves against the new working directory. + .push(10, OPEN | 1, [0, 0x601, 0, 0]) + .lookup(10, 0x9999, "c.o") + .push(10, OPEN | 2, [0, 9, 0, 0]); + let messages = stream.collect(&mut collector()); + let paths: Vec<_> = messages + .iter() + .filter_map(|message| match &message.event { + Event::Open { path, .. } => Some(path.as_str()), + _ => None, + }) + .collect(); + assert_eq!(paths, ["/src/dir", "/src/dir/b.o", "/src/sub/c.o"]); + } + + #[test] + fn a_new_process_inherits_and_is_reported() { let mut stream = Stream::new(); stream .push(10, NEWTHREAD, [11, 200, 0, 0]) - .exec(11, 200, "cc"); + .push(11, OPEN | 1, [0, 0, 0, 0]) + .lookup(11, 0x6666, "child.txt") + .push(11, OPEN | 2, [0, 3, 0, 0]); let messages = stream.collect(&mut collector()); assert!(matches!(messages[0].event, Event::Fork { child: 200 })); assert_eq!(messages[0].pid, 100); assert!(matches!( &messages[1].event, - Event::Exec { executable, .. } if executable == "cc" + Event::Open { path, .. } if path == "/src/child.txt" )); assert_eq!(messages[1].pid, 200); } - #[test] - fn unrelated_processes_are_ignored() { - let mut stream = Stream::new(); - stream.exec(99, 999, "someone-else"); - let mut collector = collector(); - collector.seed_threads([(99, 999)]); - assert_eq!(stream.collect(&mut collector), []); - } - #[test] fn an_exit_waits_for_its_process_command_line() { // A child whose command line cannot be read exits. let child = -2_i32; + let mut name = [0_u64; 4]; + name[0] = u64::from_le_bytes(*b"sh\0\0\0\0\0\0"); let mut stream = Stream::new(); stream .push(10, NEWTHREAD, [11, child as u64, 0, 0]) - .exec(11, child, "sh") + .push(11, DATA_EXEC, [child as u64, 0, 0, 0]) + .push(11, STRING_EXEC, name) .push(11, PROC_EXIT | 2, [child as u64, 0, 0, 0]); stream.push(10, OTHER_EVENT, [0; 4]); let messages = stream.collect(&mut collector()); @@ -728,6 +1072,7 @@ mod tests { [ &Event::Exec { argv: vec!["sh".into()], + cwd: "/src".into(), executable: "sh".into(), }, &Event::Exit { stat: 0 }, @@ -854,10 +1199,69 @@ mod tests { assert_eq!(collector.unnamed, 0); } + #[test] + fn a_command_line_is_given_up_once_its_window_has_passed() { + let mut collector = collector(); + collector.inspect = Box::new(|_, _| Err(io::Error::from_raw_os_error(libc::EINVAL))); + let mut stream = Stream::new(); + stream + .push(10, DATA_EXEC, [100, 0, 0, 0]) + .push(10, STRING_EXEC, program_name("cc")) + .push(10, OTHER_EVENT, [0; 4]); + let early = collect_ticking(&stream, &mut collector); + assert!(command_lines(&early, 100).is_empty(), "{early:?}"); + let mut later = Stream::new(); + later.time = stream.time + ARGV_RETRY_NS; + later.push(10, OTHER_EVENT, [0; 4]); + let messages = collect_ticking(&later, &mut collector); + assert_eq!(command_lines(&messages, 100), [vec!["cc".to_owned()]]); + assert_eq!(collector.unnamed, 1); + } + + #[test] + fn a_process_already_gone_is_not_read_again() { + let reads = std::rc::Rc::new(std::cell::Cell::new(0)); + let counted = reads.clone(); + let mut collector = collector(); + collector.inspect = Box::new(move |_, _| { + counted.set(counted.get() + 1); + Err(io::Error::from_raw_os_error(libc::ESRCH)) + }); + let mut stream = Stream::new(); + stream + .push(10, DATA_EXEC, [100, 0, 0, 0]) + .push(10, STRING_EXEC, program_name("cc")); + for _ in 0..5 { + stream.push(10, OTHER_EVENT, [0; 4]); + } + let messages = collect_ticking(&stream, &mut collector); + assert_eq!(command_lines(&messages, 100), [vec!["cc".to_owned()]]); + assert_eq!(reads.get(), 1); + } + + #[test] + fn unrelated_processes_are_ignored() { + let mut stream = Stream::new(); + stream + .push(99, OPEN | 1, [0, 0x601, 0, 0]) + .lookup(99, 0x8888, "/elsewhere/x") + .push(99, OPEN | 2, [0, 3, 0, 0]); + let mut collector = collector(); + collector.seed_threads([(99, 999)]); + assert_eq!(stream.collect(&mut collector), []); + } + + #[test] + fn normalizes_paths() { + assert_eq!(normalize("/a/b/../c/./d"), "/a/c/d"); + assert_eq!(normalize("/a/../.."), "/"); + assert_eq!(normalize("/System/Volumes/Data/Users/x"), "/Users/x"); + } + #[test] fn a_program_is_reported_before_what_it_did_while_unread() { // sh's command line is not ready for the first three reads. Before it - // is read, sh starts a child, which exits. + // is read, sh starts a child, which opens a file and exits. let mut reads = 0; let mut collector = collector(); collector.inspect = Box::new(move |_, _| { @@ -874,8 +1278,11 @@ mod tests { .push(11, DATA_EXEC, [200, 0, 0, 0]) .push(11, STRING_EXEC, program_name("sh")) .push(11, NEWTHREAD, [12, 300, 0, 0]) - .push(12, PROC_EXIT | 2, [300, 0, 0, 0]) - .push(10, OTHER_EVENT, [0; 4]); + .push(12, OPEN | 1, [0, 0, 0, 0]) + .lookup(12, 0x6666, "a.c") + .push(12, OPEN | 2, [0, 3, 0, 0]) + .push(12, PROC_EXIT | 2, [300, 0, 0, 0]); + stream.push(10, OTHER_EVENT, [0; 4]); let mut messages = collect_ticking(&stream, &mut collector); collector .flush(&mut |message| { @@ -888,6 +1295,7 @@ mod tests { .map(|message| match &message.event { Event::Fork { child } => format!("{} fork {child}", message.pid), Event::Exec { argv, .. } => format!("{} exec {}", message.pid, argv.join(" ")), + Event::Open { path, .. } => format!("{} open {path}", message.pid), Event::Exit { .. } => format!("{} exit", message.pid), }) .collect(); @@ -897,51 +1305,12 @@ mod tests { "100 fork 200", "200 exec sh -c cc", "200 fork 300", - "300 exit" + "300 open /src/a.c", + "300 exit", ] ); } - #[test] - fn a_command_line_is_given_up_once_its_window_has_passed() { - let mut collector = collector(); - collector.inspect = Box::new(|_, _| Err(io::Error::from_raw_os_error(libc::EINVAL))); - let mut stream = Stream::new(); - stream - .push(10, DATA_EXEC, [100, 0, 0, 0]) - .push(10, STRING_EXEC, program_name("cc")) - .push(10, OTHER_EVENT, [0; 4]); - let early = collect_ticking(&stream, &mut collector); - assert!(command_lines(&early, 100).is_empty(), "{early:?}"); - let mut later = Stream::new(); - later.time = stream.time + ARGV_RETRY_NS; - later.push(10, OTHER_EVENT, [0; 4]); - let messages = collect_ticking(&later, &mut collector); - assert_eq!(command_lines(&messages, 100), [vec!["cc".to_owned()]]); - assert_eq!(collector.unnamed, 1); - } - - #[test] - fn a_process_already_gone_is_not_read_again() { - let reads = std::rc::Rc::new(std::cell::Cell::new(0)); - let counted = reads.clone(); - let mut collector = collector(); - collector.inspect = Box::new(move |_, _| { - counted.set(counted.get() + 1); - Err(io::Error::from_raw_os_error(libc::ESRCH)) - }); - let mut stream = Stream::new(); - stream - .push(10, DATA_EXEC, [100, 0, 0, 0]) - .push(10, STRING_EXEC, program_name("cc")); - for _ in 0..5 { - stream.push(10, OTHER_EVENT, [0; 4]); - } - let messages = collect_ticking(&stream, &mut collector); - assert_eq!(command_lines(&messages, 100), [vec!["cc".to_owned()]]); - assert_eq!(reads.get(), 1); - } - #[test] fn a_pid_reused_after_its_exec_is_not_read() { // The exec is at trace time 1010. Only a process that started by then @@ -1004,7 +1373,8 @@ mod tests { let mut stream = Stream::new(); stream .push(10, NEWTHREAD, [11, 100, 1, 0]) - .exec(11, 100, "cc") + .push(11, DATA_EXEC, [100, 0, 0, 0]) + .push(11, STRING_EXEC, program_name("cc")) .push(10, PROC_EXIT | 1, [100, 0, 0, 0]) .push(10, PROC_EXIT | 2, [100, 0, 0, 0]) .push(11, PROC_EXIT | 1, [100, 256, 0, 0]) @@ -1038,7 +1408,8 @@ mod tests { .push(11, PROC_EXIT | 2, [100, 0, 0, 0]) .push(12, PROC_EXIT | 2, [100, 0, 0, 0]) .push(10, NEWTHREAD, [13, 100, 1, 0]) - .exec(13, 100, "pwd") + .push(13, DATA_EXEC, [100, 0, 0, 0]) + .push(13, STRING_EXEC, program_name("pwd")) .push(10, PROC_EXIT | 2, [100, 0, 0, 0]) .push(13, PROC_EXIT | 2, [100, 256, 0, 0]); let messages = stream.collect(&mut collector()); diff --git a/src/macos/tracker.rs b/src/macos/tracker.rs index a984c6e..f17dbf9 100644 --- a/src/macos/tracker.rs +++ b/src/macos/tracker.rs @@ -1,12 +1,12 @@ // Copyright 2026 The Buildprof Authors. // SPDX-License-Identifier: Apache-2.0 -//! Turns the collector's events into the same process segments the Linux -//! tracer records. +//! Turns the collector's events into the same process segments and file opens +//! the Linux tracer records. use super::event::{Event, Message}; use crate::blind_spots::BlindSpots; -use crate::model::{Process, Segment, exit_code}; +use crate::model::{FileOpen, Process, Segment, exit_code}; use crate::perfetto::Writer; use std::collections::{HashMap, HashSet}; use std::io; @@ -21,6 +21,7 @@ const FAILED_SPAWN_STAT: i32 = 1; pub trait Sink { fn process_started(&mut self, pid: i32) -> io::Result<()>; fn segment(&mut self, process: Process, segment: &Segment) -> io::Result<()>; + fn file_open(&mut self, pid: i32, open: &FileOpen) -> io::Result<()>; } /// The trace being recorded. @@ -35,6 +36,9 @@ impl Sink for TraceSink<'_> { fn segment(&mut self, process: Process, segment: &Segment) -> io::Result<()> { self.writer.segment(process, segment) } + fn file_open(&mut self, pid: i32, open: &FileOpen) -> io::Result<()> { + self.writer.file_open(pid, open) + } } /// Converts `mach_absolute_time` ticks to nanoseconds since recording began. @@ -157,8 +161,24 @@ impl<'a, S: Sink> Tracker<'a, S> { self.start_process(child, pid, timestamp_ns); } } - Event::Exec { argv, executable } => self.exec(pid, timestamp_ns, argv, executable)?, + Event::Exec { + argv, + cwd, + executable, + } => self.exec(pid, timestamp_ns, argv, cwd, executable)?, Event::Exit { stat } => self.exit(pid, timestamp_ns, stat)?, + Event::Open { path, flags, fd } => { + announce(self.sink, &mut self.announced, pid)?; + self.sink.file_open( + pid, + &FileOpen { + timestamp_ns, + path, + flags, + fd, + }, + )? + } } Ok(()) } @@ -213,6 +233,7 @@ impl<'a, S: Sink> Tracker<'a, S> { pid: i32, timestamp_ns: u64, mut argv: Vec, + cwd: String, executable: String, ) -> io::Result<()> { if argv.is_empty() { @@ -239,7 +260,7 @@ impl<'a, S: Sink> Tracker<'a, S> { end_ns: 0, name, command, - cwd: String::new(), + cwd, exit_code: None, }, ); @@ -250,6 +271,7 @@ impl<'a, S: Sink> Tracker<'a, S> { state.process.execed = true; state.segment.name = name; state.segment.command = command; + state.segment.cwd = cwd; } Ok(()) } @@ -293,7 +315,7 @@ mod tests { } fn segment(&mut self, process: Process, segment: &Segment) -> io::Result<()> { self.0.push(format!( - "segment {} parent={} build_parent={} execed={} {}..{} {:?} exit={:?}", + "segment {} parent={} build_parent={} execed={} {}..{} {:?} cwd={} exit={:?}", process.pid, process.parent_pid, process.build_parent_pid, @@ -301,10 +323,18 @@ mod tests { segment.start_ns, segment.end_ns, segment.command, + segment.cwd, segment.exit_code )); Ok(()) } + fn file_open(&mut self, pid: i32, open: &FileOpen) -> io::Result<()> { + self.0.push(format!( + "open {pid} {} {} flags={:o}", + open.timestamp_ns, open.path, open.flags + )); + Ok(()) + } } fn clock() -> Clock { @@ -325,9 +355,10 @@ mod tests { } } - fn exec(argv: &[&str]) -> Event { + fn exec(argv: &[&str], cwd: &str) -> Event { Event::Exec { argv: argv.iter().map(|arg| (*arg).to_owned()).collect(), + cwd: cwd.to_owned(), executable: format!("/usr/bin/{}", argv[0]), } } @@ -352,15 +383,25 @@ mod tests { fn records_a_build_tree() { let mut records = Records::default(); let mut blind_spots = BlindSpots::default(); - let mut tracker = tracker(&mut records, &mut blind_spots, "make"); + let mut tracker = tracker(&mut records, &mut blind_spots, "make -j2"); for message in [ - at(1001, 10, 1, exec(&["make", "-j2"])), + at(1001, 10, 1, exec(&["make", "-j2"], "/src")), at(1010, 10, 1, Event::Fork { child: 11 }), // A child started with posix_spawn is claimed through its parent. - at(1015, 12, 10, exec(&["cc", "-c", "a.c"])), - at(1020, 11, 10, exec(&["sh", "-c", "true"])), + at(1015, 12, 10, exec(&["cc", "-c", "a.c"], "/src")), + at(1020, 11, 10, exec(&["sh", "-c", "true"], "/src")), + at( + 1030, + 12, + 10, + Event::Open { + path: "/src/a.o".into(), + flags: 0o1101, + fd: 5, + }, + ), at(1040, 12, 10, Event::Exit { stat: 0 }), - at(1041, 99, 1, exec(&["unrelated"])), + at(1041, 99, 1, exec(&["unrelated"], "/")), at(1050, 11, 10, Event::Exit { stat: 2 << 8 }), at(1060, 10, 1, Event::Exit { stat: 0 }), ] { @@ -372,11 +413,12 @@ mod tests { records.0, [ "start 12", - r#"segment 12 parent=10 build_parent=10 execed=true 15..40 "cc -c a.c" exit=Some(0)"#, + "open 12 30 /src/a.o flags=1101", + r#"segment 12 parent=10 build_parent=10 execed=true 15..40 "cc -c a.c" cwd=/src exit=Some(0)"#, "start 11", - r#"segment 11 parent=10 build_parent=10 execed=true 10..50 "sh -c true" exit=Some(2)"#, + r#"segment 11 parent=10 build_parent=10 execed=true 10..50 "sh -c true" cwd=/src exit=Some(2)"#, "start 10", - r#"segment 10 parent=0 build_parent=0 execed=true 0..60 "make -j2" exit=Some(0)"#, + r#"segment 10 parent=0 build_parent=0 execed=true 0..60 "make -j2" cwd=/src exit=Some(0)"#, ] ); } @@ -387,8 +429,8 @@ mod tests { let mut blind_spots = BlindSpots::default(); let mut tracker = tracker(&mut records, &mut blind_spots, "sh"); for message in [ - at(1001, 10, 1, exec(&["sh", "-c", "true"])), - at(1005, 10, 1, exec(&["cc", "-c", "a.c"])), + at(1001, 10, 1, exec(&["sh", "-c", "exec cc"], "/")), + at(1005, 10, 1, exec(&["cc"], "/")), at(1009, 10, 1, Event::Exit { stat: 9 }), ] { tracker.handle(message).unwrap(); @@ -397,8 +439,8 @@ mod tests { assert_eq!( records.0[1..], [ - r#"segment 10 parent=0 build_parent=0 execed=true 0..5 "sh -c true" exit=None"#, - r#"segment 10 parent=0 build_parent=0 execed=true 5..9 "cc -c a.c" exit=Some(137)"#, + r#"segment 10 parent=0 build_parent=0 execed=true 0..5 "sh -c exec cc" cwd=/ exit=None"#, + r#"segment 10 parent=0 build_parent=0 execed=true 5..9 "cc" cwd=/ exit=Some(137)"#, ] ); } @@ -409,7 +451,7 @@ mod tests { let mut blind_spots = BlindSpots::default(); let mut tracker = tracker(&mut records, &mut blind_spots, "make"); for message in [ - at(1001, 10, 1, exec(&["make", "-j2"])), + at(1001, 10, 1, exec(&["make"], "/src")), // posix_spawnp trying a PATH directory without the program. at(1002, 10, 1, Event::Fork { child: 13 }), at(1003, 13, 10, Event::Exit { stat: 1 }), diff --git a/src/main.rs b/src/main.rs index aec8726..4f25cb4 100644 --- a/src/main.rs +++ b/src/main.rs @@ -126,8 +126,6 @@ fn record( } }; - // macOS recordings carry no file events yet. - let file_events = file_events && cfg!(target_os = "linux"); if let Err(error) = writer.collection_options(file_events, compiler_traces) { error!("could not write recording options: {error}"); return ExitCode::FAILURE; @@ -144,7 +142,13 @@ fn record( file_events, ); #[cfg(target_os = "macos")] - let result = macos::record(prepared, &command, &mut writer, &mut blind_spots); + let result = macos::record( + prepared, + &command, + &mut writer, + &mut blind_spots, + file_events, + ); let write_result = writer .data_loss(&blind_spots.findings()) .and_then(|()| writer.finish());