From 3bb124b52a6cbcf03b9a78126f767ed485f21545 Mon Sep 17 00:00:00 2001 From: Edward Amsden Date: Tue, 7 Nov 2023 09:50:26 -0600 Subject: [PATCH 01/16] cold state: fix matches() --- rust/ares/src/jets/cold.rs | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/rust/ares/src/jets/cold.rs b/rust/ares/src/jets/cold.rs index 84f2c2b..b5a7b62 100644 --- a/rust/ares/src/jets/cold.rs +++ b/rust/ares/src/jets/cold.rs @@ -341,6 +341,24 @@ impl Cold { } } + /** Try to match a core directly to the cold state, print the resulting path if found + */ + pub fn matches(&mut self, stack: &mut NockStack, core: &mut Noun) -> Option { + let mut battery = (*core).slot(2).ok()?; + unsafe { + let paths = (*(self.0)).battery_to_paths.lookup(stack, &mut battery)?; + for path in paths { + if let Some(batteries_list) = (*(self.0)).path_to_batteries.lookup(stack, &mut (*path)) { + + if let Some(_batt) = batteries_list.matches(stack, *core) { + return Some(*path); + } + } + }; + return None; + } + } + /// register a core, return a boolean of whether we actually needed to register (false -> /// already registered) /// From 63d91d3cd5b7b4293a0e696c70f8a50d1678d3e6 Mon Sep 17 00:00:00 2001 From: Edward Amsden Date: Thu, 9 Nov 2023 15:02:51 -0600 Subject: [PATCH 02/16] serf: add event-trace profiling (-j in king) for fast-hinted cores --- rust/ares/src/interpreter.rs | 184 ++++++++++++++++++++++++++++++++++- rust/ares/src/jets.rs | 1 + rust/ares/src/jets/bits.rs | 86 ++++++++-------- rust/ares/src/main.rs | 2 + rust/ares/src/mug.rs | 2 +- rust/ares/src/serf.rs | 103 ++++++++++++++++++-- 6 files changed, 327 insertions(+), 51 deletions(-) diff --git a/rust/ares/src/interpreter.rs b/rust/ares/src/interpreter.rs index 1c24f0e..04dd021 100644 --- a/rust/ares/src/interpreter.rs +++ b/rust/ares/src/interpreter.rs @@ -7,11 +7,14 @@ use crate::jets::cold::Cold; use crate::jets::hot::Hot; use crate::jets::warm::Warm; use crate::jets::JetErr; +use crate::jets::form::util::scow; +use crate::jets::bits::util::rap; use crate::mem::unifying_equality; use crate::mem::NockStack; +use crate::mug::met3_usize; use crate::newt::Newt; use crate::noun; -use crate::noun::{Atom, Cell, IndirectAtom, Noun, Slots, D, T}; +use crate::noun::{Atom, Cell, DirectAtom, IndirectAtom, Noun, Slots, D, T}; use crate::serf::TERMINATOR; use ares_macros::tas; use assert_no_alloc::assert_no_alloc; @@ -21,6 +24,11 @@ use std::result; use std::sync::atomic::Ordering; use std::sync::Arc; +use std::fs::File; +use std::time::Instant; +use json::object; +use std::io::Write; + crate::gdb!(); #[derive(Copy, Clone)] @@ -263,6 +271,19 @@ pub struct Context { // Per-event cache; option to share cache with virtualized events pub cache: Hamt, pub scry_stack: Noun, + pub trace_info: Option, +} + +pub struct TraceInfo { + pub file: File, + pub pid: u32, + pub process_start: Instant, +} + +pub struct TraceStack { + pub start: Instant, + pub path: Noun, + pub next: *const TraceStack, } #[derive(Clone, Copy, Debug)] @@ -303,9 +324,13 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res // Setup stack for Nock computation unsafe { - context.stack.frame_push(1); + context.stack.frame_push(2); // Bottom of mean stack *(context.stack.local_noun_pointer(0)) = D(0); + + // Bottom of trace stack + *(context.stack.local_noun_pointer(1) as *mut *const TraceStack) = std::ptr::null(); + *(context.stack.push()) = NockWork::Done; }; @@ -351,6 +376,49 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res debug_assertions(stack, subject); debug_assertions(stack, res); + // Write fast-hinted traces to file + if let Some(ref mut info) = &mut context.trace_info { + let mut trace_stack = *(stack.local_noun_pointer(1) as *const *const TraceStack); + let now = Instant::now(); + assert_no_alloc::permit_alloc(|| { + loop { + if trace_stack.is_null() { break; } + + let ts = (*trace_stack).start.saturating_duration_since(info.process_start).as_micros() as f64; + let dur = now.saturating_duration_since((*trace_stack).start).as_micros() as f64; + + let pc = path_to_cord(stack, (*trace_stack).path); + let pclen = met3_usize(pc); + if let Ok(pc_str) = std::str::from_utf8(&pc.as_bytes()[0..pclen]) { + let obj = object!{ + cat: "nock", + name: pc_str, + ph: "X", + pid: info.pid, + tid: 2, + ts: ts, + dur: dur, + }; + + if let Err(e) = obj.write(&mut info.file) { + eprintln!("Error writing trace to file: {:?}", e); + break; + }; + + if let Err(e) = info.file.write(",\n".as_bytes()) { + eprintln!("Error writing trace to file: {:?}", e); + break; + }; + + } + trace_stack = (*trace_stack).next; + } + }); + if let Err(e) = info.file.sync_data() { + eprintln!("Error syncing trace file: {:?}", e); + }; + } + stack.preserve(&mut context.cache); stack.preserve(&mut context.cold); stack.preserve(&mut context.warm); @@ -620,6 +688,21 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res let stack = &mut context.stack; if kale.tail { stack.pop::(); + + if let Some(_info) = &context.trace_info { + if let Some(path) = context.cold.matches(stack, &mut res) { + // Push onto the tracing stack + let trace_stack = *(stack.local_noun_pointer(1) as *const *const TraceStack); + let new_trace_entry = stack.struct_alloc(1); + *new_trace_entry = TraceStack { + path, + start: Instant::now(), + next: trace_stack, + }; + *(stack.local_noun_pointer(1) as *mut *const TraceStack) = new_trace_entry; + }; + }; + subject = res; push_formula(stack, formula, true)?; } else { @@ -635,6 +718,21 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res mean_frame_push(stack, 0); *stack.push() = NockWork::Ret; push_formula(stack, formula, true)?; + + if let Some(_info) = &context.trace_info { + if let Some(path) = context.cold.matches(stack, &mut res) { + // Push onto the tracing stack + let trace_stack = *(stack.local_noun_pointer(1) as *const *const TraceStack); + let new_trace_entry = stack.struct_alloc(1); + *new_trace_entry = TraceStack { + path, + start: Instant::now(), + next: trace_stack, + }; + *(stack.local_noun_pointer(1) as *mut *const TraceStack) = new_trace_entry; + }; + }; + } } else { // Axis into core must be atom @@ -1100,8 +1198,9 @@ pub fn exit(context: &mut Context, virtual_frame: *const u64, error: Error) -> E fn mean_frame_push(stack: &mut NockStack, slots: usize) { unsafe { let trace = *(stack.local_noun_pointer(0)); - stack.frame_push(slots + 1); + stack.frame_push(slots + 2); *(stack.local_noun_pointer(0)) = trace; + *(stack.local_noun_pointer(1) as *mut *const TraceStack) = std::ptr::null(); } } @@ -1196,6 +1295,84 @@ pub fn inc(stack: &mut NockStack, atom: Atom) -> Atom { } } +fn path_to_cord(stack: &mut NockStack, path: Noun) -> Atom { + let mut cursor = path; + let mut length = 0usize; + + // count how much size we need + loop { + if let Ok(c) = cursor.as_cell() { + unsafe { + match c.head().as_either_atom_cell() { + Left(a) => { + length += 1; + length += met3_usize(a); + }, + Right(ch) => { + if let Ok(nm) = ch.head().as_atom() { + if let Ok(kv) = ch.tail().as_atom() { + let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv).expect("scow should succeed in path_to_cord"); + let kvc = rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); + length += 1; + length += met3_usize(nm); + length += met3_usize(kvc); + } + } + } + } + } + cursor = c.tail(); + } else { + break; + } + } + + // reset cursor, then actually write the path + cursor = path; + let mut idx = 0; + let (mut deres, buffer) = unsafe { IndirectAtom::new_raw_mut_bytes(stack, length) }; + let slash = (b"/")[0]; + + loop { + if let Ok(c) = cursor.as_cell() { + unsafe { + match c.head().as_either_atom_cell() { + Left(a) => { + buffer[idx] = slash; + idx += 1; + let bytelen = met3_usize(a); + buffer[idx..idx+bytelen].copy_from_slice(&a.as_bytes()[0..bytelen]); + idx += bytelen; + }, + Right(ch) => { + if let Ok(nm) = ch.head().as_atom() { + if let Ok(kv) = ch.tail().as_atom() { + let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv).expect("scow should succeed in path_to_cord"); + let kvc = rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); + buffer[idx] = slash; + idx += 1; + let nmlen = met3_usize(nm); + buffer[idx..idx+nmlen].copy_from_slice(&nm.as_bytes()[0..nmlen]); + idx += nmlen; + let kvclen = met3_usize(kvc); + buffer[idx..idx+kvclen].copy_from_slice(&kvc.as_bytes()[0..kvclen]); + idx += kvclen; + } + } + }, + } + } + cursor = c.tail(); + } else { + break; + } + }; + + unsafe { + deres.normalize_as_atom() + } +} + mod hint { use super::*; use crate::jets; @@ -1504,3 +1681,4 @@ mod hint { newt.slog(stack, 0u64, tank); } } + diff --git a/rust/ares/src/jets.rs b/rust/ares/src/jets.rs index 9bc415c..6d97162 100644 --- a/rust/ares/src/jets.rs +++ b/rust/ares/src/jets.rs @@ -268,6 +268,7 @@ pub mod util { hot, cache, scry_stack: D(0), + trace_info: None, } } diff --git a/rust/ares/src/jets/bits.rs b/rust/ares/src/jets/bits.rs index f18caf2..bca0d5b 100644 --- a/rust/ares/src/jets/bits.rs +++ b/rust/ares/src/jets/bits.rs @@ -145,48 +145,10 @@ pub fn jet_rap(context: &mut Context, subject: Noun) -> Result { let arg = slot(subject, 6)?; let bloq = bloq(slot(arg, 2)?)?; let original_list = slot(arg, 3)?; - - let mut len = 0usize; - let mut list = original_list; - loop { - if unsafe { list.raw_equals(D(0)) } { - break; - } - - let cell = list.as_cell()?; - - len = checked_add(len, util::met(bloq, cell.head().as_atom()?))?; - list = cell.tail(); - } - - if len == 0 { - Ok(D(0)) - } else { - unsafe { - let (mut new_indirect, new_slice) = - IndirectAtom::new_raw_mut_bitslice(&mut context.stack, bite_to_word(bloq, len)?); - let mut pos = 0; - let mut list = original_list; - - loop { - if list.raw_equals(D(0)) { - break; - } - - let cell = list.as_cell()?; - let atom = cell.head().as_atom()?; - let step = util::met(bloq, atom); - chop(bloq, 0, step, pos, new_slice, atom.as_bitslice())?; - - pos += step; - list = cell.tail(); - } - - Ok(new_indirect.normalize_as_atom().as_noun()) - } - } + Ok(util::rap(&mut context.stack, bloq, original_list)?.as_noun()) } + pub fn jet_rep(context: &mut Context, subject: Noun) -> Result { let arg = slot(subject, 6)?; let (bloq, step) = bite(slot(arg, 2)?)?; @@ -348,7 +310,7 @@ pub mod util { use crate::jets::util::*; use crate::jets::JetErr; use crate::mem::NockStack; - use crate::noun::{Atom, Cell, DirectAtom, IndirectAtom, D}; + use crate::noun::{Atom, Cell, DirectAtom, IndirectAtom, D, Noun}; use std::cmp; use std::result; @@ -425,6 +387,48 @@ pub mod util { } } + pub fn rap(stack: &mut NockStack, bloq: usize, original_list: Noun) -> Result { + let mut len = 0usize; + let mut list = original_list; + loop { + if unsafe { list.raw_equals(D(0)) } { + break; + } + + let cell = list.as_cell()?; + + len = checked_add(len, met(bloq, cell.head().as_atom()?))?; + list = cell.tail(); + } + + if len == 0 { + Ok(Atom::new(stack, 0)) + } else { + unsafe { + let (mut new_indirect, new_slice) = + IndirectAtom::new_raw_mut_bitslice(stack, bite_to_word(bloq, len)?); + let mut pos = 0; + let mut list = original_list; + + loop { + if list.raw_equals(D(0)) { + break; + } + + let cell = list.as_cell()?; + let atom = cell.head().as_atom()?; + let step = met(bloq, atom); + chop(bloq, 0, step, pos, new_slice, atom.as_bitslice())?; + + pos += step; + list = cell.tail(); + } + + Ok(new_indirect.normalize_as_atom()) + } + } + } + #[cfg(test)] mod tests { use super::*; diff --git a/rust/ares/src/main.rs b/rust/ares/src/main.rs index fc6953c..c67e328 100644 --- a/rust/ares/src/main.rs +++ b/rust/ares/src/main.rs @@ -79,6 +79,7 @@ fn main() -> io::Result<()> { warm, hot, scry_stack: D(0), + trace_info: None, }; let result = interpret(&mut context, input_cell.head(), input_cell.tail()).expect("nock failed"); @@ -103,3 +104,4 @@ fn main() -> io::Result<()> { }; Ok(()) } + diff --git a/rust/ares/src/mug.rs b/rust/ares/src/mug.rs index 7e5f0af..712b1c3 100644 --- a/rust/ares/src/mug.rs +++ b/rust/ares/src/mug.rs @@ -20,7 +20,7 @@ fn muk_u32(syd: u32, len: usize, key: Atom) -> u32 { * * Assumes atom is normalized */ -fn met3_usize(atom: Atom) -> usize { +pub fn met3_usize(atom: Atom) -> usize { match atom.as_either() { Left(direct) => (64 - (direct.data().leading_zeros() as usize) + 7) >> 3, Right(indirect) => { diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index b887062..929bdf1 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -1,6 +1,6 @@ use crate::hamt::Hamt; use crate::interpreter; -use crate::interpreter::{inc, interpret, Error}; +use crate::interpreter::{inc, interpret, Error, TraceInfo}; use crate::jets::cold::Cold; use crate::jets::hot::Hot; use crate::jets::list::util::{lent, zing}; @@ -16,14 +16,20 @@ use ares_macros::tas; use signal_hook; use signal_hook::consts::SIGINT; use std::fs::create_dir_all; -use std::io; +use std::io::{self, Write}; use std::path::PathBuf; use std::result::Result; use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::Arc; +use std::time::Instant; +use std::fs::File; +use json::object; + crate::gdb!(); +const FLAG_TRACE: u32 = 1 << 8; + struct Context { epoch: u64, event_num: u64, @@ -34,7 +40,7 @@ struct Context { } impl Context { - pub fn new(snap_path: &PathBuf) -> Self { + pub fn new(snap_path: &PathBuf, trace_info: Option) -> Self { // TODO: switch to Pma when ready // let snap = &mut snapshot::pma::Pma::new(snap_path); let mut snapshot = DoubleJam::new(snap_path); @@ -57,6 +63,7 @@ impl Context { hot, cache, scry_stack: D(0), + trace_info, }; Context { @@ -179,15 +186,99 @@ pub fn serf() -> io::Result<()> { signal_hook::flag::register_conditional_shutdown(SIGINT, 1, Arc::clone(&TERMINATOR))?; signal_hook::flag::register(SIGINT, Arc::clone(&TERMINATOR))?; - let snap_path_string = std::env::args() + let pier_path_string = std::env::args() .nth(2) .ok_or(io::Error::new(io::ErrorKind::Other, "no pier path"))?; - let mut snap_path = PathBuf::from(snap_path_string); + let pier_path = PathBuf::from(pier_path_string); + let mut snap_path = pier_path.clone(); snap_path.push(".urb"); snap_path.push("chk"); create_dir_all(&snap_path)?; - let mut context = Context::new(&snap_path); + let wag: u32 = std::env::args().nth(4).ok_or(io::Error::new(io::ErrorKind::Other, "no flag bitmap"))?.parse().or(Err(io::Error::new(io::ErrorKind::Other, "flag bitmap is not integer")))?; + + let trace_info = + if wag & FLAG_TRACE != 0 { + let mut trace_dir_path = pier_path.clone(); + trace_dir_path.push(".urb"); + trace_dir_path.push("put"); + trace_dir_path.push("trace"); + create_dir_all(&trace_dir_path)?; + + let mut trace_idx = 0u32; + loop { + let mut trace_path = trace_dir_path.clone(); + trace_path.push(format!("{}.json", trace_idx)); + if trace_path.exists() { + trace_idx += 1; + } else { + let mut file = File::create(trace_path)?; + let process_start = Instant::now(); + let pid = std::process::id(); + + file.write("[ ".as_bytes())?; + + // write metadata to trace file + + (object!{ + name: "process_name", + ph: "M", + pid: pid, + args: object! { name: "urbit", }, + }).write(&mut file)?; + file.write(",\n".as_bytes())?; + + (object!{ + name: "thread_name", + ph: "M", + pid: pid, + tid: 1, + args: object!{ name: "Event Processing", }, + }).write(&mut file)?; + file.write(",\n".as_bytes())?; + + (object!{ + name: "thread_sort_index", + ph: "M", + pid: pid, + tid: 1, + args: object!{ sort_index: 1, }, + }).write(&mut file)?; + file.write(",\n".as_bytes())?; + + (object!{ + name: "thread_name", + ph: "M", + pid: pid, + tid: 2, + args: object!{ name: "Nock", }, + }).write(&mut file)?; + file.write(",\n".as_bytes())?; + + (object!{ + name: "thread_sort_index", + ph: "M", + pid: pid, + tid: 2, + args: object!{ sort_index: 2, }, + }).write(&mut file)?; + file.write(",\n".as_bytes())?; + + file.sync_data()?; + + break Some(TraceInfo { + file, + pid, + process_start, + }); + } + } + + } else { + None + }; + + let mut context = Context::new(&snap_path, trace_info); context.ripe(); // Can't use for loop because it borrows newt From 749444374da0c4c064a64d3bab225f98e5818589 Mon Sep 17 00:00:00 2001 From: Edward Amsden Date: Thu, 9 Nov 2023 19:12:49 -0600 Subject: [PATCH 03/16] interpreter: don't output traces < 33us --- rust/ares/src/interpreter.rs | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/rust/ares/src/interpreter.rs b/rust/ares/src/interpreter.rs index 04dd021..4171dde 100644 --- a/rust/ares/src/interpreter.rs +++ b/rust/ares/src/interpreter.rs @@ -387,6 +387,13 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res let ts = (*trace_stack).start.saturating_duration_since(info.process_start).as_micros() as f64; let dur = now.saturating_duration_since((*trace_stack).start).as_micros() as f64; + // Don't write out traces less than 33us + // (same threshhold used in vere) + if dur < 33.0 { + trace_stack = (*trace_stack).next; + continue; + } + let pc = path_to_cord(stack, (*trace_stack).path); let pclen = met3_usize(pc); if let Ok(pc_str) = std::str::from_utf8(&pc.as_bytes()[0..pclen]) { From 45e9ab00bdd5c2b15976e463b6504986a6728206 Mon Sep 17 00:00:00 2001 From: Edward Amsden Date: Thu, 9 Nov 2023 19:13:12 -0600 Subject: [PATCH 04/16] dependencies: add json for trace output --- rust/ares/Cargo.lock | 9 ++++++++- rust/ares/Cargo.toml | 1 + 2 files changed, 9 insertions(+), 1 deletion(-) diff --git a/rust/ares/Cargo.lock b/rust/ares/Cargo.lock index 950e6fc..cfa6b4f 100644 --- a/rust/ares/Cargo.lock +++ b/rust/ares/Cargo.lock @@ -20,6 +20,7 @@ dependencies = [ "either", "ibig", "intmap", + "json", "lazy_static", "libc", "memmap", @@ -322,6 +323,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "json" +version = "0.12.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "078e285eafdfb6c4b434e0d31e8cfcb5115b651496faca5749b88fafd4f23bfd" + [[package]] name = "lazy_static" version = "1.4.0" @@ -748,4 +755,4 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "30b31594f29d27036c383b53b59ed3476874d518f0efb151b27a4c275141390e" dependencies = [ "tap", -] \ No newline at end of file +] diff --git a/rust/ares/Cargo.toml b/rust/ares/Cargo.toml index 22c28c3..7f7866f 100644 --- a/rust/ares/Cargo.toml +++ b/rust/ares/Cargo.toml @@ -20,6 +20,7 @@ criterion = "0.4" either = "1.9.0" ibig = { path = "../ibig-rs" } intmap = "1.1.0" +json = "0.12.4" lazy_static = "1.4.0" libc = "0.2.126" memmap = "0.7.0" From 3c72f0244e3c10852db0faad5a8d3e7c3ff3362b Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Thu, 16 Nov 2023 22:18:56 +0100 Subject: [PATCH 05/16] trace: fix linter warnings --- rust/ares/src/interpreter.rs | 203 ++++++++++++++++++----------------- rust/ares/src/jets/bits.rs | 26 +++-- rust/ares/src/jets/cold.rs | 15 +-- rust/ares/src/serf.rs | 175 ++++++++++++++++-------------- 4 files changed, 221 insertions(+), 198 deletions(-) diff --git a/rust/ares/src/interpreter.rs b/rust/ares/src/interpreter.rs index 4171dde..5dd2f42 100644 --- a/rust/ares/src/interpreter.rs +++ b/rust/ares/src/interpreter.rs @@ -2,13 +2,13 @@ use crate::assert_acyclic; use crate::assert_no_forwarding_pointers; use crate::assert_no_junior_pointers; use crate::hamt::Hamt; +use crate::jets::bits::util::rap; use crate::jets::cold; use crate::jets::cold::Cold; +use crate::jets::form::util::scow; use crate::jets::hot::Hot; use crate::jets::warm::Warm; use crate::jets::JetErr; -use crate::jets::form::util::scow; -use crate::jets::bits::util::rap; use crate::mem::unifying_equality; use crate::mem::NockStack; use crate::mug::met3_usize; @@ -20,14 +20,13 @@ use ares_macros::tas; use assert_no_alloc::assert_no_alloc; use bitvec::prelude::{BitSlice, Lsb0}; use either::Either::*; +use json::object; +use std::fs::File; +use std::io::Write; use std::result; use std::sync::atomic::Ordering; use std::sync::Arc; - -use std::fs::File; use std::time::Instant; -use json::object; -use std::io::Write; crate::gdb!(); @@ -281,9 +280,9 @@ pub struct TraceInfo { } pub struct TraceStack { - pub start: Instant, - pub path: Noun, - pub next: *const TraceStack, + pub start: Instant, + pub path: Noun, + pub next: *const TraceStack, } #[derive(Clone, Copy, Debug)] @@ -325,9 +324,9 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res // Setup stack for Nock computation unsafe { context.stack.frame_push(2); + // Bottom of mean stack *(context.stack.local_noun_pointer(0)) = D(0); - // Bottom of trace stack *(context.stack.local_noun_pointer(1) as *mut *const TraceStack) = std::ptr::null(); @@ -378,14 +377,18 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res // Write fast-hinted traces to file if let Some(ref mut info) = &mut context.trace_info { - let mut trace_stack = *(stack.local_noun_pointer(1) as *const *const TraceStack); + let mut trace_stack = + *(stack.local_noun_pointer(1) as *const *const TraceStack); let now = Instant::now(); assert_no_alloc::permit_alloc(|| { - loop { - if trace_stack.is_null() { break; } - - let ts = (*trace_stack).start.saturating_duration_since(info.process_start).as_micros() as f64; - let dur = now.saturating_duration_since((*trace_stack).start).as_micros() as f64; + while !trace_stack.is_null() { + let ts = (*trace_stack) + .start + .saturating_duration_since(info.process_start) + .as_micros() as f64; + let dur = now + .saturating_duration_since((*trace_stack).start) + .as_micros() as f64; // Don't write out traces less than 33us // (same threshhold used in vere) @@ -396,33 +399,32 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res let pc = path_to_cord(stack, (*trace_stack).path); let pclen = met3_usize(pc); - if let Ok(pc_str) = std::str::from_utf8(&pc.as_bytes()[0..pclen]) { - let obj = object!{ - cat: "nock", - name: pc_str, - ph: "X", - pid: info.pid, - tid: 2, - ts: ts, - dur: dur, - }; - - if let Err(e) = obj.write(&mut info.file) { - eprintln!("Error writing trace to file: {:?}", e); - break; - }; + let pc_str = &pc.as_bytes()[0..pclen]; - if let Err(e) = info.file.write(",\n".as_bytes()) { - eprintln!("Error writing trace to file: {:?}", e); - break; - }; + let obj = object! { + cat: "nock", + name: pc_str, + ph: "X", + pid: info.pid, + tid: 2, + ts: ts, + dur: dur, + }; + if let Err(e) = obj.write(&mut info.file) { + eprintln!("\rError writing trace to file: {:?}", e); + break; + }; + // XX: success above but failure here permanently malforms the trace file + if let Err(e) = info.file.write(",\n".as_bytes()) { + eprintln!("\rError writing trace to file: {:?}", e); + break; + }; - } trace_stack = (*trace_stack).next; } }); if let Err(e) = info.file.sync_data() { - eprintln!("Error syncing trace file: {:?}", e); + eprintln!("\rError syncing trace file: {:?}", e); }; } @@ -696,17 +698,22 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res if kale.tail { stack.pop::(); - if let Some(_info) = &context.trace_info { + // We could trace on 2 as well, but 2 only comes from Hoon via + // '.*', so we can assume it's never directly used to invoke + // jetted code. + if context.trace_info.is_some() { if let Some(path) = context.cold.matches(stack, &mut res) { // Push onto the tracing stack - let trace_stack = *(stack.local_noun_pointer(1) as *const *const TraceStack); + let trace_stack = *(stack.local_noun_pointer(1) + as *const *const TraceStack); let new_trace_entry = stack.struct_alloc(1); *new_trace_entry = TraceStack { path, start: Instant::now(), next: trace_stack, }; - *(stack.local_noun_pointer(1) as *mut *const TraceStack) = new_trace_entry; + *(stack.local_noun_pointer(1) + as *mut *const TraceStack) = new_trace_entry; }; }; @@ -726,20 +733,24 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res *stack.push() = NockWork::Ret; push_formula(stack, formula, true)?; - if let Some(_info) = &context.trace_info { + // We could trace on 2 as well, but 2 only comes from Hoon via + // '.*', so we can assume it's never directly used to invoke + // jetted code. + if context.trace_info.is_some() { if let Some(path) = context.cold.matches(stack, &mut res) { // Push onto the tracing stack - let trace_stack = *(stack.local_noun_pointer(1) as *const *const TraceStack); + let trace_stack = *(stack.local_noun_pointer(1) + as *const *const TraceStack); let new_trace_entry = stack.struct_alloc(1); *new_trace_entry = TraceStack { path, start: Instant::now(), next: trace_stack, }; - *(stack.local_noun_pointer(1) as *mut *const TraceStack) = new_trace_entry; + *(stack.local_noun_pointer(1) + as *mut *const TraceStack) = new_trace_entry; }; }; - } } else { // Axis into core must be atom @@ -1302,36 +1313,35 @@ pub fn inc(stack: &mut NockStack, atom: Atom) -> Atom { } } +// XX: Need Rust string interpolation helper that doesn't allocate fn path_to_cord(stack: &mut NockStack, path: Noun) -> Atom { let mut cursor = path; let mut length = 0usize; // count how much size we need - loop { - if let Ok(c) = cursor.as_cell() { - unsafe { - match c.head().as_either_atom_cell() { - Left(a) => { - length += 1; - length += met3_usize(a); - }, - Right(ch) => { - if let Ok(nm) = ch.head().as_atom() { - if let Ok(kv) = ch.tail().as_atom() { - let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv).expect("scow should succeed in path_to_cord"); - let kvc = rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); - length += 1; - length += met3_usize(nm); - length += met3_usize(kvc); - } + while let Ok(c) = cursor.as_cell() { + unsafe { + match c.head().as_either_atom_cell() { + Left(a) => { + length += 1; + length += met3_usize(a); + } + Right(ch) => { + if let Ok(nm) = ch.head().as_atom() { + if let Ok(kv) = ch.tail().as_atom() { + let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv) + .expect("scow should succeed in path_to_cord"); + let kvc = + rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); + length += 1; + length += met3_usize(nm); + length += met3_usize(kvc); } } } } - cursor = c.tail(); - } else { - break; } + cursor = c.tail(); } // reset cursor, then actually write the path @@ -1339,45 +1349,41 @@ fn path_to_cord(stack: &mut NockStack, path: Noun) -> Atom { let mut idx = 0; let (mut deres, buffer) = unsafe { IndirectAtom::new_raw_mut_bytes(stack, length) }; let slash = (b"/")[0]; - - loop { - if let Ok(c) = cursor.as_cell() { - unsafe { - match c.head().as_either_atom_cell() { - Left(a) => { - buffer[idx] = slash; - idx += 1; - let bytelen = met3_usize(a); - buffer[idx..idx+bytelen].copy_from_slice(&a.as_bytes()[0..bytelen]); - idx += bytelen; - }, - Right(ch) => { - if let Ok(nm) = ch.head().as_atom() { - if let Ok(kv) = ch.tail().as_atom() { - let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv).expect("scow should succeed in path_to_cord"); - let kvc = rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); - buffer[idx] = slash; - idx += 1; - let nmlen = met3_usize(nm); - buffer[idx..idx+nmlen].copy_from_slice(&nm.as_bytes()[0..nmlen]); - idx += nmlen; - let kvclen = met3_usize(kvc); - buffer[idx..idx+kvclen].copy_from_slice(&kvc.as_bytes()[0..kvclen]); - idx += kvclen; - } + + while let Ok(c) = cursor.as_cell() { + unsafe { + match c.head().as_either_atom_cell() { + Left(a) => { + buffer[idx] = slash; + idx += 1; + let bytelen = met3_usize(a); + buffer[idx..idx + bytelen].copy_from_slice(&a.as_bytes()[0..bytelen]); + idx += bytelen; + } + Right(ch) => { + if let Ok(nm) = ch.head().as_atom() { + if let Ok(kv) = ch.tail().as_atom() { + let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv) + .expect("scow should succeed in path_to_cord"); + let kvc = + rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); + buffer[idx] = slash; + idx += 1; + let nmlen = met3_usize(nm); + buffer[idx..idx + nmlen].copy_from_slice(&nm.as_bytes()[0..nmlen]); + idx += nmlen; + let kvclen = met3_usize(kvc); + buffer[idx..idx + kvclen].copy_from_slice(&kvc.as_bytes()[0..kvclen]); + idx += kvclen; } - }, + } } } - cursor = c.tail(); - } else { - break; } - }; - - unsafe { - deres.normalize_as_atom() + cursor = c.tail(); } + + unsafe { deres.normalize_as_atom() } } mod hint { @@ -1688,4 +1694,3 @@ mod hint { newt.slog(stack, 0u64, tank); } } - diff --git a/rust/ares/src/jets/bits.rs b/rust/ares/src/jets/bits.rs index cc35a16..9b6b700 100644 --- a/rust/ares/src/jets/bits.rs +++ b/rust/ares/src/jets/bits.rs @@ -148,7 +148,6 @@ pub fn jet_rap(context: &mut Context, subject: Noun) -> Result { Ok(util::rap(&mut context.stack, bloq, original_list)?.as_noun()) } - pub fn jet_rep(context: &mut Context, subject: Noun) -> Result { let arg = slot(subject, 6)?; let (bloq, step) = bite(slot(arg, 2)?)?; @@ -307,10 +306,11 @@ pub fn jet_mix(context: &mut Context, subject: Noun) -> Result { pub mod util { use crate::jets::util::*; - use crate::jets::Result; + use crate::jets::{JetErr, Result}; use crate::mem::NockStack; - use crate::noun::{Atom, Cell, DirectAtom, IndirectAtom, D, Noun}; + use crate::noun::{Atom, Cell, DirectAtom, IndirectAtom, Noun, D}; use std::cmp; + use std::result; /// Binary exponent pub fn bex(stack: &mut NockStack, arg: usize) -> Atom { @@ -380,20 +380,24 @@ pub mod util { } } - pub fn rap(stack: &mut NockStack, bloq: usize, original_list: Noun) -> Result { + pub fn rap( + stack: &mut NockStack, + bloq: usize, + original_list: Noun, + ) -> result::Result { let mut len = 0usize; let mut list = original_list; loop { if unsafe { list.raw_equals(D(0)) } { break; } - + let cell = list.as_cell()?; - + len = checked_add(len, met(bloq, cell.head().as_atom()?))?; list = cell.tail(); } - + if len == 0 { Ok(Atom::new(stack, 0)) } else { @@ -402,21 +406,21 @@ pub mod util { IndirectAtom::new_raw_mut_bitslice(stack, bite_to_word(bloq, len)?); let mut pos = 0; let mut list = original_list; - + loop { if list.raw_equals(D(0)) { break; } - + let cell = list.as_cell()?; let atom = cell.head().as_atom()?; let step = met(bloq, atom); chop(bloq, 0, step, pos, new_slice, atom.as_bitslice())?; - + pos += step; list = cell.tail(); } - + Ok(new_indirect.normalize_as_atom()) } } diff --git a/rust/ares/src/jets/cold.rs b/rust/ares/src/jets/cold.rs index b5a7b62..29a8564 100644 --- a/rust/ares/src/jets/cold.rs +++ b/rust/ares/src/jets/cold.rs @@ -274,8 +274,8 @@ struct ColdMem { /// value: possible registered paths for core /// /// Identical nock can exist in multiple places, so the outermost battery - /// yield multiple paths. Instead of matching on the entire core in the Hamt - /// (which would require iterating through every possible pait), we match + /// yields multiple paths. Instead of matching on the entire core in the Hamt + /// (which would require iterating through every possible pair), we match /// the outermost battery to a path, then compare the core to the registered /// cores for that path. battery_to_paths: Hamt, @@ -348,15 +348,16 @@ impl Cold { unsafe { let paths = (*(self.0)).battery_to_paths.lookup(stack, &mut battery)?; for path in paths { - if let Some(batteries_list) = (*(self.0)).path_to_batteries.lookup(stack, &mut (*path)) { - + if let Some(batteries_list) = + (*(self.0)).path_to_batteries.lookup(stack, &mut (*path)) + { if let Some(_batt) = batteries_list.matches(stack, *core) { return Some(*path); } } - }; - return None; - } + } + }; + None } /// register a core, return a boolean of whether we actually needed to register (false -> diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index 929bdf1..5499e47 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -13,18 +13,16 @@ use crate::noun::{Cell, Noun, Slots, D, T}; use crate::snapshot::double_jam::DoubleJam; use crate::snapshot::Snapshot; use ares_macros::tas; +use json::object; use signal_hook; use signal_hook::consts::SIGINT; -use std::fs::create_dir_all; +use std::fs::{create_dir_all, File}; use std::io::{self, Write}; use std::path::PathBuf; use std::result::Result; use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::Arc; - use std::time::Instant; -use std::fs::File; -use json::object; crate::gdb!(); @@ -195,88 +193,103 @@ pub fn serf() -> io::Result<()> { snap_path.push("chk"); create_dir_all(&snap_path)?; - let wag: u32 = std::env::args().nth(4).ok_or(io::Error::new(io::ErrorKind::Other, "no flag bitmap"))?.parse().or(Err(io::Error::new(io::ErrorKind::Other, "flag bitmap is not integer")))?; + let wag: u32 = std::env::args() + .nth(4) + .ok_or(io::Error::new(io::ErrorKind::Other, "no flag bitmap"))? + .parse() + .or(Err(io::Error::new( + io::ErrorKind::Other, + "flag bitmap is not integer", + )))?; - let trace_info = - if wag & FLAG_TRACE != 0 { - let mut trace_dir_path = pier_path.clone(); - trace_dir_path.push(".urb"); - trace_dir_path.push("put"); - trace_dir_path.push("trace"); - create_dir_all(&trace_dir_path)?; + let trace_info = if wag & FLAG_TRACE != 0 { + let mut trace_dir_path = pier_path.clone(); + trace_dir_path.push(".urb"); + trace_dir_path.push("put"); + trace_dir_path.push("trace"); + create_dir_all(&trace_dir_path)?; - let mut trace_idx = 0u32; - loop { - let mut trace_path = trace_dir_path.clone(); - trace_path.push(format!("{}.json", trace_idx)); - if trace_path.exists() { - trace_idx += 1; - } else { - let mut file = File::create(trace_path)?; - let process_start = Instant::now(); - let pid = std::process::id(); + let trace_path: PathBuf; + let mut trace_idx = 0u32; + loop { + let mut prospective_path = trace_dir_path.clone(); + prospective_path.push(format!("{}.json", trace_idx)); - file.write("[ ".as_bytes())?; - - // write metadata to trace file - - (object!{ - name: "process_name", - ph: "M", - pid: pid, - args: object! { name: "urbit", }, - }).write(&mut file)?; - file.write(",\n".as_bytes())?; - - (object!{ - name: "thread_name", - ph: "M", - pid: pid, - tid: 1, - args: object!{ name: "Event Processing", }, - }).write(&mut file)?; - file.write(",\n".as_bytes())?; - - (object!{ - name: "thread_sort_index", - ph: "M", - pid: pid, - tid: 1, - args: object!{ sort_index: 1, }, - }).write(&mut file)?; - file.write(",\n".as_bytes())?; - - (object!{ - name: "thread_name", - ph: "M", - pid: pid, - tid: 2, - args: object!{ name: "Nock", }, - }).write(&mut file)?; - file.write(",\n".as_bytes())?; - - (object!{ - name: "thread_sort_index", - ph: "M", - pid: pid, - tid: 2, - args: object!{ sort_index: 2, }, - }).write(&mut file)?; - file.write(",\n".as_bytes())?; - - file.sync_data()?; - - break Some(TraceInfo { - file, - pid, - process_start, - }); - } + if prospective_path.exists() { + trace_idx += 1; + } else { + trace_path = prospective_path.clone(); + break; } + } - } else { - None - }; + let mut file = File::create(trace_path)?; + let process_start = Instant::now(); + let pid = std::process::id(); + + // write metadata to trace file + + file.write_all("[ ".as_bytes())?; + + (object! { + name: "process_name", + ph: "M", + pid: pid, + args: object! { name: "urbit", }, + }) + .write(&mut file)?; + file.write_all(",\n".as_bytes())?; + + (object! { + name: "thread_name", + ph: "M", + pid: pid, + tid: 1, + args: object!{ name: "Event Processing", }, + }) + .write(&mut file)?; + file.write_all(",\n".as_bytes())?; + + (object! { + name: "thread_sort_index", + ph: "M", + pid: pid, + tid: 1, + args: object!{ sort_index: 1, }, + }) + .write(&mut file)?; + file.write_all(",\n".as_bytes())?; + + (object! { + name: "thread_name", + ph: "M", + pid: pid, + tid: 2, + args: object!{ name: "Nock", }, + }) + .write(&mut file)?; + file.write_all(",\n".as_bytes())?; + + (object! { + name: "thread_sort_index", + ph: "M", + pid: pid, + tid: 2, + args: object!{ sort_index: 2, }, + }) + .write(&mut file)?; + file.write_all(",\n".as_bytes())?; + + file.sync_data()?; + + Some(TraceInfo { + file, + pid, + process_start, + }) + } else { + None + }; let mut context = Context::new(&snap_path, trace_info); context.ripe(); From e1c5d158e65a711734e5a03d698054028b1204f4 Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Fri, 17 Nov 2023 00:03:35 +0100 Subject: [PATCH 06/16] trace: move trace code to its own file --- rust/ares/src/interpreter.rs | 181 +++----------------------- rust/ares/src/lib.rs | 3 +- rust/ares/src/main.rs | 1 - rust/ares/src/serf.rs | 100 ++------------ rust/ares/src/trace.rs | 244 +++++++++++++++++++++++++++++++++++ 5 files changed, 275 insertions(+), 254 deletions(-) create mode 100644 rust/ares/src/trace.rs diff --git a/rust/ares/src/interpreter.rs b/rust/ares/src/interpreter.rs index 5dd2f42..1bd8a64 100644 --- a/rust/ares/src/interpreter.rs +++ b/rust/ares/src/interpreter.rs @@ -2,27 +2,22 @@ use crate::assert_acyclic; use crate::assert_no_forwarding_pointers; use crate::assert_no_junior_pointers; use crate::hamt::Hamt; -use crate::jets::bits::util::rap; use crate::jets::cold; use crate::jets::cold::Cold; -use crate::jets::form::util::scow; use crate::jets::hot::Hot; use crate::jets::warm::Warm; use crate::jets::JetErr; use crate::mem::unifying_equality; use crate::mem::NockStack; -use crate::mug::met3_usize; use crate::newt::Newt; use crate::noun; -use crate::noun::{Atom, Cell, DirectAtom, IndirectAtom, Noun, Slots, D, T}; +use crate::noun::{Atom, Cell, IndirectAtom, Noun, Slots, D, T}; use crate::serf::TERMINATOR; +use crate::trace::{write_nock_trace, TraceInfo, TraceStack}; use ares_macros::tas; use assert_no_alloc::assert_no_alloc; use bitvec::prelude::{BitSlice, Lsb0}; use either::Either::*; -use json::object; -use std::fs::File; -use std::io::Write; use std::result; use std::sync::atomic::Ordering; use std::sync::Arc; @@ -273,18 +268,6 @@ pub struct Context { pub trace_info: Option, } -pub struct TraceInfo { - pub file: File, - pub pid: u32, - pub process_start: Instant, -} - -pub struct TraceStack { - pub start: Instant, - pub path: Noun, - pub next: *const TraceStack, -} - #[derive(Clone, Copy, Debug)] pub enum Error { ScryBlocked(Noun), // path @@ -375,57 +358,10 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res debug_assertions(stack, subject); debug_assertions(stack, res); - // Write fast-hinted traces to file + // Write fast-hinted traces to trace file if let Some(ref mut info) = &mut context.trace_info { - let mut trace_stack = - *(stack.local_noun_pointer(1) as *const *const TraceStack); - let now = Instant::now(); - assert_no_alloc::permit_alloc(|| { - while !trace_stack.is_null() { - let ts = (*trace_stack) - .start - .saturating_duration_since(info.process_start) - .as_micros() as f64; - let dur = now - .saturating_duration_since((*trace_stack).start) - .as_micros() as f64; - - // Don't write out traces less than 33us - // (same threshhold used in vere) - if dur < 33.0 { - trace_stack = (*trace_stack).next; - continue; - } - - let pc = path_to_cord(stack, (*trace_stack).path); - let pclen = met3_usize(pc); - let pc_str = &pc.as_bytes()[0..pclen]; - - let obj = object! { - cat: "nock", - name: pc_str, - ph: "X", - pid: info.pid, - tid: 2, - ts: ts, - dur: dur, - }; - if let Err(e) = obj.write(&mut info.file) { - eprintln!("\rError writing trace to file: {:?}", e); - break; - }; - // XX: success above but failure here permanently malforms the trace file - if let Err(e) = info.file.write(",\n".as_bytes()) { - eprintln!("\rError writing trace to file: {:?}", e); - break; - }; - - trace_stack = (*trace_stack).next; - } - }); - if let Err(e) = info.file.sync_data() { - eprintln!("\rError syncing trace file: {:?}", e); - }; + let trace_stack = *(stack.local_noun_pointer(1) as *mut *const TraceStack); + write_nock_trace(stack, info, trace_stack); } stack.preserve(&mut context.cache); @@ -703,17 +639,7 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res // jetted code. if context.trace_info.is_some() { if let Some(path) = context.cold.matches(stack, &mut res) { - // Push onto the tracing stack - let trace_stack = *(stack.local_noun_pointer(1) - as *const *const TraceStack); - let new_trace_entry = stack.struct_alloc(1); - *new_trace_entry = TraceStack { - path, - start: Instant::now(), - next: trace_stack, - }; - *(stack.local_noun_pointer(1) - as *mut *const TraceStack) = new_trace_entry; + append_trace(stack, path); }; }; @@ -738,17 +664,7 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res // jetted code. if context.trace_info.is_some() { if let Some(path) = context.cold.matches(stack, &mut res) { - // Push onto the tracing stack - let trace_stack = *(stack.local_noun_pointer(1) - as *const *const TraceStack); - let new_trace_entry = stack.struct_alloc(1); - *new_trace_entry = TraceStack { - path, - start: Instant::now(), - next: trace_stack, - }; - *(stack.local_noun_pointer(1) - as *mut *const TraceStack) = new_trace_entry; + append_trace(stack, path); }; }; } @@ -1183,7 +1099,7 @@ fn push_formula(stack: &mut NockStack, formula: Noun, tail: bool) -> result::Res Ok(()) } -pub fn exit(context: &mut Context, virtual_frame: *const u64, error: Error) -> Error { +fn exit(context: &mut Context, virtual_frame: *const u64, error: Error) -> Error { unsafe { let stack = &mut context.stack; @@ -1313,77 +1229,18 @@ pub fn inc(stack: &mut NockStack, atom: Atom) -> Atom { } } -// XX: Need Rust string interpolation helper that doesn't allocate -fn path_to_cord(stack: &mut NockStack, path: Noun) -> Atom { - let mut cursor = path; - let mut length = 0usize; - - // count how much size we need - while let Ok(c) = cursor.as_cell() { - unsafe { - match c.head().as_either_atom_cell() { - Left(a) => { - length += 1; - length += met3_usize(a); - } - Right(ch) => { - if let Ok(nm) = ch.head().as_atom() { - if let Ok(kv) = ch.tail().as_atom() { - let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv) - .expect("scow should succeed in path_to_cord"); - let kvc = - rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); - length += 1; - length += met3_usize(nm); - length += met3_usize(kvc); - } - } - } - } - } - cursor = c.tail(); +/// Push onto the tracing stack +fn append_trace(stack: &mut NockStack, path: Noun) { + unsafe { + let trace_stack = *(stack.local_noun_pointer(1) as *const *const TraceStack); + let new_trace_entry = stack.struct_alloc(1); + *new_trace_entry = TraceStack { + path, + start: Instant::now(), + next: trace_stack, + }; + *(stack.local_noun_pointer(1) as *mut *const TraceStack) = new_trace_entry; } - - // reset cursor, then actually write the path - cursor = path; - let mut idx = 0; - let (mut deres, buffer) = unsafe { IndirectAtom::new_raw_mut_bytes(stack, length) }; - let slash = (b"/")[0]; - - while let Ok(c) = cursor.as_cell() { - unsafe { - match c.head().as_either_atom_cell() { - Left(a) => { - buffer[idx] = slash; - idx += 1; - let bytelen = met3_usize(a); - buffer[idx..idx + bytelen].copy_from_slice(&a.as_bytes()[0..bytelen]); - idx += bytelen; - } - Right(ch) => { - if let Ok(nm) = ch.head().as_atom() { - if let Ok(kv) = ch.tail().as_atom() { - let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv) - .expect("scow should succeed in path_to_cord"); - let kvc = - rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); - buffer[idx] = slash; - idx += 1; - let nmlen = met3_usize(nm); - buffer[idx..idx + nmlen].copy_from_slice(&nm.as_bytes()[0..nmlen]); - idx += nmlen; - let kvclen = met3_usize(kvc); - buffer[idx..idx + kvclen].copy_from_slice(&kvc.as_bytes()[0..kvclen]); - idx += kvclen; - } - } - } - } - } - cursor = c.tail(); - } - - unsafe { deres.normalize_as_atom() } } mod hint { diff --git a/rust/ares/src/lib.rs b/rust/ares/src/lib.rs index 23e67e1..558006e 100644 --- a/rust/ares/src/lib.rs +++ b/rust/ares/src/lib.rs @@ -3,6 +3,7 @@ extern crate num_derive; extern crate lazy_static; #[macro_use] extern crate static_assertions; +pub mod hamt; pub mod interpreter; pub mod jets; pub mod mem; @@ -11,9 +12,9 @@ pub mod newt; pub mod noun; pub mod serf; //pub mod bytecode; -pub mod hamt; pub mod serialization; pub mod snapshot; +pub mod trace; /** Introduce useful functions for debugging * diff --git a/rust/ares/src/main.rs b/rust/ares/src/main.rs index c67e328..874b55e 100644 --- a/rust/ares/src/main.rs +++ b/rust/ares/src/main.rs @@ -104,4 +104,3 @@ fn main() -> io::Result<()> { }; Ok(()) } - diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index 5499e47..e9937c3 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -1,6 +1,6 @@ use crate::hamt::Hamt; use crate::interpreter; -use crate::interpreter::{inc, interpret, Error, TraceInfo}; +use crate::interpreter::{inc, interpret, Error}; use crate::jets::cold::Cold; use crate::jets::hot::Hot; use crate::jets::list::util::{lent, zing}; @@ -12,17 +12,16 @@ use crate::newt::Newt; use crate::noun::{Cell, Noun, Slots, D, T}; use crate::snapshot::double_jam::DoubleJam; use crate::snapshot::Snapshot; +use crate::trace::{create_trace_file, write_metadata, TraceInfo}; use ares_macros::tas; -use json::object; use signal_hook; use signal_hook::consts::SIGINT; -use std::fs::{create_dir_all, File}; -use std::io::{self, Write}; +use std::fs::create_dir_all; +use std::io; use std::path::PathBuf; use std::result::Result; use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::Arc; -use std::time::Instant; crate::gdb!(); @@ -202,95 +201,16 @@ pub fn serf() -> io::Result<()> { "flag bitmap is not integer", )))?; - let trace_info = if wag & FLAG_TRACE != 0 { - let mut trace_dir_path = pier_path.clone(); - trace_dir_path.push(".urb"); - trace_dir_path.push("put"); - trace_dir_path.push("trace"); - create_dir_all(&trace_dir_path)?; - - let trace_path: PathBuf; - let mut trace_idx = 0u32; - loop { - let mut prospective_path = trace_dir_path.clone(); - prospective_path.push(format!("{}.json", trace_idx)); - - if prospective_path.exists() { - trace_idx += 1; - } else { - trace_path = prospective_path.clone(); - break; - } - } - - let mut file = File::create(trace_path)?; - let process_start = Instant::now(); - let pid = std::process::id(); - - // write metadata to trace file - - file.write_all("[ ".as_bytes())?; - - (object! { - name: "process_name", - ph: "M", - pid: pid, - args: object! { name: "urbit", }, - }) - .write(&mut file)?; - file.write_all(",\n".as_bytes())?; - - (object! { - name: "thread_name", - ph: "M", - pid: pid, - tid: 1, - args: object!{ name: "Event Processing", }, - }) - .write(&mut file)?; - file.write_all(",\n".as_bytes())?; - - (object! { - name: "thread_sort_index", - ph: "M", - pid: pid, - tid: 1, - args: object!{ sort_index: 1, }, - }) - .write(&mut file)?; - file.write_all(",\n".as_bytes())?; - - (object! { - name: "thread_name", - ph: "M", - pid: pid, - tid: 2, - args: object!{ name: "Nock", }, - }) - .write(&mut file)?; - file.write_all(",\n".as_bytes())?; - - (object! { - name: "thread_sort_index", - ph: "M", - pid: pid, - tid: 2, - args: object!{ sort_index: 2, }, - }) - .write(&mut file)?; - file.write_all(",\n".as_bytes())?; - - file.sync_data()?; - - Some(TraceInfo { - file, - pid, - process_start, - }) + let mut trace_info = if wag & FLAG_TRACE != 0 { + create_trace_file(pier_path).ok() } else { None }; + if let Some(ref mut info) = trace_info.as_mut() { + write_metadata(info); + } + let mut context = Context::new(&snap_path, trace_info); context.ripe(); diff --git a/rust/ares/src/trace.rs b/rust/ares/src/trace.rs new file mode 100644 index 0000000..1d14889 --- /dev/null +++ b/rust/ares/src/trace.rs @@ -0,0 +1,244 @@ +use crate::jets::bits::util::rap; +use crate::jets::form::util::scow; +use crate::mem::NockStack; +use crate::mug::met3_usize; +use crate::noun::{Atom, DirectAtom, IndirectAtom, Noun}; +use ares_macros::tas; +use either::Either::*; +use json::object; +use std::fs::{create_dir_all, File}; +use std::io::{Error, Write}; +use std::path::PathBuf; +use std::result::Result; +use std::time::Instant; + +crate::gdb!(); + +pub struct TraceInfo { + pub file: File, + pub pid: u32, + pub process_start: Instant, +} + +pub struct TraceStack { + pub start: Instant, + pub path: Noun, + pub next: *const TraceStack, +} + +pub fn create_trace_file(pier_path: PathBuf) -> Result { + let mut trace_dir_path = pier_path.clone(); + trace_dir_path.push(".urb"); + trace_dir_path.push("put"); + trace_dir_path.push("trace"); + create_dir_all(&trace_dir_path)?; + + let trace_path: PathBuf; + let mut trace_idx = 0u32; + loop { + let mut prospective_path = trace_dir_path.clone(); + prospective_path.push(format!("{}.json", trace_idx)); + + if prospective_path.exists() { + trace_idx += 1; + } else { + trace_path = prospective_path.clone(); + break; + } + } + + let file = File::create(trace_path)?; + let process_start = Instant::now(); + let pid = std::process::id(); + + Ok(TraceInfo { + file, + pid, + process_start, + }) +} + +/// Write metadata to trace file +pub fn write_metadata(info: &mut TraceInfo) { + info.file.write_all("[ ".as_bytes()); + + (object! { + name: "process_name", + ph: "M", + pid: info.pid, + args: object! { name: "urbit", }, + }) + .write(&mut info.file); + info.file.write_all(",\n".as_bytes()); + + (object! { + name: "thread_name", + ph: "M", + pid: info.pid, + tid: 1, + args: object!{ name: "Event Processing", }, + }) + .write(&mut info.file); + info.file.write_all(",\n".as_bytes()); + + (object! { + name: "thread_sort_index", + ph: "M", + pid: info.pid, + tid: 1, + args: object!{ sort_index: 1, }, + }) + .write(&mut info.file); + info.file.write_all(",\n".as_bytes()); + + (object! { + name: "thread_name", + ph: "M", + pid: info.pid, + tid: 2, + args: object!{ name: "Nock", }, + }) + .write(&mut info.file); + info.file.write_all(",\n".as_bytes()); + + (object! { + name: "thread_sort_index", + ph: "M", + pid: info.pid, + tid: 2, + args: object!{ sort_index: 2, }, + }) + .write(&mut info.file); + info.file.write_all(",\n".as_bytes()); + + info.file.sync_data(); +} + +pub fn write_nock_trace( + stack: &mut NockStack, + info: &mut TraceInfo, + mut trace_stack: *const TraceStack, +) { + let now = Instant::now(); + unsafe { + assert_no_alloc::permit_alloc(|| { + while !trace_stack.is_null() { + let ts = (*trace_stack) + .start + .saturating_duration_since(info.process_start) + .as_micros() as f64; + let dur = now + .saturating_duration_since((*trace_stack).start) + .as_micros() as f64; + + // Don't write out traces less than 33us + // (same threshhold used in vere) + if dur < 33.0 { + trace_stack = (*trace_stack).next; + continue; + } + + let pc = path_to_cord(stack, (*trace_stack).path); + let pclen = met3_usize(pc); + let pc_str = &pc.as_bytes()[0..pclen]; + + let obj = object! { + cat: "nock", + name: pc_str, + ph: "X", + pid: info.pid, + tid: 2, + ts: ts, + dur: dur, + }; + if let Err(e) = obj.write(&mut info.file) { + eprintln!("\rError writing trace to file: {:?}", e); + break; + }; + // XX: success above but failure here permanently malforms the trace file + if let Err(e) = info.file.write(",\n".as_bytes()) { + eprintln!("\rError writing trace to file: {:?}", e); + break; + }; + + trace_stack = (*trace_stack).next; + } + }); + } + if let Err(e) = info.file.sync_data() { + eprintln!("\rError syncing trace file: {:?}", e); + }; +} + +// XX: Need Rust string interpolation helper that doesn't allocate +fn path_to_cord(stack: &mut NockStack, path: Noun) -> Atom { + let mut cursor = path; + let mut length = 0usize; + + // count how much size we need + while let Ok(c) = cursor.as_cell() { + unsafe { + match c.head().as_either_atom_cell() { + Left(a) => { + length += 1; + length += met3_usize(a); + } + Right(ch) => { + if let Ok(nm) = ch.head().as_atom() { + if let Ok(kv) = ch.tail().as_atom() { + let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv) + .expect("scow should succeed in path_to_cord"); + let kvc = + rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); + length += 1; + length += met3_usize(nm); + length += met3_usize(kvc); + } + } + } + } + } + cursor = c.tail(); + } + + // reset cursor, then actually write the path + cursor = path; + let mut idx = 0; + let (mut deres, buffer) = unsafe { IndirectAtom::new_raw_mut_bytes(stack, length) }; + let slash = (b"/")[0]; + + while let Ok(c) = cursor.as_cell() { + unsafe { + match c.head().as_either_atom_cell() { + Left(a) => { + buffer[idx] = slash; + idx += 1; + let bytelen = met3_usize(a); + buffer[idx..idx + bytelen].copy_from_slice(&a.as_bytes()[0..bytelen]); + idx += bytelen; + } + Right(ch) => { + if let Ok(nm) = ch.head().as_atom() { + if let Ok(kv) = ch.tail().as_atom() { + let kvt = scow(stack, DirectAtom::new_unchecked(tas!(b"ud")), kv) + .expect("scow should succeed in path_to_cord"); + let kvc = + rap(stack, 3, kvt).expect("rap should succeed in path_to_cord"); + buffer[idx] = slash; + idx += 1; + let nmlen = met3_usize(nm); + buffer[idx..idx + nmlen].copy_from_slice(&nm.as_bytes()[0..nmlen]); + idx += nmlen; + let kvclen = met3_usize(kvc); + buffer[idx..idx + kvclen].copy_from_slice(&kvc.as_bytes()[0..kvclen]); + idx += kvclen; + } + } + } + } + } + cursor = c.tail(); + } + + unsafe { deres.normalize_as_atom() } +} From 9573584979ea66c02be965ebc025a22de6a98395 Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Fri, 17 Nov 2023 11:20:44 +0100 Subject: [PATCH 07/16] trace: disable tracing on failed write to file --- rust/ares/src/interpreter.rs | 7 ++- rust/ares/src/serf.rs | 5 +- rust/ares/src/trace.rs | 113 ++++++++++++++++------------------- 3 files changed, 63 insertions(+), 62 deletions(-) diff --git a/rust/ares/src/interpreter.rs b/rust/ares/src/interpreter.rs index 1bd8a64..7e5ebb5 100644 --- a/rust/ares/src/interpreter.rs +++ b/rust/ares/src/interpreter.rs @@ -361,7 +361,12 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res // Write fast-hinted traces to trace file if let Some(ref mut info) = &mut context.trace_info { let trace_stack = *(stack.local_noun_pointer(1) as *mut *const TraceStack); - write_nock_trace(stack, info, trace_stack); + // Abort writing to trace file if we encountered an error. This should + // result in a well-formed partial trace file. + if let Err(e) = write_nock_trace(stack, info, trace_stack) { + eprintln!("\rError writing trace to file: {:?}", e); + context.trace_info = None; + } } stack.preserve(&mut context.cache); diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index e9937c3..6db2203 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -208,7 +208,10 @@ pub fn serf() -> io::Result<()> { }; if let Some(ref mut info) = trace_info.as_mut() { - write_metadata(info); + if let Err(e) = write_metadata(info) { + eprintln!("\rError initializing trace file: {:?}", e); + trace_info = None; + } } let mut context = Context::new(&snap_path, trace_info); diff --git a/rust/ares/src/trace.rs b/rust/ares/src/trace.rs index 1d14889..fb4a16f 100644 --- a/rust/ares/src/trace.rs +++ b/rust/ares/src/trace.rs @@ -59,8 +59,8 @@ pub fn create_trace_file(pier_path: PathBuf) -> Result { } /// Write metadata to trace file -pub fn write_metadata(info: &mut TraceInfo) { - info.file.write_all("[ ".as_bytes()); +pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { + info.file.write_all("[ ".as_bytes())?; (object! { name: "process_name", @@ -68,8 +68,8 @@ pub fn write_metadata(info: &mut TraceInfo) { pid: info.pid, args: object! { name: "urbit", }, }) - .write(&mut info.file); - info.file.write_all(",\n".as_bytes()); + .write(&mut info.file)?; + info.file.write_all(",\n".as_bytes())?; (object! { name: "thread_name", @@ -78,8 +78,8 @@ pub fn write_metadata(info: &mut TraceInfo) { tid: 1, args: object!{ name: "Event Processing", }, }) - .write(&mut info.file); - info.file.write_all(",\n".as_bytes()); + .write(&mut info.file)?; + info.file.write_all(",\n".as_bytes())?; (object! { name: "thread_sort_index", @@ -88,8 +88,8 @@ pub fn write_metadata(info: &mut TraceInfo) { tid: 1, args: object!{ sort_index: 1, }, }) - .write(&mut info.file); - info.file.write_all(",\n".as_bytes()); + .write(&mut info.file)?; + info.file.write_all(",\n".as_bytes())?; (object! { name: "thread_name", @@ -98,8 +98,8 @@ pub fn write_metadata(info: &mut TraceInfo) { tid: 2, args: object!{ name: "Nock", }, }) - .write(&mut info.file); - info.file.write_all(",\n".as_bytes()); + .write(&mut info.file)?; + info.file.write_all(",\n".as_bytes())?; (object! { name: "thread_sort_index", @@ -108,66 +108,59 @@ pub fn write_metadata(info: &mut TraceInfo) { tid: 2, args: object!{ sort_index: 2, }, }) - .write(&mut info.file); - info.file.write_all(",\n".as_bytes()); + .write(&mut info.file)?; + info.file.write_all(",\n".as_bytes())?; - info.file.sync_data(); + info.file.sync_data()?; + Ok(()) } -pub fn write_nock_trace( +pub unsafe fn write_nock_trace( stack: &mut NockStack, info: &mut TraceInfo, mut trace_stack: *const TraceStack, -) { +) -> Result<(), Error> { let now = Instant::now(); - unsafe { + + while !trace_stack.is_null() { + let ts = (*trace_stack) + .start + .saturating_duration_since(info.process_start) + .as_micros() as f64; + let dur = now + .saturating_duration_since((*trace_stack).start) + .as_micros() as f64; + + // Don't write out traces less than 33us + // (same threshhold used in vere) + if dur < 33.0 { + trace_stack = (*trace_stack).next; + continue; + } + + let pc = path_to_cord(stack, (*trace_stack).path); + let pclen = met3_usize(pc); + let pc_str = &pc.as_bytes()[0..pclen]; + assert_no_alloc::permit_alloc(|| { - while !trace_stack.is_null() { - let ts = (*trace_stack) - .start - .saturating_duration_since(info.process_start) - .as_micros() as f64; - let dur = now - .saturating_duration_since((*trace_stack).start) - .as_micros() as f64; + let obj = object! { + cat: "nock", + name: pc_str, + ph: "X", + pid: info.pid, + tid: 2, + ts: ts, + dur: dur, + }; + obj.write(&mut info.file) + })?; + info.file.write_all(",\n".as_bytes())?; - // Don't write out traces less than 33us - // (same threshhold used in vere) - if dur < 33.0 { - trace_stack = (*trace_stack).next; - continue; - } - - let pc = path_to_cord(stack, (*trace_stack).path); - let pclen = met3_usize(pc); - let pc_str = &pc.as_bytes()[0..pclen]; - - let obj = object! { - cat: "nock", - name: pc_str, - ph: "X", - pid: info.pid, - tid: 2, - ts: ts, - dur: dur, - }; - if let Err(e) = obj.write(&mut info.file) { - eprintln!("\rError writing trace to file: {:?}", e); - break; - }; - // XX: success above but failure here permanently malforms the trace file - if let Err(e) = info.file.write(",\n".as_bytes()) { - eprintln!("\rError writing trace to file: {:?}", e); - break; - }; - - trace_stack = (*trace_stack).next; - } - }); + trace_stack = (*trace_stack).next; } - if let Err(e) = info.file.sync_data() { - eprintln!("\rError syncing trace file: {:?}", e); - }; + + info.file.sync_data()?; + Ok(()) } // XX: Need Rust string interpolation helper that doesn't allocate From f5889bba171cd4a0b0273b33835ed93f69e34e7d Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Fri, 17 Nov 2023 12:41:34 +0100 Subject: [PATCH 08/16] trace: add profile trace to DONE block It's possible for a tail-recursive 9 to never hit the RET block. --- rust/ares/src/interpreter.rs | 30 +++++++++++++++++------------- 1 file changed, 17 insertions(+), 13 deletions(-) diff --git a/rust/ares/src/interpreter.rs b/rust/ares/src/interpreter.rs index 7e5ebb5..71a2aed 100644 --- a/rust/ares/src/interpreter.rs +++ b/rust/ares/src/interpreter.rs @@ -334,8 +334,9 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res let work: NockWork = *context.stack.top(); match work { NockWork::Done => { - let stack = &mut context.stack; + write_trace(context); + let stack = &mut context.stack; debug_assertions(stack, orig_subject); debug_assertions(stack, subject); debug_assertions(stack, res); @@ -352,23 +353,13 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res break Ok(res); } NockWork::Ret => { - let stack = &mut context.stack; + write_trace(context); + let stack = &mut context.stack; debug_assertions(stack, orig_subject); debug_assertions(stack, subject); debug_assertions(stack, res); - // Write fast-hinted traces to trace file - if let Some(ref mut info) = &mut context.trace_info { - let trace_stack = *(stack.local_noun_pointer(1) as *mut *const TraceStack); - // Abort writing to trace file if we encountered an error. This should - // result in a well-formed partial trace file. - if let Err(e) = write_nock_trace(stack, info, trace_stack) { - eprintln!("\rError writing trace to file: {:?}", e); - context.trace_info = None; - } - } - stack.preserve(&mut context.cache); stack.preserve(&mut context.cold); stack.preserve(&mut context.warm); @@ -1248,6 +1239,19 @@ fn append_trace(stack: &mut NockStack, path: Noun) { } } +/// Write fast-hinted traces to trace file +unsafe fn write_trace(context: &mut Context) { + if let Some(ref mut info) = &mut context.trace_info { + let trace_stack = *(context.stack.local_noun_pointer(1) as *mut *const TraceStack); + // Abort writing to trace file if we encountered an error. This should + // result in a well-formed partial trace file. + if let Err(e) = write_nock_trace(&mut context.stack, info, trace_stack) { + eprintln!("\rError writing trace to file: {:?}", e); + context.trace_info = None; + } + } +} + mod hint { use super::*; use crate::jets; From d67dad2a0b54b6e6ae3f7e198bf1fa0600c3fa48 Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Fri, 17 Nov 2023 13:37:24 +0100 Subject: [PATCH 09/16] trace: fix invalid event names --- rust/ares/src/trace.rs | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/rust/ares/src/trace.rs b/rust/ares/src/trace.rs index fb4a16f..1be61dd 100644 --- a/rust/ares/src/trace.rs +++ b/rust/ares/src/trace.rs @@ -139,8 +139,15 @@ pub unsafe fn write_nock_trace( } let pc = path_to_cord(stack, (*trace_stack).path); - let pclen = met3_usize(pc); - let pc_str = &pc.as_bytes()[0..pclen]; + let pc_len = met3_usize(pc); + let pc_bytes = &pc.as_bytes()[0..pc_len]; + let pc_str = match std::str::from_utf8(pc_bytes) { + Ok(valid) => valid, + Err(error) => { + let (valid, _) = pc_bytes.split_at(error.valid_up_to()); + unsafe { std::str::from_utf8_unchecked(valid) } + } + }; assert_no_alloc::permit_alloc(|| { let obj = object! { From 6e58c32824a25363e07ec40a40977c03a1356d7a Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Sat, 18 Nov 2023 00:18:41 +0100 Subject: [PATCH 10/16] trace: add serf event tracing for work writs --- rust/ares/src/interpreter.rs | 2 +- rust/ares/src/serf.rs | 35 ++++++++++++++++++++++--- rust/ares/src/trace.rs | 51 ++++++++++++++++++++++++++++++++++++ 3 files changed, 84 insertions(+), 4 deletions(-) diff --git a/rust/ares/src/interpreter.rs b/rust/ares/src/interpreter.rs index 71a2aed..88b4118 100644 --- a/rust/ares/src/interpreter.rs +++ b/rust/ares/src/interpreter.rs @@ -1246,7 +1246,7 @@ unsafe fn write_trace(context: &mut Context) { // Abort writing to trace file if we encountered an error. This should // result in a well-formed partial trace file. if let Err(e) = write_nock_trace(&mut context.stack, info, trace_stack) { - eprintln!("\rError writing trace to file: {:?}", e); + eprintln!("\rserf: error writing nock trace to file: {:?}", e); context.trace_info = None; } } diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index 6db2203..da37bc2 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -12,7 +12,7 @@ use crate::newt::Newt; use crate::noun::{Cell, Noun, Slots, D, T}; use crate::snapshot::double_jam::DoubleJam; use crate::snapshot::Snapshot; -use crate::trace::{create_trace_file, write_metadata, TraceInfo}; +use crate::trace::*; use ares_macros::tas; use signal_hook; use signal_hook::consts::SIGINT; @@ -22,6 +22,7 @@ use std::path::PathBuf; use std::result::Result; use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::Arc; +use std::time::Instant; crate::gdb!(); @@ -206,7 +207,6 @@ pub fn serf() -> io::Result<()> { } else { None }; - if let Some(ref mut info) = trace_info.as_mut() { if let Err(e) = write_metadata(info) { eprintln!("\rError initializing trace file: {:?}", e); @@ -365,7 +365,36 @@ fn play_list(context: &mut Context, mut lit: Noun) { } fn work(context: &mut Context, job: Noun) { - match soft(context, job) { + let soft_res = if context.nock_context.trace_info.is_some() { + let start = Instant::now(); + // XX: good luck making this safe AND rust idiomatic! + let wire = job.slot(6).expect("serf: work: job missing wire"); + let vent = job + .slot(14) + .expect("serf: work: job missing event tag") + .as_atom() + .expect("serf: work: event tag not atom"); + let res = soft(context, job); + + // Abort writing to trace file if we encountered an error. This should + // result in a well-formed partial trace file. + if let Err(e) = write_event_trace( + &mut context.nock_context.stack, + context.nock_context.trace_info.as_mut().unwrap(), + wire, + vent, + start, + ) { + eprintln!("\rserf: work: error writing event trace to file: {:?}", e); + context.nock_context.trace_info = None; + } + + res + } else { + soft(context, job) + }; + + match soft_res { Ok(res) => { let cell = res.as_cell().expect("serf: work: +slam returned atom"); let fec = cell.head(); diff --git a/rust/ares/src/trace.rs b/rust/ares/src/trace.rs index 1be61dd..399ac2a 100644 --- a/rust/ares/src/trace.rs +++ b/rust/ares/src/trace.rs @@ -115,6 +115,57 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { Ok(()) } +pub fn write_event_trace( + stack: &mut NockStack, + info: &mut TraceInfo, + wire: Noun, + vent: Atom, + start: Instant, +) -> Result<(), Error> { + let dur = Instant::now().saturating_duration_since(start).as_micros() as f64; + let ts = start + .saturating_duration_since(info.process_start) + .as_micros() as f64; + + let wpc = path_to_cord(stack, wire); + let wpc_len = met3_usize(wpc); + let wpc_bytes = &wpc.as_bytes()[0..wpc_len]; + let wpc_str = match std::str::from_utf8(wpc_bytes) { + Ok(valid) => valid, + Err(error) => { + let (valid, _) = wpc_bytes.split_at(error.valid_up_to()); + unsafe { std::str::from_utf8_unchecked(valid) } + } + }; + + let vc_len = met3_usize(vent); + let vc_bytes = &vent.as_bytes()[0..vc_len]; + let vc_str = match std::str::from_utf8(vc_bytes) { + Ok(valid) => valid, + Err(error) => { + let (valid, _) = vc_bytes.split_at(error.valid_up_to()); + unsafe { std::str::from_utf8_unchecked(valid) } + } + }; + + assert_no_alloc::permit_alloc(|| { + let name = format!("work [{} {}]", wpc_str, vc_str); + let obj = object! { + cat: "event", + name: name, + ph: "X", + pid: info.pid, + tid: 1, + ts: ts, + dur: dur, + }; + obj.write(&mut info.file) + })?; + info.file.write_all(",\n".as_bytes())?; + + Ok(()) +} + pub unsafe fn write_nock_trace( stack: &mut NockStack, info: &mut TraceInfo, From eef367bb639f0d20b061ee2b2643d50d9d8b9630 Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Sun, 19 Nov 2023 14:10:17 -0500 Subject: [PATCH 11/16] trace: add serf event tracing for play writs --- rust/ares/src/serf.rs | 109 +++++++++++++++++++++++++++++------------ rust/ares/src/trace.rs | 60 ++++++++--------------- 2 files changed, 98 insertions(+), 71 deletions(-) diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index da37bc2..318ad79 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -7,9 +7,9 @@ use crate::jets::list::util::{lent, zing}; use crate::jets::nock::util::mook; use crate::jets::warm::Warm; use crate::mem::NockStack; -use crate::mug::mug_u32; +use crate::mug::*; use crate::newt::Newt; -use crate::noun::{Cell, Noun, Slots, D, T}; +use crate::noun::{Atom, Cell, DirectAtom, Noun, Slots, D, T}; use crate::snapshot::double_jam::DoubleJam; use crate::snapshot::Snapshot; use crate::trace::*; @@ -22,7 +22,6 @@ use std::path::PathBuf; use std::result::Result; use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::Arc; -use std::time::Instant; crate::gdb!(); @@ -302,9 +301,31 @@ fn goof(context: &mut Context, traces: Noun) -> Noun { T(&mut context.nock_context.stack, &[D(tas!(b"exit")), tang]) } -/** Run slam, process stack trace to tang if error */ -fn soft(context: &mut Context, ovo: Noun) -> Result { - match slam(context, POKE_AXIS, ovo) { +/** Run slam; process stack trace to tang if error. + * Generate tracing events, if JSON tracing enabled. + */ +fn soft(context: &mut Context, ovo: Noun, trace_name: Option) -> Result { + if let Some(ref mut info) = &mut context.nock_context.trace_info { + // Abort writing to trace file if we encountered an error. This should result in a + // well-formed partial trace file. + if let Err(e) = write_serf_trace_start(info, trace_name.as_ref().unwrap()) { + eprintln!("\rserf: error writing event trace to file: {:?}", e); + context.nock_context.trace_info = None; + } + } + + let slam_res = slam(context, POKE_AXIS, ovo); + + if let Some(ref mut info) = &mut context.nock_context.trace_info { + // Abort writing to trace file if we encountered an error. This should result in a + // well-formed partial trace file. + if let Err(e) = write_serf_trace_end(info, trace_name.as_ref().unwrap()) { + eprintln!("\rserf: error writing event trace to file: {:?}", e); + context.nock_context.trace_info = None; + } + } + + match slam_res { Ok(res) => Ok(res), Err(error) => match error { Error::Deterministic(trace) | Error::NonDeterministic(trace) => { @@ -335,7 +356,7 @@ fn play_life(context: &mut Context, eve: Noun) { context.play_bail(goof); } Error::ScryBlocked(_) | Error::ScryCrashed(_) => { - panic!("serf: soft: .^ invalid outside of virtual Nock") + panic!("serf: play: .^ invalid outside of virtual Nock") } }, } @@ -345,7 +366,13 @@ fn play_list(context: &mut Context, mut lit: Noun) { let mut eve = context.event_num; while let Ok(cell) = lit.as_cell() { let ovo = cell.head(); - match soft(context, ovo) { + let trace_name = if context.nock_context.trace_info.is_some() { + Some(format!("play [{}]", eve)) + } else { + None + }; + + match soft(context, ovo, trace_name) { Ok(res) => { let arvo = res .as_cell() @@ -365,8 +392,7 @@ fn play_list(context: &mut Context, mut lit: Noun) { } fn work(context: &mut Context, job: Noun) { - let soft_res = if context.nock_context.trace_info.is_some() { - let start = Instant::now(); + let trace_name = if context.nock_context.trace_info.is_some() { // XX: good luck making this safe AND rust idiomatic! let wire = job.slot(6).expect("serf: work: job missing wire"); let vent = job @@ -374,27 +400,13 @@ fn work(context: &mut Context, job: Noun) { .expect("serf: work: job missing event tag") .as_atom() .expect("serf: work: event tag not atom"); - let res = soft(context, job); - // Abort writing to trace file if we encountered an error. This should - // result in a well-formed partial trace file. - if let Err(e) = write_event_trace( - &mut context.nock_context.stack, - context.nock_context.trace_info.as_mut().unwrap(), - wire, - vent, - start, - ) { - eprintln!("\rserf: work: error writing event trace to file: {:?}", e); - context.nock_context.trace_info = None; - } - - res + Some(work_trace_name(&mut context.nock_context.stack, wire, vent)) } else { - soft(context, job) + None }; - match soft_res { + match soft(context, job, trace_name) { Ok(res) => { let cell = res.as_cell().expect("serf: work: +slam returned atom"); let fec = cell.head(); @@ -417,21 +429,31 @@ fn work_swap(context: &mut Context, job: Noun, goof: Noun) { clear_interrupt(); let stack = &mut context.nock_context.stack; - // crud = [+(now) [%$ %arvo ~] [%crud goof ovo]] + // crud ovo = [+(now) [%$ %arvo ~] [%crud goof ovo]] let job_cell = job.as_cell().expect("serf: work: job not a cell"); let job_now = job_cell.head().as_atom().expect("serf: work: now not atom"); let now = inc(stack, job_now).as_noun(); let wire = T(stack, &[D(0), D(tas!(b"arvo")), D(0)]); - let crud = T(stack, &[now, wire, D(tas!(b"crud")), goof, job_cell.tail()]); + let crud = DirectAtom::new_panic(tas!(b"crud")); + let ovo = T(stack, &[now, wire, crud.as_noun(), goof, job_cell.tail()]); + let trace_name = if context.nock_context.trace_info.is_some() { + Some(work_trace_name( + &mut context.nock_context.stack, + wire, + crud.as_atom(), + )) + } else { + None + }; - match soft(context, crud) { + match soft(context, ovo, trace_name) { Ok(res) => { let cell = res.as_cell().expect("serf: work: crud +slam returned atom"); let fec = cell.head(); let eve = context.event_num; context.event_update(eve + 1, cell.tail()); - context.work_swap(crud, fec); + context.work_swap(ovo, fec); } Err(goof_crud) => { work_bail(context, &[goof_crud, goof]); @@ -446,6 +468,31 @@ fn work_bail(context: &mut Context, goofs: &[Noun]) { context.work_bail(lud); } +fn work_trace_name(stack: &mut NockStack, wire: Noun, vent: Atom) -> String { + let wpc = path_to_cord(stack, wire); + let wpc_len = met3_usize(wpc); + let wpc_bytes = &wpc.as_bytes()[0..wpc_len]; + let wpc_str = match std::str::from_utf8(wpc_bytes) { + Ok(valid) => valid, + Err(error) => { + let (valid, _) = wpc_bytes.split_at(error.valid_up_to()); + unsafe { std::str::from_utf8_unchecked(valid) } + } + }; + + let vc_len = met3_usize(vent); + let vc_bytes = &vent.as_bytes()[0..vc_len]; + let vc_str = match std::str::from_utf8(vc_bytes) { + Ok(valid) => valid, + Err(error) => { + let (valid, _) = vc_bytes.split_at(error.valid_up_to()); + unsafe { std::str::from_utf8_unchecked(valid) } + } + }; + + format!("work [{} {}]", wpc_str, vc_str) +} + fn slot(noun: Noun, axis: u64) -> io::Result { noun.slot(axis) .map_err(|_e| io::Error::new(io::ErrorKind::InvalidInput, "Bad axis")) diff --git a/rust/ares/src/trace.rs b/rust/ares/src/trace.rs index 399ac2a..5b14f67 100644 --- a/rust/ares/src/trace.rs +++ b/rust/ares/src/trace.rs @@ -75,7 +75,7 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { name: "thread_name", ph: "M", pid: info.pid, - tid: 1, + tid: 1, // XX: get tid in Rust args: object!{ name: "Event Processing", }, }) .write(&mut info.file)?; @@ -85,7 +85,7 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { name: "thread_sort_index", ph: "M", pid: info.pid, - tid: 1, + tid: 1, // XX: get tid in Rust args: object!{ sort_index: 1, }, }) .write(&mut info.file)?; @@ -95,7 +95,7 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { name: "thread_name", ph: "M", pid: info.pid, - tid: 2, + tid: 2, // XX: get tid in Rust args: object!{ name: "Nock", }, }) .write(&mut info.file)?; @@ -105,7 +105,7 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { name: "thread_sort_index", ph: "M", pid: info.pid, - tid: 2, + tid: 2, // XX: get tid in Rust args: object!{ sort_index: 2, }, }) .write(&mut info.file)?; @@ -115,49 +115,29 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { Ok(()) } -pub fn write_event_trace( - stack: &mut NockStack, - info: &mut TraceInfo, - wire: Noun, - vent: Atom, - start: Instant, -) -> Result<(), Error> { - let dur = Instant::now().saturating_duration_since(start).as_micros() as f64; - let ts = start +pub fn write_serf_trace_start(info: &mut TraceInfo, name: &str) -> Result<(), Error> { + let phase = "B"; + write_serf_trace_event(info, name, phase) +} + +pub fn write_serf_trace_end(info: &mut TraceInfo, name: &str) -> Result<(), Error> { + let phase = "E"; + write_serf_trace_event(info, name, phase) +} + +pub fn write_serf_trace_event(info: &mut TraceInfo, name: &str, phase: &str) -> Result<(), Error> { + let ts = Instant::now() .saturating_duration_since(info.process_start) .as_micros() as f64; - let wpc = path_to_cord(stack, wire); - let wpc_len = met3_usize(wpc); - let wpc_bytes = &wpc.as_bytes()[0..wpc_len]; - let wpc_str = match std::str::from_utf8(wpc_bytes) { - Ok(valid) => valid, - Err(error) => { - let (valid, _) = wpc_bytes.split_at(error.valid_up_to()); - unsafe { std::str::from_utf8_unchecked(valid) } - } - }; - - let vc_len = met3_usize(vent); - let vc_bytes = &vent.as_bytes()[0..vc_len]; - let vc_str = match std::str::from_utf8(vc_bytes) { - Ok(valid) => valid, - Err(error) => { - let (valid, _) = vc_bytes.split_at(error.valid_up_to()); - unsafe { std::str::from_utf8_unchecked(valid) } - } - }; - assert_no_alloc::permit_alloc(|| { - let name = format!("work [{} {}]", wpc_str, vc_str); let obj = object! { cat: "event", name: name, - ph: "X", + ph: phase, pid: info.pid, - tid: 1, + tid: 1, // XX: get tid in Rust ts: ts, - dur: dur, }; obj.write(&mut info.file) })?; @@ -206,7 +186,7 @@ pub unsafe fn write_nock_trace( name: pc_str, ph: "X", pid: info.pid, - tid: 2, + tid: 2, // XX: get tid in Rust ts: ts, dur: dur, }; @@ -222,7 +202,7 @@ pub unsafe fn write_nock_trace( } // XX: Need Rust string interpolation helper that doesn't allocate -fn path_to_cord(stack: &mut NockStack, path: Noun) -> Atom { +pub fn path_to_cord(stack: &mut NockStack, path: Noun) -> Atom { let mut cursor = path; let mut length = 0usize; From 60aaa45443d7065a02d4884fe19b421182398883 Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Sun, 19 Nov 2023 14:33:30 -0500 Subject: [PATCH 12/16] trace: add serf event tracing for peek writs --- rust/ares/src/serf.rs | 32 +++++++++++++++++++++++++++++--- 1 file changed, 29 insertions(+), 3 deletions(-) diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index 318ad79..167bc43 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -242,9 +242,8 @@ pub fn serf() -> io::Result<()> { context.live(); } tas!(b"peek") => { - let sam = slot(writ, 7)?; - let res = - slam(&mut context, PEEK_AXIS, sam).expect("peek error handling unimplemented"); + let ovo = slot(writ, 7)?; + let res = peek(&mut context, ovo); context.peek_done(res); } tas!(b"play") => { @@ -289,6 +288,33 @@ fn slam(context: &mut Context, axis: u64, ovo: Noun) -> Result { interpret(&mut context.nock_context, sub, fol) } +fn peek(context: &mut Context, ovo: Noun) -> Noun { + if context.nock_context.trace_info.is_some() { + // XX: way too many cases in the input to pull the actual vane, care, and path out + let trace_name = "peek"; + + let _ = write_serf_trace_start( + context.nock_context.trace_info.as_mut().unwrap(), + trace_name, + ); + let slam_res = slam(context, PEEK_AXIS, ovo); + + // Abort writing to trace file if we encountered an error. This should result in a + // well-formed partial trace file. + if let Err(e) = write_serf_trace_start( + context.nock_context.trace_info.as_mut().unwrap(), + trace_name, + ) { + eprintln!("\rserf: error writing event trace to file: {:?}", e); + context.nock_context.trace_info = None; + } + + slam_res.expect("peek error handling unimplemented") + } else { + slam(context, PEEK_AXIS, ovo).expect("peek error handling unimplemented") + } +} + fn goof(context: &mut Context, traces: Noun) -> Noun { let trace = zing(&mut context.nock_context.stack, traces).unwrap(); let tone = Cell::new(&mut context.nock_context.stack, D(2), trace); From c40896c429574d7173af91079b96e299e4082e2f Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Sun, 19 Nov 2023 14:51:57 -0500 Subject: [PATCH 13/16] trace: add serf event tracing for initial boot --- rust/ares/src/serf.rs | 28 +++++++++++++++++++++++++--- 1 file changed, 25 insertions(+), 3 deletions(-) diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index 167bc43..aac40ad 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -292,7 +292,6 @@ fn peek(context: &mut Context, ovo: Noun) -> Noun { if context.nock_context.trace_info.is_some() { // XX: way too many cases in the input to pull the actual vane, care, and path out let trace_name = "peek"; - let _ = write_serf_trace_start( context.nock_context.trace_info.as_mut().unwrap(), trace_name, @@ -301,7 +300,7 @@ fn peek(context: &mut Context, ovo: Noun) -> Noun { // Abort writing to trace file if we encountered an error. This should result in a // well-formed partial trace file. - if let Err(e) = write_serf_trace_start( + if let Err(e) = write_serf_trace_end( context.nock_context.trace_info.as_mut().unwrap(), trace_name, ) { @@ -368,7 +367,30 @@ fn play_life(context: &mut Context, eve: Noun) { let stack = &mut context.nock_context.stack; let sub = T(stack, &[D(0), D(3)]); let lyf = T(stack, &[D(2), sub, D(0), D(2)]); - match interpret(&mut context.nock_context, eve, lyf) { + let res = if context.nock_context.trace_info.is_some() { + let trace_name = "boot"; + let _ = write_serf_trace_start( + context.nock_context.trace_info.as_mut().unwrap(), + trace_name, + ); + let boot_res = interpret(&mut context.nock_context, eve, lyf); + + // Abort writing to trace file if we encountered an error. This should result in a + // well-formed partial trace file. + if let Err(e) = write_serf_trace_end( + context.nock_context.trace_info.as_mut().unwrap(), + trace_name, + ) { + eprintln!("\rserf: error writing event trace to file: {:?}", e); + context.nock_context.trace_info = None; + } + + boot_res + } else { + interpret(&mut context.nock_context, eve, lyf) + }; + + match res { Ok(gat) => { let eved = lent(eve).expect("serf: play: boot event number failure") as u64; let arvo = slot(gat, 7).expect("serf: play: lifecycle didn't return initial Arvo"); From 8968ed4597cfac2c91e5393707c783386e656f1f Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Sun, 19 Nov 2023 15:03:18 -0500 Subject: [PATCH 14/16] trace: replace duration events with completion events --- rust/ares/src/serf.rs | 45 +++++++++++++++++++----------------------- rust/ares/src/trace.rs | 18 +++++------------ 2 files changed, 25 insertions(+), 38 deletions(-) diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index aac40ad..2ef1eab 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -22,6 +22,7 @@ use std::path::PathBuf; use std::result::Result; use std::sync::atomic::{AtomicBool, Ordering}; use std::sync::Arc; +use std::time::Instant; crate::gdb!(); @@ -292,17 +293,14 @@ fn peek(context: &mut Context, ovo: Noun) -> Noun { if context.nock_context.trace_info.is_some() { // XX: way too many cases in the input to pull the actual vane, care, and path out let trace_name = "peek"; - let _ = write_serf_trace_start( - context.nock_context.trace_info.as_mut().unwrap(), - trace_name, - ); + let start = Instant::now(); let slam_res = slam(context, PEEK_AXIS, ovo); - // Abort writing to trace file if we encountered an error. This should result in a // well-formed partial trace file. - if let Err(e) = write_serf_trace_end( + if let Err(e) = write_serf_trace( context.nock_context.trace_info.as_mut().unwrap(), trace_name, + start, ) { eprintln!("\rserf: error writing event trace to file: {:?}", e); context.nock_context.trace_info = None; @@ -330,25 +328,25 @@ fn goof(context: &mut Context, traces: Noun) -> Noun { * Generate tracing events, if JSON tracing enabled. */ fn soft(context: &mut Context, ovo: Noun, trace_name: Option) -> Result { - if let Some(ref mut info) = &mut context.nock_context.trace_info { + let slam_res = if context.nock_context.trace_info.is_some() { + let start = Instant::now(); + let slam_res = slam(context, POKE_AXIS, ovo); + // Abort writing to trace file if we encountered an error. This should result in a // well-formed partial trace file. - if let Err(e) = write_serf_trace_start(info, trace_name.as_ref().unwrap()) { + if let Err(e) = write_serf_trace( + context.nock_context.trace_info.as_mut().unwrap(), + trace_name.as_ref().unwrap(), + start, + ) { eprintln!("\rserf: error writing event trace to file: {:?}", e); context.nock_context.trace_info = None; } - } - let slam_res = slam(context, POKE_AXIS, ovo); - - if let Some(ref mut info) = &mut context.nock_context.trace_info { - // Abort writing to trace file if we encountered an error. This should result in a - // well-formed partial trace file. - if let Err(e) = write_serf_trace_end(info, trace_name.as_ref().unwrap()) { - eprintln!("\rserf: error writing event trace to file: {:?}", e); - context.nock_context.trace_info = None; - } - } + slam_res + } else { + slam(context, POKE_AXIS, ovo) + }; match slam_res { Ok(res) => Ok(res), @@ -369,17 +367,14 @@ fn play_life(context: &mut Context, eve: Noun) { let lyf = T(stack, &[D(2), sub, D(0), D(2)]); let res = if context.nock_context.trace_info.is_some() { let trace_name = "boot"; - let _ = write_serf_trace_start( - context.nock_context.trace_info.as_mut().unwrap(), - trace_name, - ); + let start = Instant::now(); let boot_res = interpret(&mut context.nock_context, eve, lyf); - // Abort writing to trace file if we encountered an error. This should result in a // well-formed partial trace file. - if let Err(e) = write_serf_trace_end( + if let Err(e) = write_serf_trace( context.nock_context.trace_info.as_mut().unwrap(), trace_name, + start, ) { eprintln!("\rserf: error writing event trace to file: {:?}", e); context.nock_context.trace_info = None; diff --git a/rust/ares/src/trace.rs b/rust/ares/src/trace.rs index 5b14f67..e9116c0 100644 --- a/rust/ares/src/trace.rs +++ b/rust/ares/src/trace.rs @@ -115,29 +115,21 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { Ok(()) } -pub fn write_serf_trace_start(info: &mut TraceInfo, name: &str) -> Result<(), Error> { - let phase = "B"; - write_serf_trace_event(info, name, phase) -} - -pub fn write_serf_trace_end(info: &mut TraceInfo, name: &str) -> Result<(), Error> { - let phase = "E"; - write_serf_trace_event(info, name, phase) -} - -pub fn write_serf_trace_event(info: &mut TraceInfo, name: &str, phase: &str) -> Result<(), Error> { - let ts = Instant::now() +pub fn write_serf_trace(info: &mut TraceInfo, name: &str, start: Instant) -> Result<(), Error> { + let ts = start .saturating_duration_since(info.process_start) .as_micros() as f64; + let dur = Instant::now().saturating_duration_since(start).as_micros() as f64; assert_no_alloc::permit_alloc(|| { let obj = object! { cat: "event", name: name, - ph: phase, + ph: "X", pid: info.pid, tid: 1, // XX: get tid in Rust ts: ts, + dur: dur, }; obj.write(&mut info.file) })?; From 9fb2b1f510dcab56252ea797559ddfbdc7573dfe Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Sun, 19 Nov 2023 15:22:56 -0500 Subject: [PATCH 15/16] trace: simplify code to disable tracing on failure --- rust/ares/src/serf.rs | 34 +++++----------------------------- rust/ares/src/trace.rs | 10 ++++++++++ 2 files changed, 15 insertions(+), 29 deletions(-) diff --git a/rust/ares/src/serf.rs b/rust/ares/src/serf.rs index 2ef1eab..319813b 100644 --- a/rust/ares/src/serf.rs +++ b/rust/ares/src/serf.rs @@ -295,16 +295,7 @@ fn peek(context: &mut Context, ovo: Noun) -> Noun { let trace_name = "peek"; let start = Instant::now(); let slam_res = slam(context, PEEK_AXIS, ovo); - // Abort writing to trace file if we encountered an error. This should result in a - // well-formed partial trace file. - if let Err(e) = write_serf_trace( - context.nock_context.trace_info.as_mut().unwrap(), - trace_name, - start, - ) { - eprintln!("\rserf: error writing event trace to file: {:?}", e); - context.nock_context.trace_info = None; - } + write_serf_trace_safe(&mut context.nock_context.trace_info, trace_name, start); slam_res.expect("peek error handling unimplemented") } else { @@ -331,17 +322,11 @@ fn soft(context: &mut Context, ovo: Noun, trace_name: Option) -> Result< let slam_res = if context.nock_context.trace_info.is_some() { let start = Instant::now(); let slam_res = slam(context, POKE_AXIS, ovo); - - // Abort writing to trace file if we encountered an error. This should result in a - // well-formed partial trace file. - if let Err(e) = write_serf_trace( - context.nock_context.trace_info.as_mut().unwrap(), + write_serf_trace_safe( + &mut context.nock_context.trace_info, trace_name.as_ref().unwrap(), start, - ) { - eprintln!("\rserf: error writing event trace to file: {:?}", e); - context.nock_context.trace_info = None; - } + ); slam_res } else { @@ -369,16 +354,7 @@ fn play_life(context: &mut Context, eve: Noun) { let trace_name = "boot"; let start = Instant::now(); let boot_res = interpret(&mut context.nock_context, eve, lyf); - // Abort writing to trace file if we encountered an error. This should result in a - // well-formed partial trace file. - if let Err(e) = write_serf_trace( - context.nock_context.trace_info.as_mut().unwrap(), - trace_name, - start, - ) { - eprintln!("\rserf: error writing event trace to file: {:?}", e); - context.nock_context.trace_info = None; - } + write_serf_trace_safe(&mut context.nock_context.trace_info, trace_name, start); boot_res } else { diff --git a/rust/ares/src/trace.rs b/rust/ares/src/trace.rs index e9116c0..bacafa0 100644 --- a/rust/ares/src/trace.rs +++ b/rust/ares/src/trace.rs @@ -115,6 +115,16 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { Ok(()) } +/// Abort writing to trace file if an error is encountered. +/// +/// This should result in a well-formed partial trace file. +pub fn write_serf_trace_safe(info: &mut Option, name: &str, start: Instant) { + if let Err(e) = write_serf_trace(info.as_mut().unwrap(), name, start) { + eprintln!("\rserf: error writing event trace to file: {:?}", e); + *info = None; + } +} + pub fn write_serf_trace(info: &mut TraceInfo, name: &str, start: Instant) -> Result<(), Error> { let ts = start .saturating_duration_since(info.process_start) From 7267fcfe32fb6a4b25bf52db6e57510cd1ef16b3 Mon Sep 17 00:00:00 2001 From: Alex Shelkovnykov Date: Sun, 19 Nov 2023 15:28:26 -0500 Subject: [PATCH 16/16] trace: remove fake thread distinction --- rust/ares/src/trace.rs | 28 ++++------------------------ 1 file changed, 4 insertions(+), 24 deletions(-) diff --git a/rust/ares/src/trace.rs b/rust/ares/src/trace.rs index bacafa0..69eedf3 100644 --- a/rust/ares/src/trace.rs +++ b/rust/ares/src/trace.rs @@ -75,7 +75,7 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { name: "thread_name", ph: "M", pid: info.pid, - tid: 1, // XX: get tid in Rust + tid: 1, args: object!{ name: "Event Processing", }, }) .write(&mut info.file)?; @@ -85,32 +85,12 @@ pub fn write_metadata(info: &mut TraceInfo) -> Result<(), Error> { name: "thread_sort_index", ph: "M", pid: info.pid, - tid: 1, // XX: get tid in Rust + tid: 1, args: object!{ sort_index: 1, }, }) .write(&mut info.file)?; info.file.write_all(",\n".as_bytes())?; - (object! { - name: "thread_name", - ph: "M", - pid: info.pid, - tid: 2, // XX: get tid in Rust - args: object!{ name: "Nock", }, - }) - .write(&mut info.file)?; - info.file.write_all(",\n".as_bytes())?; - - (object! { - name: "thread_sort_index", - ph: "M", - pid: info.pid, - tid: 2, // XX: get tid in Rust - args: object!{ sort_index: 2, }, - }) - .write(&mut info.file)?; - info.file.write_all(",\n".as_bytes())?; - info.file.sync_data()?; Ok(()) } @@ -137,7 +117,7 @@ pub fn write_serf_trace(info: &mut TraceInfo, name: &str, start: Instant) -> Res name: name, ph: "X", pid: info.pid, - tid: 1, // XX: get tid in Rust + tid: 1, ts: ts, dur: dur, }; @@ -188,7 +168,7 @@ pub unsafe fn write_nock_trace( name: pc_str, ph: "X", pid: info.pid, - tid: 2, // XX: get tid in Rust + tid: 1, ts: ts, dur: dur, };