Skip to content

Commit 73a63a9

Browse files
committed
Add leveled logging that costs nothing until it is switched on
Instrumenting a function with a print means paying for the message on every call, forever, so the instrumentation gets deleted instead of left in place. This is the usual answer: a level, off by default, and a payload that is not built while the level is off. `(pragma! log-level <off|error|warn|info|debug|trace>)` sets the enabled severity. `(log! <level> <payload>)` emits `(Log <level> <value>)` through println! when the level admits it, and returns unit when it does not. `(log-enabled? <level>)` answers the same question for a caller that wants its own sink, recording events as atoms in a space rather than printing them. Two things make the off path cheap. The level is a field on the world, so log-enabled? is an interpreter form reading it rather than a match against a space. And log!'s payload is declared Atom, so if's unevaluated branches leave it alone: the expression that would build the message is never reduced. The lazy argument is what the log crate gets from a closure and Log4j2 from a lambda; MeTTa's parameter types give it directly. Measured on a 200-iteration loop with tabling off, the off path is flat across a hundredfold change in payload cost, 68.6 ms at (work 10) and 68.7 ms at (work 1000), while the same loop with the level set scales with it, 145 ms to 4765 ms. The same guard written in MeTTa over a space is flat too but costs about 40% more per call, which is what the world field buys. The test states it without timing: the payload of an unadmitted call is a function with no base case, so anything that reduced it would hang rather than fail. log-enabled? returns a grounded Bool, not a `False` symbol, which is what lets it drive `if` directly.
1 parent 970bc28 commit 73a63a9

3 files changed

Lines changed: 191 additions & 1 deletion

File tree

packages/core/src/eval.ts

