Skip to content

feat: read the variables in scope at an event - #142

Merged
lcottercertinia merged 28 commits into
mainfrom
worktree-humble-pondering-brook
Oct 16, 2026
Merged

lcottercertinia merged 28 commits into
mainfrom
worktree-humble-pondering-brook

Conversation

@lukecotter

Copy link
Copy Markdown
Collaborator

📝 Overview

A consumer that wants the variables a frame could see must build them again from the raw lines. The debug-log-analyzer (DLA) does this in about 1,700 lines. Most of that code is log rules, not UI. This PR moves those rules into the parser, so each consumer gets the same answer. It keeps the DLA rules and uses the v1 style: typed-array columns, byte reads and figures made on the first read.

const vars = log.at(ns)?.variables;     // or event.variables
vars?.locals;                           // the frame's own, each with its last write by then
vars?.this; vars?.fields;               // the object the frame runs on, and its fields
vars?.statics;                          // each static by then, by class
event.objectAt(address);                // the object at an address, as the event stood

🛠️ Changes

  • event.variables: the frame, its locals, this, the fields of this and the statics, by class. A query or a system call answers from the Apex frame that issued it. A frame reads as it stood when it finished.
  • event.objectAt(address): the class, value and fields of the object at an address. A reused address starts a new object.
  • Each Variable gives its write as the VARIABLE_ASSIGNMENT event, or null when the log has no write.
  • The types Variable, Variables, StaticClass and ObjectState are exported.
  • Fix: a VARIABLE_ASSIGNMENT line's value field no longer holds the trailing |0x… address. The address field holds it.
  • The index (engine/variables.ts) is built on the first read only, so parse does no new work. It is not in toBuffers; a log from fromBuffers builds it again on its first read.
  • New gate in bench:views: variables at 100 MB.
  • CONTEXT.md has a new "Variables" section.

Performance

Parse, bench:large against main (55427c4), 2 rounds:

Log main branch, round 2 Round 1
8 MB 19 ms 19 ms (−1.7%) 21 ms (+9.1%)
20 MB 46 ms 46 ms (−0.3%) 45 ms (+0.7%)
50 MB 98 ms 97 ms (−0.5%) 99 ms (+1.9%)
75 MB 147 ms 146 ms (−0.8%) 148 ms (+1.1%)
100 MB 195 ms 194 ms (−0.1%) 197 ms (+1.4%)

Heap is ±0.0% at every size in both rounds. Round 1's +9.1% at 8 MB is 2 ms, and round 2 does not show it, so it is noise. The parse path has no new work: the index is made on the first variables read.

Index build and memory, on real FINEST logs (median of the build; heap kept after GC):

Log Rows Writes Build Keeps Per read
A 271,567 65,624 31.0 ms 4.0 MB 17 µs
B 150,254 33,982 12.2 ms 2.4 MB 5 µs
C 17,519 3,577 3.0 ms 0.4 MB 42 µs
D 1,654 416 0.4 ms 0.0 MB 5 µs

Worst cases, from synthetic logs that read every event:

  • 20,000 writes over 2,000 names in one frame: 2.1 s for 20,001 events, keeps 310 MB.
  • 3,000 statics in one class, with 20,000 static writes: 2.8 s, keeps 455 MB.
  • 3,000 statics in 50 classes: 0.24 s, keeps 28 MB. The statics of a class are shared until a line changes them.

Against DLA (frameVariablesFor), the same events, 2 runs each:

Log Index, DLA Index, v1 Keeps, DLA Keeps, v1 Read, DLA Read, v1
A 105–125 ms 49 ms 11.1 MB 4.1 MB 4,012–4,433 µs 20 µs
B 77–80 ms 36 ms 2.5 MB 2.5 MB 36 µs 10–11 µs
E 49–50 ms 12 ms 2.3 MB 1.2 MB 176–191 µs 59–60 µs
C 6.8–7.0 ms 7.0–7.3 ms 0.7 MB 0.6 MB 537–549 µs 35–36 µs

This table times one cold build per side, so its v1 figures are higher than the medians of 5 builds above.

Answers against DLA on 3 logs (2,845 events): 0 differences in the frame, locals, this, fields, statics, or the class, value and fields of each object. v1 gives a value for 1,658 addresses where DLA gives none. DLA indexes a value only where some value is that address; v1 indexes each one.

Gate, bench:views at 100 MB: variables adds 19.9 ms over the build and keeps 13.4 MB. The gate is < 50 ms, so it passes.

