serf: add event-trace profiling (-j in king) for fast-hinted cores

This commit is contained in:
Edward Amsden 2023-11-09 15:02:51 -06:00
parent 3bb124b52a
commit 63d91d3cd5
6 changed files with 327 additions and 51 deletions

View File

@ -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<Noun>,
pub scry_stack: Noun,
pub trace_info: Option<TraceInfo>,
}
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::<NockWork>();
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);
}
}

View File

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

View File

@ -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<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::*;

View File

@ -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(())
}

View File

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

View File

@ -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<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 +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