diff --git a/src/macos.rs b/src/macos.rs index 6b981e4..b61a3ba 100644 --- a/src/macos.rs +++ b/src/macos.rs @@ -268,6 +268,12 @@ pub fn record( })?; let root_pid = build.id() as i32; let mut collector = recon::Collector::new(root_pid, clock); + collector.set_root_command( + command + .iter() + .map(|arg| arg.to_string_lossy().into_owned()) + .collect(), + ); collector.seed_threads(threads); let mut sink = TraceSink { writer }; @@ -293,6 +299,7 @@ pub fn record( collect(&mut session, &mut collector, &mut |message| { tracker.handle(message) })?; + collector.tick(&mut |message| tracker.handle(message))?; if let Some(ended) = ended && ended.elapsed() > DRAIN { @@ -323,6 +330,17 @@ pub fn record( let _ = session.wait(READ_INTERVAL.as_millis() as u64); } collector.flush(&mut |message| tracker.handle(message))?; + match collector.unnamed { + 0 => {} + 1 => note!( + "1 process ended before its command line could be read; it is named after its \ + program alone" + ), + n => note!( + "{n} processes ended before their command line could be read; they are named after \ + their program alone" + ), + } if collector.dropped > 0 { let times = match collector.dropped { 1 => "once".to_owned(), diff --git a/src/macos/event.rs b/src/macos/event.rs index 411659c..457ca2e 100644 --- a/src/macos/event.rs +++ b/src/macos/event.rs @@ -20,8 +20,9 @@ pub enum Event { Fork { child: i32, }, - /// The program a process is now running. + /// What a process is now running. Exec { + argv: Vec, executable: String, }, /// A `wait(2)` status. diff --git a/src/macos/kdebug.rs b/src/macos/kdebug.rs index d8e702f..7afc0dd 100644 --- a/src/macos/kdebug.rs +++ b/src/macos/kdebug.rs @@ -12,9 +12,11 @@ //! change between releases. `fs_usage(1)` and `ktrace(1)` use it too. use std::io; +use std::time::{Duration, SystemTime}; const CTL_KERN: i32 = 1; const KERN_KDEBUG: i32 = 24; +const KERN_PROCARGS2: i32 = 49; const KERN_KDENABLE: i32 = 3; const KERN_KDSETBUF: i32 = 4; @@ -206,10 +208,94 @@ fn describe(error: io::Error) -> io::Error { } } +/// The command line of a running process, as `(executable, argv)`. +/// +/// This fails while a process is still setting up a new program after `exec`, +/// and after it has exited. Callers retry for a short while. +pub fn command_line(pid: i32, buffer: &mut Vec) -> io::Result<(String, Vec)> { + let mut length = buffer.len(); + sysctl( + &mut [CTL_KERN, KERN_PROCARGS2, pid], + buffer.as_mut_ptr().cast(), + &mut length, + )?; + let data = &buffer[..length.min(buffer.len())]; + if data.len() < 4 { + return Err(io::Error::new(io::ErrorKind::InvalidData, "short procargs")); + } + // [argc][executable path][padding][argv][envp] + let count = i32::from_ne_bytes(data[0..4].try_into().expect("4 bytes")).max(0) as usize; + let rest = &data[4..]; + let executable_end = rest + .iter() + .position(|byte| *byte == 0) + .unwrap_or(rest.len()); + let executable = String::from_utf8_lossy(&rest[..executable_end]).into_owned(); + let rest = &rest[executable_end..]; + let argv_start = rest + .iter() + .position(|byte| *byte != 0) + .unwrap_or(rest.len()); + let argv = rest[argv_start..] + .split(|byte| *byte == 0) + .take(count) + .map(|arg| String::from_utf8_lossy(arg).into_owned()) + .collect(); + Ok((executable, argv)) +} + +/// When a process started. This tells processes apart when a pid is reused, +/// which happens often in a build of thousands of processes. +pub fn start_time(pid: i32) -> io::Result { + let mut info: libc::proc_bsdinfo = unsafe { std::mem::zeroed() }; + let size = size_of::() as i32; + // SAFETY: `info` is a valid, correctly sized destination for the call. + let written = unsafe { + libc::proc_pidinfo( + pid, + libc::PROC_PIDTBSDINFO, + 0, + std::ptr::from_mut(&mut info).cast(), + size, + ) + }; + if written != size { + return Err(io::Error::last_os_error()); + } + Ok(SystemTime::UNIX_EPOCH + + Duration::new(info.pbi_start_tvsec, info.pbi_start_tvusec as u32 * 1_000)) +} + +/// The file id of the program a process is running now. The kernel's execution +/// event identifies the new program by the same id. +pub fn image(pid: i32) -> io::Result { + use std::os::unix::ffi::OsStrExt; + use std::os::unix::fs::MetadataExt; + + let mut path = [0_u8; libc::PROC_PIDPATHINFO_MAXSIZE as usize]; + // SAFETY: `path` is a valid destination of the length given. + let length = unsafe { libc::proc_pidpath(pid, path.as_mut_ptr().cast(), path.len() as u32) }; + if length <= 0 { + return Err(io::Error::last_os_error()); + } + let path = std::ffi::OsStr::from_bytes(&path[..length as usize]); + Ok(std::fs::metadata(path)?.ino()) +} + #[cfg(test)] mod tests { use super::*; + #[test] + fn own_image_is_this_test_binary() { + use std::os::unix::fs::MetadataExt; + + let expected = std::fs::metadata(std::env::current_exe().unwrap()) + .unwrap() + .ino(); + assert_eq!(image(std::process::id() as i32).unwrap(), expected); + } + #[test] fn decodes_a_record() { let mut record = [0_u8; EVENT_BYTES]; @@ -224,4 +310,30 @@ mod tests { assert_eq!(event.code(), 0x0401_0004); assert!(event.is_end()); } + + #[test] + fn reads_own_command_line() { + let mut buffer = vec![0_u8; 1 << 16]; + let (executable, argv) = + command_line(std::process::id() as i32, &mut buffer).expect("own argv"); + assert!( + executable.contains("kdebug") || executable.contains("buildprof"), + "{executable}" + ); + assert!(!argv.is_empty()); + } + + #[test] + fn own_start_time_is_in_the_past() { + let started = start_time(std::process::id() as i32).expect("own start time"); + assert!(started <= SystemTime::now()); + assert!(start_time(-1).is_err()); + } + + #[test] + fn missing_process_is_an_error() { + let mut buffer = vec![0_u8; 1 << 16]; + // Pid 0 is the kernel. It has no argv to read. + assert!(command_line(0, &mut buffer).is_err()); + } } diff --git a/src/macos/recon.rs b/src/macos/recon.rs index bb547d4..82c3261 100644 --- a/src/macos/recon.rs +++ b/src/macos/recon.rs @@ -5,13 +5,15 @@ //! //! 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. +//! created it does. 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::kdebug; use super::tracker::Clock; use std::collections::{HashMap, HashSet}; use std::io; +use std::time::{Duration, SystemTime}; const NEWTHREAD: u32 = 0x0700_0004; const DATA_EXEC: u32 = 0x0700_0008; @@ -23,6 +25,73 @@ const PROC_EXIT: u32 = 0x0401_0004; /// also reports an exit when a process starts a new program. Anything further /// from the pid cancels the exit. const EXIT_HOLD_NS: u64 = 10_000_000; +/// 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; +/// How much later than its exec a process may claim to have started before it +/// is taken to be a different process that reused the pid. +const REUSE_TOLERANCE: Duration = Duration::from_millis(2); + +/// What a process reports about itself. This is when it started, its command +/// line, and the file id of the program it is running now. +pub struct Inspection { + pub started: SystemTime, + pub executable: String, + pub argv: Vec, + pub image: u64, +} + +fn inspect(pid: i32, buffer: &mut Vec) -> io::Result { + let started = kdebug::start_time(pid)?; + let (executable, argv) = kdebug::command_line(pid, buffer)?; + // Read after the arguments, so a program started in between is noticed. + let image = kdebug::image(pid)?; + Ok(Inspection { + started, + executable, + argv, + image, + }) +} + +/// Reads a process's command line and program. +type Inspect = Box) -> io::Result>; + +impl Unread { + /// What the process was running instead, if it had moved on. + fn moved_on(&self) -> Option<(String, Vec)> { + match self { + Self::MovedOn(executable, argv) => Some((executable.clone(), argv.clone())), + _ => None, + } + } +} + +/// Why a command line could not be used. +enum Unread { + /// Not readable yet. The new program may still be starting. + NotYet, + /// The process has exited, or its pid belongs to another process now. + Gone, + /// The process has started another program since, which has this + /// executable and these arguments. + MovedOn(String, Vec), +} + +/// A program whose command line is still to be read. Once reading is given up, +/// it waits only for the kernel to name the program. +struct PendingArgv { + pid: i32, + mach_time: u64, + /// The file id the kernel reported for the program, or zero. + image: u64, + give_up: bool, + /// What the process was running instead, when it had started another + /// program by the time it was read. + moved_on: Option<(String, Vec)>, + /// Whether the kernel's name for this program has arrived. + named: bool, +} struct HeldExit { pid: i32, @@ -36,12 +105,25 @@ pub struct Collector { clock: Clock, processes: HashSet, threads: HashMap, - /// Executions seen but not yet reported. The kernel names the new program - /// in a second event. - starting: 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. + names: HashMap, held_exits: Vec, + argv_retries: Vec, + /// The command Buildprof started the build with, until the build's first + /// program is seen. + root_command: Option>, + /// Reads a process's command line and program. Tests replace it. + inspect: Inspect, + /// The time of the newest event seen. Retries measure their window against + /// it. + latest: u64, + argv_buffer: Vec, /// Events the kernel dropped because the buffer filled. pub dropped: u64, + /// Processes whose command line was gone before it could be read. They are + /// named after their program alone. + pub unnamed: u64, } impl Collector { @@ -51,12 +133,24 @@ impl Collector { clock, processes: HashSet::from([root]), threads: HashMap::new(), - starting: HashMap::new(), + names: HashMap::new(), held_exits: Vec::new(), + argv_retries: Vec::new(), + root_command: None, + inspect: Box::new(inspect), + latest: 0, + argv_buffer: vec![0; 1 << 18], dropped: 0, + unnamed: 0, } } + /// Gives the command Buildprof started the build with. The build's first + /// program then needs no read, which fails for a command that exits at once. + pub fn set_root_command(&mut self, argv: Vec) { + self.root_command = Some(argv); + } + /// Threads that existed before tracing started. pub fn seed_threads(&mut self, map: impl IntoIterator) { self.threads.extend(map); @@ -70,6 +164,7 @@ impl Collector { let code = event.code(); let args = event.args; let thread = event.thread; + self.latest = self.latest.max(event.timestamp); match code { NEWTHREAD => { @@ -115,20 +210,17 @@ impl Collector { } match code { - DATA_EXEC => { - self.starting.insert(pid, event.timestamp); - } - // The program's name follows the execution that started it. + // The kernel reports the new program's file id as the third argument. + DATA_EXEC => return self.exec(pid, event.timestamp, args[2], out), + // The kernel names the new program right after the execution. STRING_EXEC => { - if let Some(mach_time) = self.starting.remove(&pid) { - out(Message { - mach_time, - pid, - ppid: 0, - event: Event::Exec { - executable: decode_string(&args), - }, - })?; + self.names.insert(pid, decode_string(&args)); + for pending in self + .argv_retries + .iter_mut() + .filter(|pending| pending.pid == pid) + { + pending.named = true; } } PROC_EXIT if event.is_end() => { @@ -144,8 +236,16 @@ impl Collector { Ok(()) } + /// Follows up the command lines that were not ready yet. + pub fn tick(&mut self, out: &mut impl FnMut(Message) -> io::Result<()>) -> io::Result<()> { + self.retry_command_lines(out, false) + } + /// Emits everything still held back, at the end of a recording. pub fn flush(&mut self, out: &mut impl FnMut(Message) -> io::Result<()>) -> io::Result<()> { + // A process's execution has to reach the trace before its exit ends it. + // The last reads therefore go first. + self.retry_command_lines(out, true)?; for exit in std::mem::take(&mut self.held_exits) { self.emit_exit(exit, out)?; } @@ -161,6 +261,184 @@ impl Collector { (nanoseconds as f64 * self.clock.ticks_per_ns()) as u64 } + /// Reads the command line of the program a process started at `mach_time`, + /// whose file id the kernel reported as `image`. A pid that started later + /// belongs to another process now. A process running a different program + /// has started another since. Neither command line is this program's. + fn command_line( + &mut self, + pid: i32, + mach_time: u64, + image: u64, + ) -> Result<(String, Vec), Unread> { + let inspection = match (self.inspect)(pid, &mut self.argv_buffer) { + Ok(inspection) => inspection, + Err(error) if error.raw_os_error() == Some(libc::ESRCH) => return Err(Unread::Gone), + Err(_) => return Err(Unread::NotYet), + }; + if inspection.started > self.clock.wall(mach_time) + REUSE_TOLERANCE { + return Err(Unread::Gone); + } + // The kernel reports zero for a file id that does not fit. + if image != 0 && inspection.image != image { + return Err(Unread::MovedOn(inspection.executable, inspection.argv)); + } + Ok((inspection.executable, inspection.argv)) + } + + fn exec( + &mut self, + pid: i32, + mach_time: u64, + image: u64, + out: &mut impl FnMut(Message) -> io::Result<()>, + ) -> io::Result<()> { + // 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. + if let Some(index) = self + .argv_retries + .iter() + .position(|pending| pending.pid == pid) + { + let earlier = self.argv_retries.remove(index); + self.settle(earlier, out)?; + } + if pid == self.root + && let Some(argv) = self.root_command.take() + { + let executable = argv.first().cloned().unwrap_or_default(); + return self.emit_exec(pid, mach_time, executable, argv, out); + } + match self.command_line(pid, mach_time, image) { + Ok((executable, argv)) => self.emit_exec(pid, mach_time, executable, argv, out), + // Come back to it even to give up. The kernel names the program in + // the event after this one. + Err(unread) => { + self.argv_retries.push(PendingArgv { + pid, + mach_time, + image, + give_up: !matches!(unread, Unread::NotYet), + moved_on: unread.moved_on(), + named: false, + }); + Ok(()) + } + } + } + + fn retry_command_lines( + &mut self, + out: &mut impl FnMut(Message) -> io::Result<()>, + last_chance: bool, + ) -> io::Result<()> { + for pending in std::mem::take(&mut self.argv_retries) { + let read = if pending.give_up { + Err(Unread::Gone) + } else { + self.command_line(pending.pid, pending.mach_time, pending.image) + }; + let deadline = pending.mach_time + self.ticks(ARGV_RETRY_NS); + let waiting = !last_chance && self.latest < deadline; + match read { + Ok((executable, argv)) => { + self.emit_exec(pending.pid, pending.mach_time, executable, argv, out)? + } + // Read again while the window lasts. A read that was given up + // on still waits for the kernel to name the program. + Err(unread) if waiting && (matches!(unread, Unread::NotYet) || !pending.named) => { + self.argv_retries.push(PendingArgv { + give_up: !matches!(unread, Unread::NotYet), + moved_on: pending.moved_on.or(unread.moved_on()), + ..pending + }); + } + Err(unread) => { + let moved_on = pending.moved_on.or(unread.moved_on()); + self.settle( + PendingArgv { + moved_on, + ..pending + }, + out, + )? + } + } + } + Ok(()) + } + + /// Reports a program whose own command line could not be read. A launcher + /// may start another program in the same process and pass its own arguments + /// on unchanged. /bin/sh does this when it starts bash. Such a launcher + /// keeps those arguments. A launcher whose successor has other arguments is + /// named after its program. + fn settle( + &mut self, + pending: PendingArgv, + out: &mut impl FnMut(Message) -> io::Result<()>, + ) -> io::Result<()> { + match pending.moved_on { + Some((executable, argv)) if self.passed_on(pending.pid, &argv) => { + self.emit_exec(pending.pid, pending.mach_time, executable, argv, out) + } + Some(_) => self.emit_named_exec(pending.pid, pending.mach_time, false, out), + None => self.emit_named_exec(pending.pid, pending.mach_time, true, out), + } + } + + /// Whether `argv` starts with the name the kernel gave the program that + /// `pid` started. A launcher's own arguments look like this once it has + /// passed them on. + fn passed_on(&self, pid: i32, argv: &[String]) -> bool { + let Some(name) = self.names.get(&pid).filter(|name| !name.is_empty()) else { + return false; + }; + let first = argv.first().map_or("", |arg| { + arg.rsplit('/') + .next() + .unwrap_or(arg) + .trim_start_matches('-') + }); + // The kernel cuts long names short. + first == name || (name.len() >= 15 && first.starts_with(name.as_str())) + } + + /// Reports an execution under the name the kernel gave it, without its + /// arguments. They count as `lost` unless the process started another + /// program that has them. + fn emit_named_exec( + &mut self, + pid: i32, + mach_time: u64, + lost: bool, + out: &mut impl FnMut(Message) -> io::Result<()>, + ) -> io::Result<()> { + if lost { + self.unnamed += 1; + } + let executable = self.names.get(&pid).cloned().unwrap_or_default(); + let argv = vec![executable.clone()]; + self.emit_exec(pid, mach_time, executable, argv, out) + } + + fn emit_exec( + &mut self, + pid: i32, + mach_time: u64, + executable: String, + argv: Vec, + out: &mut impl FnMut(Message) -> io::Result<()>, + ) -> io::Result<()> { + out(Message { + mach_time, + pid, + ppid: 0, + event: Event::Exec { argv, executable }, + }) + } + fn cancel_exit(&mut self, pid: i32) { self.held_exits.retain(|exit| exit.pid != pid); } @@ -170,11 +448,15 @@ impl Collector { now: u64, out: &mut impl FnMut(Message) -> io::Result<()>, ) -> io::Result<()> { - while let Some(index) = self - .held_exits - .iter() - .position(|exit| exit.believe_after <= now) - { + // 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| { + exit.believe_after <= now + && !self + .argv_retries + .iter() + .any(|pending| pending.pid == exit.pid) + }) { let exit = self.held_exits.remove(index); self.emit_exit(exit, out)?; } @@ -189,7 +471,7 @@ impl Collector { if exit.pid != self.root { self.processes.remove(&exit.pid); } - self.starting.remove(&exit.pid); + self.names.remove(&exit.pid); out(Message { mach_time: exit.mach_time, pid: exit.pid, @@ -273,11 +555,15 @@ mod tests { } } + /// An event the collector ignores, for moving time on. + const OTHER_EVENT: u32 = 0x0409_0000; + fn collector() -> Collector { let clock = Clock { origin: 0, numer: 1, denom: 1, + origin_wall: std::time::SystemTime::now(), }; let mut collector = Collector::new(100, clock); collector.seed_threads([(10, 100)]); @@ -285,10 +571,11 @@ mod tests { } #[test] - fn reports_a_process_and_what_it_runs() { + fn an_execution_whose_command_line_is_gone_is_named_after_its_program() { let mut stream = Stream::new(); stream.exec(10, 100, "make"); - let messages = stream.collect(&mut collector()); + let mut collector = collector(); + let messages = stream.collect(&mut collector); assert_eq!( messages, [Message { @@ -296,10 +583,28 @@ mod tests { pid: 100, ppid: 0, event: Event::Exec { + argv: vec!["make".into()], executable: "make".into(), }, }] ); + 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"); + let mut collector = collector(); + collector.set_root_command(vec!["true".into(), "--flag".into()]); + let messages = stream.collect(&mut collector); + // Only the first program is the command Buildprof started. + assert_eq!( + command_lines(&messages, 100), + [vec!["true".to_owned(), "--flag".into()], vec!["sh".into()]] + ); + assert_eq!(collector.unnamed, 1); } #[test] @@ -313,7 +618,7 @@ mod tests { assert_eq!(messages[0].pid, 100); assert!(matches!( &messages[1].event, - Event::Exec { executable } if executable == "cc" + Event::Exec { executable, .. } if executable == "cc" )); assert_eq!(messages[1].pid, 200); } @@ -327,6 +632,197 @@ mod tests { 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, and its exit is due + // long before the recording ends. + let child = -2_i32; + let mut stream = Stream::new(); + stream + .push(10, NEWTHREAD, [11, child as u64, 0, 0]) + .exec(11, child, "sh") + .push(11, PROC_EXIT | 2, [child as u64, 0, 0, 0]); + stream.time += 2 * EXIT_HOLD_NS; + stream.push(10, OTHER_EVENT, [0; 4]); + let messages = stream.collect(&mut collector()); + let child_events: Vec<_> = messages + .iter() + .filter(|message| message.pid == child) + .map(|message| &message.event) + .collect(); + // Its execution still reaches the trace before its exit, named after + // its program. + assert_eq!( + child_events, + [ + &Event::Exec { + argv: vec!["sh".into()], + executable: "sh".into(), + }, + &Event::Exit { stat: 0 }, + ] + ); + } + + /// The words the kernel's name event carries for `name`. + fn program_name(name: &str) -> [u64; 4] { + 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")); + } + words + } + + fn command_lines(messages: &[Message], pid: i32) -> Vec> { + messages + .iter() + .filter(|message| message.pid == pid) + .filter_map(|message| match &message.event { + Event::Exec { argv, .. } => Some(argv.clone()), + _ => None, + }) + .collect() + } + + fn running(argv: &[&str], image: u64) -> io::Result { + Ok(Inspection { + started: SystemTime::UNIX_EPOCH, + executable: argv[0].into(), + argv: argv.iter().map(|arg| (*arg).to_owned()).collect(), + image, + }) + } + + /// Feeds `stream` to `collector` and reads pending command lines after each + /// event. The recorder does the same after each batch. + fn collect_ticking(stream: &Stream, collector: &mut Collector) -> Vec { + let mut out = Vec::new(); + for event in &stream.events { + let mut push = |message| { + out.push(message); + Ok(()) + }; + collector.observe(event, &mut push).expect("observe"); + collector.tick(&mut push).expect("tick"); + } + out + } + + #[test] + fn a_process_that_starts_another_program_keeps_its_own_name() { + // /usr/bin/cc is a shim that runs the real clang in the same process, + // so by the time cc's command line is read, clang is running. + const CC: u64 = 0x1111; + const CLANG: u64 = 0x2222; + let mut collector = collector(); + collector.inspect = Box::new(|_, _| running(&["clang", "-c", "a.c"], CLANG)); + let mut stream = Stream::new(); + stream + .push(10, DATA_EXEC, [100, 0, CC, 0]) + .push(10, STRING_EXEC, program_name("cc")) + .push(10, DATA_EXEC, [100, 0, CLANG, 0]) + .push(10, STRING_EXEC, program_name("clang")); + let messages = stream.collect(&mut collector); + assert_eq!( + command_lines(&messages, 100), + [ + vec!["cc".to_owned()], + vec!["clang".into(), "-c".into(), "a.c".into()] + ] + ); + assert_eq!(collector.unnamed, 0); + } + + #[test] + fn a_launcher_that_passes_its_arguments_on_keeps_them() { + // /bin/sh starts bash in the same process straight away, with its own + // arguments, so by the time sh is read, bash has them. + const SH: u64 = 0x3333; + const BASH: u64 = 0x4444; + let mut collector = collector(); + collector.inspect = Box::new(|_, _| running(&["/bin/sh", "-c", "true"], BASH)); + let mut stream = Stream::new(); + stream + .push(10, DATA_EXEC, [100, 0, SH, 0]) + .push(10, STRING_EXEC, program_name("sh")) + .push(10, DATA_EXEC, [100, 0, BASH, 0]) + .push(10, STRING_EXEC, program_name("bash")); + let messages = stream.collect(&mut collector); + let sh = vec!["/bin/sh".to_owned(), "-c".into(), "true".into()]; + assert_eq!(command_lines(&messages, 100), [sh.clone(), sh]); + assert_eq!(collector.unnamed, 0); + } + + #[test] + fn a_command_line_is_retried_for_a_while_not_a_number_of_times() { + // Unreadable seven times, all within the window. + let mut reads = 0; + let mut collector = collector(); + collector.inspect = Box::new(move |_, _| { + reads += 1; + if reads <= 7 { + Err(io::Error::from_raw_os_error(libc::EINVAL)) + } else { + running(&["cc", "-c", "a.c"], 0) + } + }); + let mut stream = Stream::new(); + stream + .push(10, DATA_EXEC, [100, 0, 0, 0]) + .push(10, STRING_EXEC, program_name("cc")); + for _ in 0..8 { + stream.push(10, OTHER_EVENT, [0; 4]); + } + let messages = collect_ticking(&stream, &mut collector); + assert_eq!( + command_lines(&messages, 100), + [vec!["cc".to_owned(), "-c".into(), "a.c".into()]] + ); + 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 an_exit_is_only_believed_when_nothing_follows_it() { // The kernel reports an exit when an image is replaced, too. diff --git a/src/macos/tracker.rs b/src/macos/tracker.rs index fbf840b..152b3c9 100644 --- a/src/macos/tracker.rs +++ b/src/macos/tracker.rs @@ -11,6 +11,7 @@ use crate::perfetto::Writer; use std::collections::{HashMap, HashSet}; use std::io; use std::path::Path; +use std::time::{Duration, SystemTime}; /// The raw exit status of a child that `posix_spawn` created but could not /// exec. `posix_spawnp` tries each `PATH` directory in turn, so one spawn can @@ -43,6 +44,8 @@ pub struct Clock { pub origin: u64, pub numer: u32, pub denom: u32, + /// When the origin was, on the wall clock. + pub origin_wall: SystemTime, } // libc deprecates these in favour of the mach2 crate. Two calls do not justify @@ -56,6 +59,7 @@ impl Clock { origin: mach_now(), numer: timebase.numer.max(1), denom: timebase.denom.max(1), + origin_wall: SystemTime::now(), } } @@ -72,6 +76,11 @@ impl Clock { pub fn ticks_per_ns(&self) -> f64 { f64::from(self.denom) / f64::from(self.numer) } + + /// When an event happened, on the wall clock. + pub fn wall(&self, mach_time: u64) -> SystemTime { + self.origin_wall + Duration::from_nanos(self.ns(mach_time)) + } } #[allow(deprecated)] @@ -157,7 +166,7 @@ impl<'a, S: Sink> Tracker<'a, S> { self.start_process(child, pid, timestamp_ns); } } - Event::Exec { executable } => self.exec(pid, timestamp_ns, executable)?, + Event::Exec { argv, executable } => self.exec(pid, timestamp_ns, argv, executable)?, Event::Exit { stat } => self.exit(pid, timestamp_ns, stat)?, } Ok(()) @@ -208,13 +217,26 @@ impl<'a, S: Sink> Tracker<'a, S> { ); } - fn exec(&mut self, pid: i32, timestamp_ns: u64, executable: String) -> io::Result<()> { - self.blind_spots.observe(std::slice::from_ref(&executable)); - let name = Path::new(&executable) - .file_name() - .map(|name| name.to_string_lossy().into_owned()) - .unwrap_or_else(|| format!("pid:{pid}")); - let command = executable.clone(); + fn exec( + &mut self, + pid: i32, + timestamp_ns: u64, + mut argv: Vec, + executable: String, + ) -> io::Result<()> { + if argv.is_empty() { + argv.push(executable.clone()); + } + self.blind_spots.observe(&argv); + let name = Path::new( + argv.first() + .filter(|arg| !arg.is_empty()) + .unwrap_or(&executable), + ) + .file_name() + .map(|name| name.to_string_lossy().into_owned()) + .unwrap_or_else(|| format!("pid:{pid}")); + let command = argv.join(" "); let Some(state) = self.processes.get_mut(&pid) else { return Ok(()); }; @@ -299,6 +321,7 @@ mod tests { origin: 1000, numer: 1, denom: 1, + origin_wall: SystemTime::UNIX_EPOCH, } } @@ -312,9 +335,10 @@ mod tests { } } - fn exec(program: &str) -> Event { + fn exec(argv: &[&str]) -> Event { Event::Exec { - executable: format!("/usr/bin/{program}"), + argv: argv.iter().map(|arg| (*arg).to_owned()).collect(), + executable: format!("/usr/bin/{}", argv[0]), } } @@ -340,13 +364,13 @@ 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")), + at(1001, 10, 1, exec(&["make", "-j2"])), 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")), - at(1020, 11, 10, exec("sh")), + at(1015, 12, 10, exec(&["cc", "-c", "a.c"])), + at(1020, 11, 10, exec(&["sh", "-c", "true"])), 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 }), ] { @@ -358,11 +382,11 @@ mod tests { records.0, [ "start 12", - r#"segment 12 parent=10 build_parent=10 execed=true 15..40 "/usr/bin/cc" exit=Some(0)"#, + r#"segment 12 parent=10 build_parent=10 execed=true 15..40 "cc -c a.c" exit=Some(0)"#, "start 11", - r#"segment 11 parent=10 build_parent=10 execed=true 10..50 "/usr/bin/sh" exit=Some(2)"#, + r#"segment 11 parent=10 build_parent=10 execed=true 10..50 "sh -c true" exit=Some(2)"#, "start 10", - r#"segment 10 parent=0 build_parent=0 execed=true 0..60 "/usr/bin/make" exit=Some(0)"#, + r#"segment 10 parent=0 build_parent=0 execed=true 0..60 "make -j2" exit=Some(0)"#, ] ); } @@ -373,8 +397,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")), - at(1005, 10, 1, exec("cc")), + at(1001, 10, 1, exec(&["sh", "-c", "true"])), + at(1005, 10, 1, exec(&["cc", "-c", "a.c"])), at(1009, 10, 1, Event::Exit { stat: 9 }), ] { tracker.handle(message).unwrap(); @@ -383,8 +407,8 @@ mod tests { assert_eq!( records.0[1..], [ - r#"segment 10 parent=0 build_parent=0 execed=true 0..5 "/usr/bin/sh" exit=None"#, - r#"segment 10 parent=0 build_parent=0 execed=true 5..9 "/usr/bin/cc" exit=Some(137)"#, + 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)"#, ] ); } @@ -395,7 +419,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")), + at(1001, 10, 1, exec(&["make", "-j2"])), // 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 }), @@ -417,6 +441,7 @@ mod tests { origin: 100, numer: 125, denom: 3, + origin_wall: SystemTime::UNIX_EPOCH, }; assert_eq!(clock.ns(103), 125); assert_eq!(clock.ns(50), 0, "events before the origin clamp to it");