nx_trace.nx source
↩ module page · 170 lines · 6367 B
1// nx_trace.nx -- span-based tracing.
2//
3// Structured call-tree observability. When a function enters +
4// exits, emit a pair of span events with matching IDs, so offline
5// analysis can reconstruct the exact call path and timing profile.
6//
7// Design draws from:
8//
9// OpenTelemetry tracing data model -- span id, parent id,
10// start/end, attributes
11// Google Dapper (Sigelman et al 2010) -- distributed tracing
12// origin paper
13// Rust tracing crate -- in-process span primitives
14// Linux ftrace -- kernel-mode per-function trace
15// perf probe -- USDT tracepoints
16//
17// Span events are emitted through nx_log, so all existing
18// level/tag/filter infrastructure applies. Format:
19//
20// <seq> DEBUG span.enter <tag> id=<N> parent=<P>
21// <seq> DEBUG span.exit <tag> id=<N> dt=<elapsed_ticks>
22//
23// Matching pairs reconstruct the tree off-line via seq ordering.
24// `dt` is a monotonic tick counter the tracer maintains (NOT
25// wall-clock, by design -- reproducible across runs).
26//
27// Not yet (deferred):
28// * rdtime CSR read for real wall-clock nanoseconds. Needs
29// inline asm in NishiLang, which we don't have yet. When
30// it lands, dt gets real ns units.
31// * Sampling -- limit overhead by only tracing every N calls.
32// * Remote export -- emit spans to a socket in OTLP / Zipkin
33// protobuf format for external analyzers.
34//
35// Span IDs are monotonic per-context. Parent id = id of the
36// enclosing span, or 0 for root spans. For single-threaded v0.0.1
37// we track a stack of active span ids. When threading arrives,
38// per-thread span stacks + flush-on-thread-join are the pattern.
39
40// nx_safety_envelope:
41// intended_use: AUTO_APPLIED -- primitive-specific tuning queued
42// sil_target: SIL1
43// evidence: [bulk_applied_2026-05-16, see-file-comment-for-detail]
44// verdict: NOT_YET_EVALUATED
45
46import "syscalls.nx"
47import "nx_log.nx"
48
49const NX_TRACE_STACK_DEPTH: i64 = 64
50
51struct NxTraceCtx {
52 log: *NxLogContext, // where span events go (DEBUG level)
53 next_id: i64, // monotonic span-id counter
54 tick: i64, // monotonic tick counter (our wall-clock stand-in)
55 stack: *i64, // span id stack (for parent lookup)
56 stack_depth: i64, // current nesting
57}
58
59const NX_TRACE_CTX_BYTES: i64 = 48
60
61// --- construction --------------------------------------------------
62
63func nx_trace_new(log: *NxLogContext) -> *NxTraceCtx {
64 let raw: *u8 = sys_mmap(NX_TRACE_CTX_BYTES)
65 let c: *NxTraceCtx = raw as *NxTraceCtx
66 c.log = log
67 c.next_id = 1 // 0 reserved for "no parent"
68 c.tick = 0
69 c.stack = sys_mmap(NX_TRACE_STACK_DEPTH * 8) as *i64
70 c.stack_depth = 0
71 return c
72}
73
74// --- span entry/exit -----------------------------------------------
75
76// Enter a new span with `tag`. Returns the span id to pass to
77// nx_span_exit. Parent is the current top-of-stack (0 if none).
78func nx_span_enter(ctx: *NxTraceCtx, tag: *u8) -> i64 {
79 let id: i64 = ctx.next_id
80 ctx.next_id = id + 1
81 var parent: i64 = 0
82 if ctx.stack_depth > 0 {
83 parent = ctx.stack[ctx.stack_depth - 1]
84 }
85
86 // Push onto stack (bounded).
87 if ctx.stack_depth < NX_TRACE_STACK_DEPTH {
88 ctx.stack[ctx.stack_depth] = id
89 ctx.stack_depth = ctx.stack_depth + 1
90 }
91
92 // Emit span.enter event.
93 nx_log_emit(ctx.log, NX_LOG_DEBUG, tag, "span.enter" as *u8)
94 sys_write(ctx.log.out_fd, " id=" as *u8, 4)
95 nx_log_puti(ctx.log.out_fd, id)
96 sys_write(ctx.log.out_fd, " parent=" as *u8, 8)
97 nx_log_puti(ctx.log.out_fd, parent)
98 sys_write(ctx.log.out_fd, " t=" as *u8, 3)
99 nx_log_puti(ctx.log.out_fd, ctx.tick)
100 sys_write(ctx.log.out_fd, "\n" as *u8, 1)
101 ctx.tick = ctx.tick + 1
102
103 return id
104}
105
106// Exit the named span id. Pops the stack if id matches top.
107// Emits a span.exit event with elapsed-tick delta.
108func nx_span_exit(ctx: *NxTraceCtx, tag: *u8, id: i64) -> i64 {
109 // Pop if id matches top. Out-of-order exit is tolerated (we
110 // just don't update the stack) so mismatched enter/exit
111 // don't corrupt the nesting, but the log reader will see it.
112 if ctx.stack_depth > 0 {
113 if ctx.stack[ctx.stack_depth - 1] == id {
114 ctx.stack_depth = ctx.stack_depth - 1
115 }
116 }
117
118 ctx.tick = ctx.tick + 1
119 nx_log_emit(ctx.log, NX_LOG_DEBUG, tag, "span.exit" as *u8)
120 sys_write(ctx.log.out_fd, " id=" as *u8, 4)
121 nx_log_puti(ctx.log.out_fd, id)
122 sys_write(ctx.log.out_fd, " t=" as *u8, 3)
123 nx_log_puti(ctx.log.out_fd, ctx.tick)
124 sys_write(ctx.log.out_fd, "\n" as *u8, 1)
125
126 return 0
127}
128
129// --- self-test ------------------------------------------------------
130
131func main() -> i64 {
132 let log: *NxLogContext = nx_log_new(NX_LOG_DEBUG, 2)
133 let ctx: *NxTraceCtx = nx_trace_new(log)
134
135 // Simulate a call tree:
136 // main
137 // parse_module
138 // parse_function
139 // parse_expr
140 // parse_function
141 // codegen
142 let s_main: i64 = nx_span_enter(ctx, "main" as *u8)
143 let s_parse: i64 = nx_span_enter(ctx, "parse_module" as *u8)
144 let s_fn1: i64 = nx_span_enter(ctx, "parse_function" as *u8)
145 let s_expr: i64 = nx_span_enter(ctx, "parse_expr" as *u8)
146 nx_span_exit(ctx, "parse_expr" as *u8, s_expr)
147 nx_span_exit(ctx, "parse_function" as *u8, s_fn1)
148 let s_fn2: i64 = nx_span_enter(ctx, "parse_function" as *u8)
149 nx_span_exit(ctx, "parse_function" as *u8, s_fn2)
150 nx_span_exit(ctx, "parse_module" as *u8, s_parse)
151 let s_cg: i64 = nx_span_enter(ctx, "codegen" as *u8)
152 nx_span_exit(ctx, "codegen" as *u8, s_cg)
153 nx_span_exit(ctx, "main" as *u8, s_main)
154
155 // Verify span IDs are monotonic.
156 if s_main != 1 { return __syscall(93, 10, 0, 0, 0, 0, 0) }
157 if s_parse != 2 { return __syscall(93, 11, 0, 0, 0, 0, 0) }
158 if s_fn1 != 3 { return __syscall(93, 12, 0, 0, 0, 0, 0) }
159 if s_expr != 4 { return __syscall(93, 13, 0, 0, 0, 0, 0) }
160 if s_fn2 != 5 { return __syscall(93, 14, 0, 0, 0, 0, 0) }
161 if s_cg != 6 { return __syscall(93, 15, 0, 0, 0, 0, 0) }
162
163 // Stack should be empty after all exits.
164 if ctx.stack_depth != 0 { return __syscall(93, 20, 0, 0, 0, 0, 0) }
165
166 // Tick monotonic: 12 events (6 enter + 6 exit).
167 if ctx.tick != 12 { return __syscall(93, 30, 0, 0, 0, 0, 0) }
168
169 return 0
170}