perf(experiment): measure native analysis phase costs

[AUTOMATED] Add a gated diagnostic overlay and production-owner profiling runner. Preserve actual phase/resource results, disabled-output control and lossless full-graph encoding feasibility without claiming a public codec or model speedup.

Co-authored-by: gensokyo-dev <342580529+gensokyo-dev@users.noreply.github.com>
Co-authored-by: Kaoru0822 <208281322+kaoru0822-kitauji@users.noreply.github.com>
This commit is contained in:
committed 2026-10-16 12:41:35 +00:00
1 parent 4986b8644f
commit 7d0da075e7
6 files changed
+499 -7

No files matched your search

+8
View File
@@ -272,3 +272,11 @@ Code Mode. All four wide-operand answers pass, with no retry or OOM. Costs remai
mixed. A selected-slot read still incurs whole-function native decompilation on
a fresh lease; phase profiling is the next computation question, separate from
the now finer fact/query boundary.
The [native phase study](native-compute-study.md) now measures the VM drive at
about 34 seconds, C rendering at 0.22 seconds and projection at 0.03 seconds.
Repeated new native processes do not gain the API owner's warm result reuse.
It also demonstrates offline lossless encoding of all VM facts below the existing
transport budget; native codec/decoder bounds and model verification remain
pending. This may close full-graph/definition coverage without another analysis
or a live-function lifecycle, but is not yet a callable capability.
@@ -0,0 +1,86 @@
--- a/decompiler/crates/kuna-console/src/project.rs
+++ b/decompiler/crates/kuna-console/src/project.rs
@@ -693,6 +693,17 @@
flow_ovr.extend(seed.flow_overrides.iter().cloned());
let replay = crate::assertions::has_symbol_scoped(prog, &name, single_target);
prog.arch_mut().kuna_record_names = replay;
+ let mut profile_clock = (want_atomic_facts
+ && std::env::var_os("KUNA_EXPERIMENT_ATOMIC_TIMING").as_deref()
+ == Some(std::ffi::OsStr::new("1")))
+ .then(std::time::Instant::now);
+ let mut profile_phase = |phase: &str| {
+ if let Some(clock) = profile_clock.as_mut() {
+ let now = std::time::Instant::now();
+ eprintln!("{{\"kind\":\"rea_atomic_phase\",\"address\":\"0x{byte_address:x}\",\"phase\":\"{phase}\",\"wall_ns\":{}}}", now.duration_since(*clock).as_nanos());
+ *clock = std::time::Instant::now();
+ }
+ };
let step = crate::decompile_step::decompile_one(
prog.arch_mut(),
&name,
@@ -751,6 +762,7 @@
}
other => other,
};
+ profile_phase("decompile_drive");
match result {
Ok(mut fd) => {
// (kuna `--assert`) The flow overrides the follower REFUSED are only
@@ -813,6 +825,7 @@
kuna_decomp::kuna_elemptr::record(prog.arch_mut(), &fd);
prog.arch_mut().print_mut().set_record_pointer_arguments(want_pointer_arguments);
let rendered = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| {
+ profile_phase("pre_render_metadata");
// Trim the surrounding newlines the same way `kuna decompile`
// does (`decompile.rs::trim_newlines`), so the per-function
// `code` is byte-identical to the single-shot path.
@@ -826,6 +839,7 @@
};
let pointerargs = prog.arch_mut().print_mut().take_pointer_arguments(&untrimmed);
let code = untrimmed.trim_matches('\n').to_string();
+ profile_phase("render_c");
let globals = kuna_decomp::decompile_drive::extract_global_objects(prog.arch());
let field_calls = kuna_decomp::kuna_calltargettype::field_declarations(prog.arch(), &fd);
let mut variables =
@@ -848,15 +862,20 @@
prog, &fd, &var_refs, &raw_tokens, &untrimmed, &code, &variables,
))
});
+ profile_phase("metadata_extract");
if want_atomic_facts {
let detail = detail.get_or_insert_with(Default::default);
let membership = kuna_decomp::atomic_membership::inspect(&fd);
+ profile_phase("membership");
detail.atomic_calls = Some(membership.as_ref().map_err(Clone::clone)
.and_then(|m| kuna_decomp::atomic_calls::collect_all(&fd, m)));
+ profile_phase("calls");
detail.atomic_facts = Some(membership.as_ref().map_err(Clone::clone)
.and_then(|m| kuna_decomp::atomic_facts::collect(prog.arch(), &fd, m)));
+ profile_phase("full_graph");
detail.atomic_projection = Some(membership.as_ref().map_err(Clone::clone)
.and_then(|m| kuna_decomp::atomic_projection::collect(prog.arch(), &fd, m)));
+ profile_phase("projection");
}
for variable in &mut variables {
for address in &mut variable.addresses {
@@ -881,6 +900,7 @@
.as_ref()
.map(|ctx| ctx.scan(&fd, byte_address))
.unwrap_or_default();
+ profile_phase("metadata_tail");
(code, variables, types, (globals, field_calls), proto, line_mappings, callee_hints, detail, pointerargs, stack_objects)
}));
match rendered {
--- a/docs/spec/00-overview.md
+++ b/docs/spec/00-overview.md
@@ -3496,3 +3496,10 @@
runtime reachability. Collection uses the same live function after C rendering;
no second decompilation is performed. Complete source Evidence keeps the native
frontier while callers may select a compact summary and individual facts.
+
+An experiment-only timing overlay recognizes `KUNA_EXPERIMENT_ATOMIC_TIMING=1`
+only with atomic capture enabled. It records sequential per-function wall times
+to stderr for the decompile drive, pre-render metadata, C rendering, metadata
+extraction, membership, calls, full graph, projection and metadata tail. It does
+not change analysis parameters or JSON facts. Loading, setup and final JSON
+encoding are outside these phase intervals; phase CPU costs are not measured.
@@ -0,0 +1,70 @@
"""Lossless encoding feasibility on retained native JSON; no provider implementation."""
import argparse
import base64
import gzip
import hashlib
import json
from pathlib import Path
import time
def measure(source, output):
with source.open('rb') as stream:
raw = stream.read(32 * 1024 * 1024 + 1)
if len(raw) > 32 * 1024 * 1024:
raise ValueError('Input exceeds the diagnostic 32 MiB source bound')
document = json.loads(raw)
if len(document['functions']) != 1:
raise ValueError('Select one retained native function')
function = document['functions'][0]
graph = function['atomic_facts']
graph_json = json.dumps(graph, separators=(',', ':'), ensure_ascii=False).encode()
wall, cpu = time.perf_counter(), time.process_time()
compressed = gzip.compress(graph_json, compresslevel=1, mtime=0)
base64_data = base64.b64encode(compressed)
encode_cost = {'wall_ms': (time.perf_counter() - wall) * 1000,
'cpu_ms': (time.process_time() - cpu) * 1000}
wall, cpu = time.perf_counter(), time.process_time()
restored = gzip.decompress(base64.b64decode(base64_data, validate=True))
if restored != graph_json:
raise ValueError('Lossless byte roundtrip failed')
decode_cost = {'wall_ms': (time.perf_counter() - wall) * 1000,
'cpu_ms': (time.process_time() - cpu) * 1000}
results = {}
for name, data in [('gzip-base64', base64_data.decode()),
('gzip-hex', compressed.hex())]:
function['atomic_facts'] = {
'schema_version': 4, 'encoding': name,
'raw_bytes': len(graph_json), 'data': data,
}
results[name] = len(json.dumps(document, separators=(',', ':'),
ensure_ascii=False).encode())
report = {
'source': str(source), 'source_sha256': hashlib.sha256(raw).hexdigest(),
'original_document_bytes': len(raw), 'graph_json_bytes': len(graph_json),
'graph_statement_bytes': sum(len(op['statement'].encode()) for op in graph['operations']),
'graph_operations': len(graph['operations']),
'graph_values': len(graph['values']), 'graph_blocks': len(graph['blocks']),
'gzip_level': 1, 'gzip_bytes': len(compressed),
'candidate_document_bytes': results,
'public_transport_budget_bytes': 8 * 1024 * 1024,
'lossless_graph_byte_roundtrip': True,
'python_gzip_and_base64_encoding': encode_cost,
'python_base64_and_gzip_decoding': decode_cost,
'scope': 'Offline retained-source format feasibility, not a native/provider/model '
'implementation. Timings are Python only, not Rust/Node or agent savings. '
'Whole-run CPU/peak family memory are separate resource-run receipts.',
}
with output.open('x') as stream:
json.dump(report, stream, indent=2)
stream.write('\n')
print(json.dumps(report))
if __name__ == '__main__':
parser = argparse.ArgumentParser(description=__doc__)
parser.add_argument('source', type=Path)
parser.add_argument('output', type=Path)
args = parser.parse_args()
measure(args.source, args.output)
@@ -0,0 +1,118 @@
# Native computation and retained fact coverage
This diagnostic separates native computation from fact selection and Code Mode
dispatch after the wide-operand model pairs. It does not change those adapters
or establish model-token savings.
## Phase instrument and actual measurements
Apply `kuna-native-ir.patch`, then `kuna-atomic-timing-diagnostic.patch`, to Kuna
`fe01d6294eb0d1053ce343c8943646df88e143fc`. Reuse existing compiled specs and the
one-job opt-level-1 embed-specs build in `native-engine.md`. Preserved engine:
`c755184455b8fe8950a5194788d954bc0476602779b6dd614cb893a230f6fde7`;
overlay: `b2ddfd5b6d3fc4a386cfbb07d97fbd0fcbfd8279837ce68327e62baa3e0f3018`.
The preceding `a0685486...` public executable remains independently preserved.
The instrument requires `--atomic-facts` and the exact environment value
`KUNA_EXPERIMENT_ATOMIC_TIMING=1`. It emits nine sequential per-function wall
intervals to stderr, excluding logging time from the next interval. Disabled
instrumentation emits none. Analysis parameters and JSON facts are unchanged.
These are phase wall times, not phase CPU. Loading, preparation before the drive
and final output encoding are outside the intervals; the residual cannot all be
attributed to one phase.
`profile-native.mjs` uses production target/installation/process owners and a
private runtime/cache root. Its diagnostic launcher adds only the timing flag;
ambient environment is not persisted. It measures two new native processes:
fresh private cache, then the same cache/staged input. This second process is
distinct from the API owner's warm result-cache hit. Complete stdout/stderr and
digests are retained before validation. OS cache remains uncontrolled.
```sh
python3 experiments/analysis-efficiency/resource-run.py --observe-payload-exit -- \
node experiments/atomic-codemode/profile-native.mjs \
/absolute/diagnostic-kuna /usr/lib/x86_64-linux-gnu/libsqlite3.so.0 \
0xea6d0 /absolute/new-profile.json /absolute/prior-public-capture.json
```
Add `--without-timing` for the disabled control. Target: SQLite Debian
`3.40.1-2+deb12u2` amd64, SHA-256
`2e6eef9a727f081f0d453b4e5e6cbd8b9ef8b6f86cbf7681cbad444d3b0b55c8`.
VM entry is `0xea6d0`; parser-helper entry is `0x64060`.
| Wall milliseconds | VM fresh | VM same cache/new process | Helper fresh | Helper same cache/new process |
| --------------------- | ---------: | ------------------------: | -----------: | ----------------------------: |
| Entire owned request | 36,336.306 | 36,353.240 | 2,339.393 | 2,193.311 |
| Decompile drive | 33,681.369 | 33,855.870 | 256.200 | 266.629 |
| C rendering | 220.052 | 215.235 | 9.399 | 7.416 |
| Metadata extraction | 64.434 | 128.247 | 1.576 | 1.564 |
| Membership scan | 3.259 | 3.496 | 0.137 | 0.093 |
| Call facts | 2.889 | 3.328 | 0.245 | 0.133 |
| Full graph collection | 0.006* | 0.007* | 6.993 | 5.473 |
| Projection collection | 31.383 | 31.711 | 1.955 | 1.770 |
Pre-render/tail metadata also appear in the nine-interval raw receipts. `*` VM
full-graph collection fails its early operation-capacity check; these numbers
do not time a complete graph export. Whole-function analysis nevertheless
produces the live IR. Each function record deeply equals its prior public golden
and its repeat. The disabled helper control also agrees, with zero timing rows.
| Whole-run resource scope | Family wall seconds | CPU seconds | Kernel peak MiB |
| ------------------------------------- | ------------------: | ----------: | --------------: |
| Instrument build | 115.279 | 92.082 | 760.7 |
| VM, two processes plus validation | 74.218 | 73.867 | 572.2 |
| Helper, two processes plus validation | 5.554 | 5.328 | 191.9 |
| Disabled helper, two processes | 5.556 | 5.409 | 191.8 |
| Final cached build | 0.322 | 0.155 | 26.8 |
All use one CPU, 4 GiB hard / 3 GiB early-stop bounds, verified cleanup and OOM 0.
Kernel peak includes charged file cache, not RSS. Final build keeps the same
digest. Patch forward/reverse and lenient `check-spec` pass; full native corpus,
stages and workspace gates remain unexecuted. No upstream commit/PR or integration
readiness is claimed. Receipts/raw sources are local
`phase-timing-{vm,helper,helper-off}.json*` and resource logs under
`.cache/atomic-codemode/`.
C rendering is below 1% of this VM request; skipping it cannot remove the
approximately 34-second drive. The helper instead spends most time outside the
instrumented phases, requiring further profiling before choosing persistent
state. Same-cache new processes reanalyze. Previously measured same-lease API
source reuse remains a separate approximately 40 ms path.
## Lossless full-graph encoding feasibility
The earlier diagnostic source has 21,349 operations, 35,755 values and 1,229
blocks, with no omitted definition IDs. Its whole document is 17,801,972 bytes;
the graph is 17,008,223 bytes, including 2,255,616 bytes of operation display and
90,013 bytes of value type names. Plain tuple packing was still too large.
```sh
python3 experiments/analysis-efficiency/resource-run.py --observe-payload-exit -- \
python3 experiments/atomic-codemode/measure-native-encoding.py \
/absolute/diagnostic-native.json /absolute/new-encoding-report.json
```
Gzip level 1 makes the graph 2,020,464 bytes. Hypothetical documents retaining
ordinary C/metadata/calls and replacing only the graph with a typed envelope are:
| Encoding | Entire JSON bytes | Existing transport budget |
| ------------- | ----------------: | ------------------------: |
| gzip + base64 | 3,487,776 | 8,388,608 |
| gzip + hex | 4,834,749 | 8,388,608 |
The graph byte roundtrip is exact. Python gzip/base64 encode costs 69.037 ms
wall / 69.037 ms CPU; decode 34.632 / 34.571 ms. Whole sizing task: 0.826 wall /
0.654 CPU seconds, 169.8 MiB peak, cleanup verified and OOM 0. These are offline
Python feasibility measurements, not Rust/Node timings, native output, public
support or agent savings. Source SHA-256:
`0a31513350be440983094710197b155a2ec8c49d28852bb20a524292091637b7`;
reproducible receipt: `full-graph-encoding-repro.json` beside its resource log.
This supports testing bounded lossless transport before introducing live-function
ownership or repeating analysis for missing definitions. Required checks include
allocation/encoding growth, bounded inflation, exact format/length/row admission,
malformed-graph isolation from calls/C, complete Evidence access, actual CPU and
memory, fallback behavior and real-model workflows. The shared owner must return
selected facts rather than send an encoded graph to the agent. The current
public engine still has a bounded call-rooted projection, without a complete VM
CFG or arbitrary expansion of unretained definitions.
+9 -7
View File
@@ -665,10 +665,12 @@ arbitrary definitions outside the retained call-rooted projection cannot be
expanded by a fact read. Provider parity and general complex-software superiority
remain unestablished.
Pipeline, C rendering, metadata and fact-export phase costs have not been
separately profiled. Their source order and C size do not prove which dominates
runtime. A phase-timing experiment is needed before choosing compute/cache
changes; suppressing C or retaining a live function must preserve explicit
capability/lifetime and Evidence semantics. Current model comparisons share the
same computation and fact owners, avoiding a capability difference between the
two adapters.
At that checkpoint, pipeline/render/metadata/export costs were not separately
profiled. The [subsequent native computation study](native-compute-study.md) now
measures them: VM drive about 34 seconds, C rendering 0.22 seconds and projection
0.03 seconds. Skipping C is a small opportunity for this workload. An offline
lossless encoding probe also puts the earlier full 17.8 MB diagnostic record
inside the unchanged 8 MiB transport. That codec is not implemented in the public
engine; allocation/inflation bounds, shared decoding, Evidence and real-model
behavior still need testing. Current model comparisons share the same
computation/fact owners, avoiding a capability difference between adapters.
@@ -0,0 +1,208 @@
// Diagnostic native timings, using REA's target, environment and process owners.
import assert from "node:assert/strict";
import { createHash } from "node:crypto";
import { readFile, writeFile } from "node:fs/promises";
import { join } from "node:path";
import { parseArgs } from "node:util";
import { parseBinaryTarget } from "../../dist/application/BinaryTargetResolver.js";
import { inspectKunaInstallation } from "../../dist/kuna/KunaInstallation.js";
import { KunaTargetCommands } from "../../dist/kuna/KunaTargetCommands.js";
import { PrivateRuntimeRoot } from "../../dist/process/PrivateRuntimeRoot.js";
import { spawnOwnedProviderProcess } from "../../dist/process/ProviderProcess.js";
import { requireResult } from "./fact-error.mjs";
import { parseNativeIR } from "./native-ir.mjs";
import {
createVerifierRun,
completeVerifierRun,
assertVerifierCleanupComplete,
} from "../../scripts/lib/verifier-run.mjs";
const { values: options, positionals } = parseArgs({
allowPositionals: true,
options: { "without-timing": { type: "boolean", default: false } },
});
const [engine, binary, entry, output, goldenPath] = positionals;
const timingEnabled = !options["without-timing"];
assert.ok(engine && binary && entry && output);
const sha = (s) => createHash("sha256").update(s).digest("hex");
const expectedPhases = [
"decompile_drive",
"pre_render_metadata",
"render_c",
"metadata_extract",
"membership",
"calls",
"full_graph",
"projection",
"metadata_tail",
];
const verifier = createVerifierRun(),
runs = [],
failures = [];
const root = await PrivateRuntimeRoot.create({ prefix: "rea-atomic-profile-" });
let commands, installation, target;
try {
target = requireResult(await parseBinaryTarget(binary));
installation = requireResult(
await inspectKunaInstallation({
...process.env,
REA_KUNA_COMMAND: engine,
REA_KUNA_CACHE_DIR: join(root.path, "engine-cache"),
}),
);
commands = new KunaTargetCommands(target, {
signal: new AbortController().signal,
launcher: (options) =>
spawnOwnedProviderProcess({
...options,
env: {
...options.env,
...(timingEnabled ? { KUNA_EXPERIMENT_ATOMIC_TIMING: "1" } : {}),
},
}),
});
let firstFunction;
for (const phase of [
"fresh-private-native-cache",
"same-private-native-cache-new-process",
]) {
const before = performance.now();
const captured = requireResult(
await commands.run({
installation,
operation: "experiment:atomic-phase-profile",
arguments: (input) => [
"decompile",
input,
entry,
"--addr",
"--json",
"--atomic-facts",
"--atomic-output-bytes",
"8388608",
"--max-fn-memory",
"1024",
],
outputBytes: 8 * 1024 * 1024,
timeoutMs: 120000,
signal: new AbortController().signal,
}),
);
const wallMs = performance.now() - before;
const stdout = captured.stdout.text,
stderr = captured.stderr.text;
const stdoutPath = `${output}.run-${runs.length}.stdout.json`,
stderrPath = `${output}.run-${runs.length}.stderr.jsonl`;
await writeFile(stdoutPath, stdout, { flag: "wx" });
await writeFile(stderrPath, stderr, { flag: "wx" });
const record = {
phase,
wall_ms: wallMs,
status: "unverified",
source: {
stdout_path: stdoutPath,
stdout_sha256: sha(stdout),
stdout_bytes: Buffer.byteLength(stdout),
stderr_path: stderrPath,
stderr_sha256: sha(stderr),
},
};
runs.push(record);
assert.notEqual(captured.diagnosticTruncated, true);
const timings = stderr
.split("\n")
.filter((line) => line.startsWith('{"kind":"rea_atomic_phase",'))
.map((line) => JSON.parse(line));
assert.deepEqual(
timings.map((row) => row.phase),
timingEnabled ? expectedPhases : [],
);
assert.ok(
timings.every(
(row) =>
row.address === entry &&
Number.isSafeInteger(row.wall_ns) &&
row.wall_ns >= 0,
),
);
const model = parseNativeIR(stdout, entry, captured.input);
const functionRecord = JSON.parse(stdout).functions[0];
if (firstFunction) assert.deepEqual(functionRecord, firstFunction);
firstFunction ??= functionRecord;
if (goldenPath)
assert.deepEqual(
functionRecord,
JSON.parse(await readFile(goldenPath, "utf8")).functions[0],
);
const accountedMs = timingEnabled
? timings.reduce((n, row) => n + row.wall_ns / 1e6, 0)
: null;
if (accountedMs !== null) assert.ok(accountedMs <= wallMs);
Object.assign(record, {
status: "verified",
accounted_wall_ms: accountedMs,
unprofiled_wall_ms: accountedMs === null ? null : wallMs - accountedMs,
timings,
code_bytes: Buffer.byteLength(functionRecord.code),
facets: model.facets,
function_record_matches_prior_run: runs.length > 1,
function_record_matches_golden: goldenPath ? true : null,
});
}
} catch (error) {
failures.push({
code: error.code ?? "verification_failed",
message: error.message,
details: error.details ?? {},
stack: error.stack,
});
} finally {
let closed = true;
if (commands) {
const result = await commands.close();
closed = result.ok;
if (!closed)
failures.push({
code: result.error.code,
message: result.error.message,
details: result.error.details,
});
}
if (closed) {
try {
await root.close();
} catch (error) {
failures.push({
code: "cleanup_incomplete",
message: error.message,
resources: [root.path],
});
}
}
}
const lifecycle = await completeVerifierRun(verifier);
assertVerifierCleanupComplete(lifecycle.process_lineage);
await writeFile(
output,
JSON.stringify(
{
engine: installation && {
path: installation.executable,
sha256: installation.sha256,
},
target: target && { path: target.path, sha256: target.sha256 },
entry,
timing_enabled: timingEnabled,
runs,
failures,
lifecycle,
scope:
"Diagnostic native processes through production owners with an explicit timing-only launcher environment. Phase walls only, not phase CPU. Whole-run CPU/peak memory are separate resource-run receipts; OS cache uncontrolled. Not a model or public MCP measurement.",
},
null,
2,
),
{ flag: "wx" },
);
console.log(JSON.stringify({ output, runs: runs.length, failures }));
if (failures.length) process.exitCode = 1;