Known limits

  • A value on more than one line is not read past its first line. 0 of 362,518 writes in the real logs did this.
  • A class with thousands of statics makes one list per change, so it costs time and memory (see the worst cases above).
  • The fields of this are merged over the frames of the same class: O(depth × names) per read.
  • A frame that has not yet written this can take fields from a frame of the same class on another object. DLA does the same.

Architecture

  • Depth: VariableIndex keeps about 770 lines behind 4 queries: at, objectAt, staticClasses and staticsOf. LogVariables turns what it finds into shared, frozen objects. Without it, the caching and freezing go into views/events.ts. The split is the same as engine/throws.ts.
  • Next sibling: a new query, such as the history of one name, needs one index method, one view method and one EventBase member, as details does.
  • Not done, and why:
    1. Constructor split. One write pass fills the field, describing and static lists. A split undoes that and passes 6–8 arrays between functions. The complexity moves; it does not go away.
    2. Shared grouped with Store.indexTypes. indexTypes sorts every row with a range check. grouped adds a closure call per row and an n-sized array, and changes code outside this PR.
    3. A catalog rule for the trailing address. addressPipe holds the rule in one place, and both readers call it. A catalog rule changes the ByteFields hot path that every event reads, a deopt risk, to remove one branch beside the INTERVIEWS precedent.
    4. Static ordinals grouped by class. This removes classStatics but adds a remap of the same size.

🧩 Type of change

  • 🐛 Bug fix — fixes an issue
  • ✨ Feature — adds new functionality
  • ♻️ Refactor — no behaviour change
  • ⚡ Performance
  • 📝 Docs
  • 🔧 Chore — tooling, CI, deps
  • 💥 Breaking change

🔗 Related issues

Closes #72

✅ Checklist

  • Tests added/updated
  • pnpm run ci passes locally
  • Changeset added (pnpm changeset) if this affects the published package
  • Docs updated if behaviour or the public API changed

lukecotter and others added 28 commits October 16, 2026 18:03
A VARIABLE_ASSIGNMENT value that holds `|` lost its tail to `address`.
The value now runs to a trailing address field. The address field is
`0x` and hex, or empty for a null value. With no address field, the
value runs to the end of the line.
`event.variables` gives the locals an event's frame could see, as the
log recorded them: each name's last write by then, and each name the
frame declared and never wrote. A frame reads as it finished, a leaf as
the log reached it. A query or a system call answers from the nearest
frame with a variable line of its own, as debug-log-analyzer does.

The first read indexes the log's variable lines once, in typed-array
columns, with each frame's own lines in one CSR list. The parse does not
change. Null when the event is in no frame or the log has no variable
lines.
`variables.statics` gives every static written or declared anywhere by
the event, grouped by class, both sorted. A static lives for the
transaction, so a write in any frame counts, and a static declared and
never written has a null value. Each static's writes are one CSR list,
so a read is one binary search per static.
Addresses and types share the index's string table with names, so a
new name could take an id past the end of the name-kind array, which
grew only when an id equalled its length. The write fell outside the
typed array without an error, and that name read as no local.
`variables.this` is the frame's last write to `this`, with its declared
type. `variables.fields` gives the last write to each field of that
object: from every frame of the same class on the stack, and from the
field writes the log grouped under the object's address, so a field a
returned constructor set is in scope. A frame on another object of the
class is left out. The latest write wins.

A method's class is its signature up to its name, a constructor's is its
className field. One `grouped` helper now builds every CSR list.
`event.objectAt(address)` reads what the log holds for the object at an
address, as the event stood: its class, its value and its fields.

- Class: the type its frame declared `this` as, at the object's `this`
  write. A superclass constructor inside the run does not change it, and
  only a construction starts a new object at a reused address.
- Value: the last write by then that reports the address, unless the
  value is itself an address. `laterAt` is where the first one is, when
  none is by then.
- Fields: the last write to each by then. Writes from an earlier object
  at the address do not count, here or in `variables.fields`.

Null when the log holds nothing for the address.
A frame's lines are now one run per name, declarations then writes,
each in log order. A name's earliest declaration and its last write by
a cut are each one binary search, so a read costs the frame's names,
not its lines. In a log where an open callout holds 65k field writes,
a read drops from 251 µs to 26 µs.