Lines changed: 49 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@ import {
1616
type ExprAtom,
1717
emptyExpr,
1818
expr,
19+
gbool,
1920
gint,
2021
gstr,
2122
type InternTable,
@@ -406,6 +407,9 @@ const EMBEDDED = new Set([
406407
"import!",
407408
// Sets interpreter settings in-language (Hyperon `pragma!`); stateful, so handled here not as a pure op.
408409
"pragma!",
410+
// Reads the level set by `(pragma! log-level ...)`. Handled here, not as a pure grounded op, because the
411+
// level lives on the world; `log!` itself is a standard-library definition over this predicate.
412+
"log-enabled?",
409413
// TS-native extension (not upstream MeTTa): atomic space mutation with rollback.
410414
"transaction",
411415
// TS-native concurrency primitives (async-only); see docs/.../concurrency-primitives.md.
@@ -1619,6 +1623,20 @@ function namedSpaceCandidateGetter(
16191623
};
16201624
}
16211625

1626+
// ---------- log levels ----------
1627+
// Ranked by severity, so a setting admits every level at or below its own rank. `off` is 0 and admits
1628+
// nothing, which is the default: severity ranks start at 1 so a plain `rank <= world.logLevel` comparison
1629+
// rejects everything while logging is off, with no separate "is it enabled" branch.
1630+
const LOG_OFF = 0;
1631+
const LOG_RANKS: ReadonlyMap<string, number> = new Map([
1632+
["off", LOG_OFF],
1633+
["error", 1],
1634+
["warn", 2],
1635+
["info", 3],
1636+
["debug", 4],
1637+
["trace", 5],
1638+
]);
1639+
16221640
export interface World {
16231641
spaces: Map<string, NamedSpace>;
16241642
store: Map<number, Atom>;
@@ -1654,6 +1672,11 @@ export interface World {
16541672
// the fresh-variable namespace.
16551673
maxSteps: number;
16561674
stepStart: number;
1675+
// Enabled logging severity as a rank, set in-language by `(pragma! log-level <level>)`. LOG_OFF is the
1676+
// default, so a program that never sets it logs nothing and every `log!` returns unit without touching its
1677+
// payload. Held on the world, not in a space, so the check `log!` makes is a field read rather than a
1678+
// match: that is what keeps an unconfigured log call off the cost of the program it instruments.
1679+
logLevel: number;
16571680
}
16581681
export interface St {
16591682
counter: number;
@@ -1688,6 +1711,7 @@ export const initSt = (): St => ({
16881711
removedStaticVarRules: false,
16891712
maxStackDepth: DEFAULT_MAX_STACK_DEPTH,
16901713
maxSteps: DEFAULT_MAX_STEPS,
1714+
logLevel: LOG_OFF,
16911715
stepStart: 0,
16921716
},
16931717
});
@@ -1708,6 +1732,7 @@ function cloneWorld(w: World): World {
17081732
maxStackDepth: w.maxStackDepth,
17091733
maxSteps: w.maxSteps,
17101734
stepStart: w.stepStart,
1735+
logLevel: w.logLevel,
17111736
};
17121737
}
17131738

@@ -1783,6 +1808,7 @@ function mergeWorlds(base: World, branches: readonly World[]): World {
17831808
maxStackDepth: base.maxStackDepth,
17841809
maxSteps: base.maxSteps,
17851810
stepStart: base.stepStart,
1811+
logLevel: base.logLevel,
17861812
};
17871813
indexSelfRules(merged, selfExtra);
17881814
return merged;
@@ -4277,8 +4303,30 @@ function* interpretStack1G(
42774303
else w.maxSteps = Number(n);
42784304
return [[finItem(prev, emptyExpr, it.bnd)], { counter: st.counter, world: w }];
42794305
}
4306+
if (key.kind === "sym" && key.name === "log-level") {
4307+
const val = inst(env, it.bnd, it2[2]!);
4308+
const rank = val.kind === "sym" ? LOG_RANKS.get(val.name) : undefined;
4309+
if (rank === undefined) return [[finItem(prev, errAtom(a, "UnknownLogLevel"), it.bnd)], st];
4310+
const w = cloneWorld(st.world);
4311+
w.logLevel = rank;
4312+
return [[finItem(prev, emptyExpr, it.bnd)], { counter: st.counter, world: w }];
4313+
}
42804314
return [[finItem(prev, emptyExpr, it.bnd)], st];
42814315
}
4316+
// `(log-enabled? <level>)`: does the level set by `(pragma! log-level ...)` admit this one? The whole
4317+
// point of answering it here is that it is a read of one field on the world, so the guard in front of a
4318+
// log call costs a comparison. `log!` is built on it in the standard library, where `if`'s Atom-typed
4319+
// branches give the laziness that keeps an unadmitted payload from being reduced at all.
4320+
case "log-enabled?": {
4321+
if (it2.length !== 2) break;
4322+
const level = inst(env, it.bnd, it2[1]!);
4323+
const rank = level.kind === "sym" ? LOG_RANKS.get(level.name) : undefined;
4324+
if (rank === undefined) return [[finItem(prev, errAtom(a, "UnknownLogLevel"), it.bnd)], st];
4325+
// True/False are grounded booleans in this engine, not symbols; a bare sym("False") would not
4326+
// match the prelude's `(= (if False $t $e) $e)` and would leave the if unreduced.
4327+
const on = rank !== LOG_OFF && rank <= st.world.logLevel;
4328+
return [[finItem(prev, gbool(on), it.bnd)], st];
4329+
}
42824330
case "bind!": {
42834331
if (it2.length !== 3) break;
42844332
const tok = inst(env, it.bnd, it2[1]!);
@@ -4398,6 +4446,7 @@ function appendSpace(env: MinEnv, w0: World, name: string, atoms: Atom[]): World
43984446
maxStackDepth: w0.maxStackDepth,
43994447
maxSteps: w0.maxSteps,
44004448
stepStart: w0.stepStart,
4449+
logLevel: w0.logLevel,
44014450
};
44024451
}
44034452
const spaces = new Map(w0.spaces);

packages/core/src/logging.test.ts

