Merge pull request #122 from urbit/eamsden/event-profiling

Event-based profiling

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",
-]
+]

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"

rust/ares/src/interpreter.rs

@@ -13,6 +13,7 @@ use crate::newt::Newt;
 use crate::noun;
 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};
@@ -20,6 +21,7 @@ use either::Either::*;
 use std::result;
 use std::sync::atomic::Ordering;
 use std::sync::Arc;
+use std::time::Instant;
 
 crate::gdb!();
 
@@ -263,6 +265,7 @@ pub struct Context {
     // Per-event cache; option to share cache with virtualized events
     pub cache: Hamt<Noun>,
     pub scry_stack: Noun,
+    pub trace_info: Option<TraceInfo>,
 }
 
 #[derive(Clone, Copy, Debug)]
@@ -303,9 +306,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;
     };
 
@@ -327,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);
@@ -345,8 +353,9 @@ 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);
@@ -620,6 +629,16 @@ pub fn interpret(context: &mut Context, mut subject: Noun, formula: Noun) -> Res
                                 let stack = &mut context.stack;
                                 if kale.tail {
                                     stack.pop::<NockWork>();
+
+                                    // 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) {
+                                            append_trace(stack, path);
+                                        };
+                                    };
+
                                     subject = res;
                                     push_formula(stack, formula, true)?;
                                 } else {
@@ -635,6 +654,15 @@ 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)?;
+
+                                    // 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) {
+                                            append_trace(stack, path);
+                                        };
+                                    };
                                 }
                             } else {
                                 // Axis into core must be atom
@@ -1067,7 +1095,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;
 
@@ -1100,8 +1128,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 +1225,33 @@ pub fn inc(stack: &mut NockStack, atom: Atom) -> Atom {
     }
 }
 
+/// 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;
+    }
+}
+
+/// 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!("\rserf: error writing nock trace to file: {:?}", e);
+            context.trace_info = None;
+        }
+    }
+}
+
 mod hint {
     use super::*;
     use crate::jets;

rust/ares/src/jets.rs

@@ -268,6 +268,7 @@ pub mod util {
                 hot,
                 cache,
                 scry_stack: D(0),
+                trace_info: None,
             }
         }
 

rust/ares/src/jets/bits.rs

@@ -145,46 +145,7 @@ 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 {
@@ -345,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};
+    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 {
@@ -418,6 +380,52 @@ pub mod util {
         }
     }
 
+    pub fn rap(
+        stack: &mut NockStack,
+        bloq: usize,
+        original_list: Noun,
+    ) -> result::Result<Atom, JetErr> {
+        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::*;

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<NounList>,
@@ -341,6 +341,25 @@ 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<Noun> {
+        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);
+                    }
+                }
+            }
+        };
+        None
+    }
+
     /// register a core, return a boolean of whether we actually needed to register (false ->
     /// already registered)
     ///

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
  *

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");

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) => {

rust/ares/src/serf.rs

@@ -7,11 +7,12 @@ 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::*;
 use ares_macros::tas;
 use signal_hook;
 use signal_hook::consts::SIGINT;
@@ -21,9 +22,12 @@ use std::path::PathBuf;
 use std::result::Result;
 use std::sync::atomic::{AtomicBool, Ordering};
 use std::sync::Arc;
+use std::time::Instant;
 
 crate::gdb!();
 
+const FLAG_TRACE: u32 = 1 << 8;
+
 struct Context {
     epoch: u64,
     event_num: u64,
@@ -34,7 +38,7 @@ struct Context {
 }
 
 impl Context {
-    pub fn new(snap_path: &PathBuf) -> Self {
+    pub fn new(snap_path: &PathBuf, trace_info: Option<TraceInfo>) -> 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 +61,7 @@ impl Context {
             hot,
             cache,
             scry_stack: D(0),
+            trace_info,
         };
 
         Context {
@@ -179,15 +184,37 @@ 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 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() {
+        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);
     context.ripe();
 
     // Can't use for loop because it borrows newt
@@ -216,9 +243,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") => {
@@ -263,6 +289,20 @@ fn slam(context: &mut Context, axis: u64, ovo: Noun) -> Result<Noun, Error> {
     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 start = Instant::now();
+        let slam_res = slam(context, PEEK_AXIS, ovo);
+        write_serf_trace_safe(&mut context.nock_context.trace_info, trace_name, start);
+
+        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);
@@ -275,9 +315,25 @@ 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<Noun, Noun> {
-    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<String>) -> Result<Noun, Noun> {
+    let slam_res = if context.nock_context.trace_info.is_some() {
+        let start = Instant::now();
+        let slam_res = slam(context, POKE_AXIS, ovo);
+        write_serf_trace_safe(
+            &mut context.nock_context.trace_info,
+            trace_name.as_ref().unwrap(),
+            start,
+        );
+
+        slam_res
+    } else {
+        slam(context, POKE_AXIS, ovo)
+    };
+
+    match slam_res {
         Ok(res) => Ok(res),
         Err(error) => match error {
             Error::Deterministic(trace) | Error::NonDeterministic(trace) => {
@@ -294,7 +350,18 @@ 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 start = Instant::now();
+        let boot_res = interpret(&mut context.nock_context, eve, lyf);
+        write_serf_trace_safe(&mut context.nock_context.trace_info, trace_name, start);
+
+        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");
@@ -308,7 +375,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")
             }
         },
     }
@@ -318,7 +385,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()
@@ -338,7 +411,21 @@ fn play_list(context: &mut Context, mut lit: Noun) {
 }
 
 fn work(context: &mut Context, job: Noun) {
-    match soft(context, job) {
+    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
+            .slot(14)
+            .expect("serf: work: job missing event tag")
+            .as_atom()
+            .expect("serf: work: event tag not atom");
+
+        Some(work_trace_name(&mut context.nock_context.stack, wire, vent))
+    } else {
+        None
+    };
+
+    match soft(context, job, trace_name) {
         Ok(res) => {
             let cell = res.as_cell().expect("serf: work: +slam returned atom");
             let fec = cell.head();
@@ -361,21 +448,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]);
@@ -390,6 +487,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> {
     noun.slot(axis)
         .map_err(|_e| io::Error::new(io::ErrorKind::InvalidInput, "Bad axis"))

rust/ares/src/trace.rs

@@ -0,0 +1,257 @@
+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<TraceInfo, Error> {
+    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) -> Result<(), Error> {
+    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())?;
+
+    info.file.sync_data()?;
+    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<TraceInfo>, 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)
+        .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: "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,
+    mut trace_stack: *const TraceStack,
+) -> Result<(), Error> {
+    let now = Instant::now();
+
+    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 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! {
+                cat: "nock",
+                name: pc_str,
+                ph: "X",
+                pid: info.pid,
+                tid: 1,
+                ts: ts,
+                dur: dur,
+            };
+            obj.write(&mut info.file)
+        })?;
+        info.file.write_all(",\n".as_bytes())?;
+
+        trace_stack = (*trace_stack).next;
+    }
+
+    info.file.sync_data()?;
+    Ok(())
+}
+
+//  XX: Need Rust string interpolation helper that doesn't allocate
+pub 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() }
+}