The query marks by string id and the per-frame line and `this` lists
go; each frame keeps the row of its first variable line.
The index counts the static lines by a cut that change the statics.
Two events with the same count get the same frozen list. A new list
decodes only the statics whose write changed. In a log with 739
statics, a read drops from 437 µs to 104 µs.
The index answers `at(id)`, `objectAt(id, address)` and `statics(id)`,
and gives rows and string ids that need no more work. The cut, the
recording frame and the address lookup move inside it, so the view
only decodes strings and freezes. A static never written is kept by
its declaration's row in a map of its own, not in a key that packs
two kinds of ordinal into one number.
A local, `this` or a field is now one frozen object per write, and a
local declared and never written is one per declaration. Events that
see the same write share it, and its value is read from the log once.
With 20 locals of 100 KB read on 500 events, the reads drop from
932 ms and 1,022 MB to 5 ms and 0.4 MB.
The index lists each class's statics and the lines that change them.
A read that sees a new statics version rebuilds only the class whose
static changed; the other classes keep the same frozen object. With
3,000 statics in 50 classes and 20k static writes, reading every event
drops from 6.8 s and 745 MB to 0.23 s and 28 MB.
A static named `.x`, or declared static with no `.`, had `className:
''`. It is now null, so a caller can tell "no class" from a name. It
sorts first.
`Variable.id` held the id of the event that wrote the value, and read
as the variable's own id. `ObjectState.laterAt` held an id, and read as
a time. They are now `write` and `laterWrite`: the
`VARIABLE_ASSIGNMENT` event itself, as `Variables.frame` and
`LogIssue.event` give theirs. Null as before.
The glossary had two meanings for "Field"; the variable one is now
"Object field". "Scope", which the glossary bans, goes from the README,
the glossary and a comment. The docs now state the frame used when no
frame records a variable, that every list is sorted by name in
code-unit order, that `objectAt` matches the address text exactly, and
that a `VARIABLE_ASSIGNMENT` value stops before its address.
Adds tests for `this` declared and never written, a write before its
declaration, a caller that answers when the called frame writes only
after the event, code-unit sort order, a static declared twice, and
`objectAt` on a log with no variable lines. Every part of a result is
checked as frozen. Drops a fixture line that no assertion read.
A block can declare a name again with another type, as two loops do.
The real test logs do this 391 times. A local took the frame's
earliest declaration, so a String value read as Integer. It now takes
the latest declaration by the cut.
A written static took its earliest declaration's type even when the
declaration came after the event. It now takes it only from the
declaration on, as a local does. Locals, fields and statics now share
one memo keyed by the line's row, which checks the type.
When every line for an address came after the event, `objectAt` gave
an object of nulls, which the null rule in AGENTS.md forbids. It now
gives null, unless a later write states the value, so `laterWrite`
still points to it.
The three multi-line `//` comments in the index are now one line each,
and keep only the why. Doc comments wider than the repo's 100-column
line are wrapped or cut.
An address is at most `0x` and 16 hex digits; the real logs hold 7 to
10 characters. So the pipe before it is in the last 19 bytes, and a
value with no address is no longer read end to start. The index build
drops by 9–14% on real logs.
The memo was keyed by the write's row and checked the type, because a
write can pair with more than one declaration. The write's row and the
declaration's row together fix every value of a `Variable`, so one map
keyed by both replaces the two maps and the check.
Six reads wrote the same `upperBound(...) - 1` and range check by hand.
`lastBy` does it once; `objectOf` and the version counts keep
`upperBound`, as they need the index itself.
A name was static when it held a dot, or when its declaration said
isStatic. In the real test logs the two agree on all 186,220
declarations, so the flag adds nothing. A static is now a name with a
dot after its first character. Every static has a class, so
`StaticClass.className` is a string again.
One pass over the writes now fills the field, describing and static
lists, and one over the declarations finds each static's first one.
Declarations go first by construction, not by a sort. `frameFirst`
comes from the log-order pass that finds the objects, and `this` is
read from the name's kind. `addressOf` adds each address once. The
build drops by about 25–40% on real logs.
The view made, kept and read back its caches the same way in five
places. One helper now does it. Direct calls to shared() take the
place of the three one-line wrappers around it.
@codspeed

codspeed Bot commented Oct 16, 2026 •

Copy link
Copy Markdown

Merging this PR will not alter performance

✅ 6 untouched benchmarks


Comparing worktree-humble-pondering-brook (d0178a5) with main (53e852e)

Open in CodSpeed

@lcottercertinia
lcottercertinia merged commit df7726f into main Oct 16, 2026
10 checks passed
@lcottercertinia
lcottercertinia deleted the worktree-humble-pondering-brook branch October 16, 2026 17:08
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

✨ feat: Answer "what variables were in scope at this frame" from the parser

2 participants