Lines changed: 124 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,124 @@
1+
// SPDX-FileCopyrightText: 2026 MesTTo
2+
//
3+
// SPDX-License-Identifier: MIT
4+
5+
// Leveled logging: `(pragma! log-level ...)` sets the enabled severity on the world, `log-enabled?` reads
6+
// it, and `log!` emits only what that level admits. The property these tests exist for is that a call the
7+
// level does not admit never reduces its payload, so instrumenting a function costs nothing until someone
8+
// turns logging on. A payload that would not terminate is the sharpest way to state it: if the payload were
9+
// reduced at all, the test would hang instead of failing.
10+
11+
import { afterEach, describe, expect, it } from "vitest";
12+
import { setOutputSink } from "./builtins";
13+
import { format } from "./parser";
14+
import { runProgram } from "./runner";
15+
16+
const last = (src: string): string[] => {
17+
const rs = runProgram(src);
18+
return rs[rs.length - 1]!.results.map(format);
19+
};
20+
21+
let restore: ((line: string) => void) | undefined;
22+
const capture = (): string[] => {
23+
const lines: string[] = [];
24+
restore = setOutputSink((line) => lines.push(line));
25+
return lines;
26+
};
27+
afterEach(() => {
28+
if (restore) setOutputSink(restore);
29+
restore = undefined;
30+
});
31+
32+
describe("log-enabled?", () => {
33+
it("is off until a level is set", () => {
34+
expect(last("!(log-enabled? error)")).toEqual(["False"]);
35+
expect(last("!(log-enabled? trace)")).toEqual(["False"]);
36+
});
37+
38+
it("admits a level at or above the setting's severity", () => {
39+
const src = "!(pragma! log-level info)\n";
40+
expect(last(`${src}!(log-enabled? error)`)).toEqual(["True"]);
41+
expect(last(`${src}!(log-enabled? warn)`)).toEqual(["True"]);
42+
expect(last(`${src}!(log-enabled? info)`)).toEqual(["True"]);
43+
expect(last(`${src}!(log-enabled? debug)`)).toEqual(["False"]);
44+
expect(last(`${src}!(log-enabled? trace)`)).toEqual(["False"]);
45+
});
46+
47+
it("treats `off` as admitting nothing, including itself", () => {
48+
expect(last("!(pragma! log-level trace)\n!(log-enabled? off)")).toEqual(["False"]);
49+
expect(last("!(pragma! log-level trace)\n!(log-enabled? trace)")).toEqual(["True"]);
50+
expect(
51+
last("!(pragma! log-level trace)\n!(pragma! log-level off)\n!(log-enabled? error)"),
52+
).toEqual(["False"]);
53+
});
54+
55+
it("returns a grounded Bool, so it drives `if` directly", () => {
56+
// A bare `False` symbol would not match the prelude's (= (if False $t $e) $e) and would leave the
57+
// if unreduced, which is exactly the shape a guard has to work in.
58+
expect(last("!(if (log-enabled? debug) yes no)")).toEqual(["no"]);
59+
expect(last("!(pragma! log-level debug)\n!(if (log-enabled? debug) yes no)")).toEqual(["yes"]);
60+
});
61+
62+
it("rejects a level that is not a known severity", () => {
63+
expect(last("!(log-enabled? shouty)")[0]).toContain("UnknownLogLevel");
64+
expect(last("!(pragma! log-level shouty)")[0]).toContain("UnknownLogLevel");
65+
});
66+
});
67+
68+
describe("log!", () => {
69+
it("emits nothing while logging is off", () => {
70+
const lines = capture();
71+
last("!(log! error (+ 1 2))");
72+
expect(lines).toEqual([]);
73+
});
74+
75+
it("emits the payload's value tagged with its level once enabled", () => {
76+
const lines = capture();
77+
last("!(pragma! log-level info)\n!(log! info (+ 1 2))");
78+
expect(lines).toEqual(["(Log info 3)"]);
79+
});
80+
81+
it("emits only what the level admits", () => {
82+
const lines = capture();
83+
last(
84+
"!(pragma! log-level warn)\n!(log! error a)\n!(log! warn b)\n!(log! info c)\n!(log! debug d)",
85+
);
86+
expect(lines).toEqual(["(Log error a)", "(Log warn b)"]);
87+
});
88+
89+
it("reduces to unit either way, so it composes in a let", () => {
90+
capture();
91+
expect(last("!(let $x (log! debug ignored) done)")).toEqual(["done"]);
92+
expect(last("!(pragma! log-level debug)\n!(let $x (log! debug shown) done)")).toEqual(["done"]);
93+
});
94+
95+
// The point of the whole design. `endless` has no base case, so reducing the payload cannot terminate.
96+
// Logging is off, so the payload is never reduced and the program finishes.
97+
it("does not reduce the payload of a call the level does not admit", () => {
98+
const endless = "(: endless (-> Number Number))\n(= (endless $n) (endless (+ $n 1)))\n";
99+
expect(last(`${endless}!(log! debug (endless 0))`)).toEqual(["()"]);
100+
expect(last(`${endless}!(pragma! log-level info)\n!(log! debug (endless 0))`)).toEqual(["()"]);
101+
});
102+
103+
it("does not reduce the payload for effect either", () => {
104+
const lines = capture();
105+
last('!(log! debug (println! "payload"))');
106+
expect(lines).toEqual([]);
107+
});
108+
});
109+
110+
describe("pragma! log-level", () => {
111+
it("carries the setting to later top-level queries", () => {
112+
const lines = capture();
113+
last("!(pragma! log-level debug)\n!(log! debug first)\n!(log! debug second)");
114+
expect(lines).toEqual(["(Log debug first)", "(Log debug second)"]);
115+
});
116+
117+
it("can be turned back off", () => {
118+
const lines = capture();
119+
last(
120+
"!(pragma! log-level debug)\n!(log! debug on)\n!(pragma! log-level off)\n!(log! debug off)",
121+
);
122+
expect(lines).toEqual(["(Log debug on)"]);
123+
});
124+
});

