nx_regprof_test.nx source
↩ module page · 143 lines · 6020 B
1// nx_regprof_test.nx -- DECOMPOSE the reg_put cost. A profiler, not a gate.
2//
3// WHY: debt 1785519597 records "reg_put costs ~678ms per append vs reg_get ~70us". That number is REAL
4// (measured on this host) but it is an AGGREGATE, and an aggregate names no fix. Whoever owns seg_store
5// needs to know WHERE the 678ms goes, and the source offers two very different candidate explanations:
6//
7// (a) THE PLANE LOCK, added 2026-07-31. reg_put now takes <prefix>plock via sts_lock. If another
8// writer family holds it, every put pays contention -- and the fix is scheduling, not storage.
9// (b) THE FULL-INDEX-PER-SEGMENT SHAPE. Per the source: "every reg segment carries the FULL index",
10// so ss_get walks every segment and each put copies the whole index forward. The fix there is
11// the store layout, and it gets worse with every row.
12//
13// Those imply OPPOSITE work. u2605AN AGGREGATE THAT CANNOT DISTINGUISH TWO OPPOSITE FIXES IS NOT YET A
14// MEASUREMENT -- it is a symptom. This probe separates them by timing the phases independently against
15// a FRESH prefix (so segment count starts at zero) and reporting per-op microseconds for each.
16//
17// It also measures GROWTH: the same put timed at row 1 and at row 20. If cost is flat, the lock or a
18// per-commit fsync dominates and (a) is the story. If cost climbs with row count, the full-index copy
19// dominates and (b) is the story. u2605THE SLOPE, NOT THE MAGNITUDE, IS THE DISCRIMINATOR.
20//
21// Reports only. Kills nothing, changes nothing, writes only to its own nonce-scoped prefix.
22// license_tier: ORIGINAL No hw writes (Rule 26). expect_exit: 0
23
24import "nx_registry.nx"
25import "nx_store_seed_lib.nx"
26import "nx_gate_verdict.nx"
27
28
29
30func rp_cat(dst: *u8, off: i64, s: *u8) -> i64 { var i: i64 = 0; while s[i] != (0 as u8) { dst[off+i] = s[i]; i = i + 1 } return off + i }
31func rp_catn(dst: *u8, off: i64, v: i64) -> i64 {
32 var m: i64 = v
33 var o: i64 = off
34 if m == 0 { dst[o] = 48 as u8; return o + 1 }
35 let t: *u8 = sys_mmap(24)
36 var k: i64 = 0
37 while m > 0 { t[k] = (48 + (m % 10)) as u8; m = m / 10; k = k + 1 }
38 var i: i64 = 0
39 while i < k { dst[o+i] = t[k-1-i]; i = i + 1 }
40 return o + k
41}
42
43func main(argc: i64, argv: *i64) -> i64 {
44 let nonce: i64 = sys_now_us()
45 let pfx: *u8 = sys_mmap(256)
46 var o: i64 = rp_cat(pfx, 0, "knowledge/store/regprof" as *u8)
47 o = rp_catn(pfx, o, nonce)
48 pfx[o] = 45 as u8
49 o = o + 1
50 pfx[o] = 0 as u8
51
52 let ctr: *i64 = gv_ctr()
53 gv_head("NX-REGPROF (decomposing reg_put; fresh prefix, segments start at zero)" as *u8)
54
55 // ---- phase 1: the PLANE LOCK alone ----
56 let l0: i64 = sys_now_us()
57 var i: i64 = 0
58 while i < 10 {
59 let lk: i64 = sts_lock(pfx)
60 sts_unlock(lk)
61 i = i + 1
62 }
63 let l1: i64 = sys_now_us()
64 gv_puts(" lock_cycle_us_per_op=" as *u8); gv_num((l1 - l0) / 10); gv_puts("\n" as *u8)
65
66 // ---- phase 2: ss_get on an ABSENT key (read path, no segments yet) ----
67 let po: *i64 = sys_mmap(16) as *i64
68 let lo: *i64 = sys_mmap(16) as *i64
69 let g0: i64 = sys_now_us()
70 var j: i64 = 0
71 while j < 10 {
72 ss_get(pfx, "rp:absent" as *u8, po, lo)
73 j = j + 1
74 }
75 let g1: i64 = sys_now_us()
76 gv_puts(" ss_get_absent_us_per_op=" as *u8); gv_num((g1 - g0) / 10); gv_puts("\n" as *u8)
77
78 // ---- phase 3: reg_put at row 1..5 (EARLY, few segments) ----
79 let rec: *u8 = sys_mmap(64)
80 rp_cat(rec, 0, "x" as *u8)
81 rec[1] = 0 as u8
82 let idb: *u8 = sys_mmap(64)
83 let e0: i64 = sys_now_us()
84 var a: i64 = 0
85 while a < 5 {
86 var q: i64 = rp_cat(idb, 0, "id" as *u8)
87 q = rp_catn(idb, q, a)
88 idb[q] = 0 as u8
89 reg_put(pfx, "rp:" as *u8, "rp:__idx__" as *u8, idb, rec, 1)
90 a = a + 1
91 }
92 let e1: i64 = sys_now_us()
93 let early: i64 = (e1 - e0) / 5
94 gv_puts(" reg_put_EARLY_us_per_op=" as *u8); gv_num(early); gv_puts("\n" as *u8)
95
96 // ---- phase 4: reg_put at row 16..20 (LATE, index now carries 15+ ids) ----
97 var b: i64 = 5
98 while b < 15 {
99 var q2: i64 = rp_cat(idb, 0, "id" as *u8)
100 q2 = rp_catn(idb, q2, b)
101 idb[q2] = 0 as u8
102 reg_put(pfx, "rp:" as *u8, "rp:__idx__" as *u8, idb, rec, 1)
103 b = b + 1
104 }
105 let f0: i64 = sys_now_us()
106 var c: i64 = 15
107 while c < 20 {
108 var q3: i64 = rp_cat(idb, 0, "id" as *u8)
109 q3 = rp_catn(idb, q3, c)
110 idb[q3] = 0 as u8
111 reg_put(pfx, "rp:" as *u8, "rp:__idx__" as *u8, idb, rec, 1)
112 c = c + 1
113 }
114 let f1: i64 = sys_now_us()
115 let late: i64 = (f1 - f0) / 5
116 gv_puts(" reg_put_LATE_us_per_op=" as *u8); gv_num(late); gv_puts("\n" as *u8)
117
118 // ---- phase 5: ss_get with 20 segments present (read path under growth) ----
119 let h0: i64 = sys_now_us()
120 var k2: i64 = 0
121 while k2 < 10 {
122 ss_get(pfx, "rp:id3" as *u8, po, lo)
123 k2 = k2 + 1
124 }
125 let h1: i64 = sys_now_us()
126 gv_puts(" ss_get_20seg_us_per_op=" as *u8); gv_num((h1 - h0) / 10); gv_puts("\n" as *u8)
127
128 // ---- u2605THE DISCRIMINATOR ----
129 gv_puts(" growth_late_minus_early_us=" as *u8); gv_num(late - early); gv_puts("\n" as *u8)
130 if early > 0 {
131 gv_puts(" growth_permille_of_early=" as *u8); gv_num(((late - early) * 1000) / early); gv_puts("\n" as *u8)
132 }
133 gv_puts("HINT flat cost => plane lock or per-commit fsync dominates (scheduling fix)
134" as *u8)
135 gv_puts("HINT rising cost => full-index-per-segment copy dominates (store-layout fix)
136" as *u8)
137 gv_check("P1 lock cycle was measured" as *u8, (l1 - l0) >= 0, ctr)
138 gv_check("P2 reg_put EARLY was timed" as *u8, early >= 0, ctr)
139 gv_check("P3 reg_put LATE was timed" as *u8, late >= 0, ctr)
140 gv_check("P4 twenty rows written without error" as *u8, c == 20, ctr)
141 gv_check("P5 an absent-key read is not costlier than a write" as *u8, ((g1 - g0) / 10) <= early, ctr)
142 return gv_verdict("REGPROF" as *u8, ctr, "reg_put decomposed: lock vs read vs write, early vs late" as *u8)
143}