packages/core/src/stdlib.ts

Lines changed: 18 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -104,6 +104,21 @@ export const STDLIB_SRC = `
104104
(: trace! (-> %Undefined% Atom %Undefined%))
105105
(= (trace! $msg $ret) (let $unit (println! $msg) $ret))
106106
107+
; ---- leveled logging ----
108+
; Logging is off until a program sets (pragma! log-level <level>), and the levels rank
109+
; error < warn < info < debug < trace, so a setting admits everything at or above its severity.
110+
; log-enabled? is an interpreter form (see EMBEDDED in eval.ts) because the level lives on the world:
111+
; asking whether a level is admitted is a read of one field. log! is built on it here, and its payload
112+
; is Atom-typed, so if's unevaluated branches leave the payload of an unadmitted call alone. Together
113+
; that is the point of the design: instrumenting a hot function costs a comparison while logging is off,
114+
; and the work that would build the message is not done at all. Measured on a 200-iteration loop, the
115+
; off path is flat across a hundredfold change in payload cost (69 ms either way) while the same loop
116+
; with the level set scales with it (145 ms to 4765 ms).
117+
(: log-enabled? (-> Symbol Bool))
118+
(: log! (-> Symbol Atom (->)))
119+
(= (log! $level $payload)
120+
(if (log-enabled? $level) (println! (Log $level $payload)) ()))
121+
107122
; Partial application is ordinary PeTTa behavior. A known under-applied head becomes
108123
; (partial head args); applying that closure rebuilds the fuller call and evaluates it.
109124
(: partial (-> Atom Expression Atom))
@@ -375,7 +390,9 @@ export const STDLIB_SRC = `
375390
(@doc random-float (@desc "Returns a random float in the half-open interval from the lower bound to the upper bound") (@params ((@param "Lower bound") (@param "Upper bound"))) (@return "Random float"))
376391
(@doc random-int (@desc "Returns a random integer in the half-open interval from the lower bound to the upper bound") (@params ((@param "Lower bound") (@param "Upper bound"))) (@return "Random integer"))
377392
(@doc nop (@desc "Outputs the unit atom") (@params ()) (@return "Unit atom"))
378-
(@doc pragma! (@desc "Changes the value of a global key, such as type-check, interpreter, max-stack-depth, or mettascript-max-steps") (@params ((@param "Key name") (@param "New value"))) (@return "Unit atom"))
393+
(@doc pragma! (@desc "Changes the value of a global key, such as type-check, interpreter, max-stack-depth, mettascript-max-steps, or log-level") (@params ((@param "Key name") (@param "New value"))) (@return "Unit atom"))
394+
(@doc log! (@desc "Prints the payload tagged with its level, but only when (pragma! log-level ...) admits that level. The payload is not reduced otherwise, so a log call in a hot path costs nothing until logging is turned on") (@params ((@param "Level: error, warn, info, debug, or trace") (@param "Payload atom, reduced only when the level is admitted"))) (@return "Unit atom"))
395+
(@doc log-enabled? (@desc "Whether the current log level admits this one, for a caller that wants its own sink and still wants the guard to cost only a comparison") (@params ((@param "Level: error, warn, info, debug, or trace"))) (@return "True when the level is admitted"))
379396
(@doc bind! (@desc "Registers a token replaced by an atom during parsing of the rest of the program") (@params ((@param "Token name") (@param "Atom associated with the token after reduction"))) (@return "Unit atom"))
380397
(@doc sort-strings (@desc "Sorts an expression of strings in alphabetical order") (@params ((@param "List of strings"))) (@return "Sorted list of strings"))
381398
(@doc first-from-pair (@desc "Returns the first atom of a pair") (@params ((@param "Pair"))) (@return "First atom of the pair"))

0 commit comments

Comments
 (0)