Skip to content

vm: TracePoint — line, class/end, call/return, b_call/b_return and rescue (core/tracepoint 0 → 69) - #654

Merged
tannevaled merged 6 commits into
mainfrom
wave30/trace
Sep 25, 2026
Merged

tannevaled merged 6 commits into
mainfrom
wave30/trace

Conversation

@tannevaled

Copy link
Copy Markdown
Contributor

TracePoint

core/tracepoint was the last wholly-absent subsystem in the pinned corpus: 75 examples, pass = 0, unchanged across six censuses. There was no TracePoint code in the tree — a grep for TracePoint over internal/ found nothing.

core/tracepoint: 0 → 69 of 75. No regression anywhere else in the corpus.

Bibliography

Read before choosing a shape, all at ruby/ruby v3_4_0, and cited at each site in the code:

what where
the RUBY_EVENT_* bit set include/ruby/internal/event.h
symbol2event_flag (name → bit, incl. the :a_call/:a_return aggregates) vm_trace.c:804
get_event_id (bit → name) vm_trace.c:667
tracepoint_new_s (default event set; events validated before the block check) vm_trace.c:1490
tracepoint_trace_s vm_trace.c:1513
tracepoint_enable_m / tracepoint_disable_m (previous-state answer, rb_ensure restore, target_thread: default) vm_trace.c:1375 / :1424
rb_tracepoint_enable / rb_tracepoint_enable_for_target (the two nest-enable refusals, "can not enable any hooks") vm_trace.c:1193 / :1234
rb_iseq_add_local_tracepoint_recursively (a target: covers the target's nested ISeqs) iseq.c:3912
rb_tracearg_* — event, lineno, path, method_id, callee_id, defined_class, self, binding, parameters, return_value, raised_exception vm_trace.c:862–1080
get_trace_arg (the RuntimeError "access from outside") vm_trace.c:846
get_path_and_lineno (class/call/b_call report first_lineno, everything else the current line) vm_trace.c:694
tracepoint_inspect vm_trace.c:1521
tracepoint_allow_reentry vm_trace.c:1607
rb_exec_event_hooks (the ec->trace_arg reentry guard) + exec_hooks_body vm_trace.c:412 / :341
hook_list_connect (hooks are prepended) vm_trace.c
vm_trace_hook (global hooks first, the ISeq's local hooks second) vm_insnhelper.c:7054
rb_iseq_trace_set (how MRI avoids a per-instruction test at all) iseq.c:3981

Events raised

line, class, end, call, return, b_call, b_return, rescue — with TracePoint.new, .trace, .allow_reentry, #enable (including target:, target_line: and target_thread:), #disable, #enabled?, #inspect, and every accessor above.

Events left out, and why

Each needs a hook in a file this change does not own. They are listed at supportedTraceEvents in internal/vm/tracepoint.go, with the reason, so the next person does not have to re-derive it.

event why not
c_call / c_return a native body is invoked from callNative (object_model.go) and only from there. The OpSend sites in vm.go hold a resolved *Method on the inline-cache fast path but not on the send / method_missing / operator fallbacks, so hooking them here would fire for some native calls and not others — worse than not firing.
raise every Ruby-level raise funnels through excError / captureBacktrace (builtins.go). The only raise-shaped point reachable from vm.go is the rescue dispatch, which is where :rescue fires; announcing :raise from there would report the rescuing frame's line as the raise site.
script_compiled eval compiles in eval.go / binding_eval_open.go, and rbgo forms no "(eval at FILE:LINE)" path for the compiled unit.
thread_begin / thread_end / fiber_switch thread.go / fiber.go.

An unknown event name is still an ArgumentError; an event outside the raised set is accepted and simply never delivered, exactly as a TracePoint for an event the program never reaches behaves.

The hot path

MRI never tests a flag per instruction. Its compiler emits distinct trace instructions and rb_iseq_trace_set (iseq.c:3981) rewrites their encodings when a hook turns an event on, so an untraced program executes no trace instruction. rbgo has no instruction to rewrite — its ISeqs are plain []Instr, shared and reachable from AOT-frozen output — so the gate is a test instead of a rewrite:

if myFrame < len(vm.frameCode) {
    vm.frameCode[myFrame].pc = pc        // already there
}
if vm.traceEvents&evLine != 0 {          // added: one load, one not-taken branch
    …
}

vm.traceEvents is a single word: the union of the event masks of every enabled TracePoint, narrowed to the events rbgo raises, so a hook for an event that can never fire does not open the gate. Everything past the branch — the line-map search, the event record, the hook walk — is behind it. traceFrame is built lazily and only when tracing is on, so a traced program pays per frame and an untraced one pays nothing per frame.

ISeq.IsLineStart is the line-map question MRI answers with a trace instruction: Lines already holds one entry per line change, which is exactly the set of positions MRI would have marked, and the lookup is LineAt's binary search narrowed to an exact hit.

Measured cost — see the benchmark section. This is the trade to weigh.

Hook order is observable, and it is not registration order

vm_trace_hook runs the global hooks first and the ISeq's local (target:) hooks second, and within each list hook_list_connect prepends, so the most recently enabled hook is called first. ruby/spec pins all three combinations that distinguishes (enable_spec.rb:377 / :399 / :421): a targeting TracePoint enabled inside a global one reports [:outer, :inner], two targeting ones report [:inner, :outer], and a global one inside a targeting one reports [:inner, :outer] again. No single ordering of one list produces all three.

A second witness, because the shim's should.equal? asserts nothing

The corpus shim's ShouldProxy defines equal but not equal?, so x.should.equal?(y) dispatches Object#equal? on the proxy, compares nothing, and raises nothing — a spec written that way passes whatever the implementation does. There are 20 such sites across 7 of the 19 tracepoint spec files.

So the behaviour is measured a second way as well: 24 differential probes, run under ruby 4.0.5 and under rbgo and compared as raw bytes — events and their order, every accessor, the inspect shapes, enable/disable return values and block scoping, target: and target_line: including all 11 refusals, hook order, allow_reentry, the thread filter, defined_class through an include and two super hops, :rescue, a handler that raises, a handler that disables itself mid-walk, every exit event on an unwinding frame, and a TracePoint enabled from inside the frame it then traces. 24/24 byte-identical.

Exactly one passing example is vacuous and known to be: raised_exception_spec's :raise case. :raise is not raised (above), the shim's should.equal? does not notice, and the probe does.

Known divergences

Two :line-event shapes still differ from MRI. Neither is reachable by any example in the pinned corpus; both are line-map facts that live in internal/compiler, which this change does not own.

  1. An empty method body. def m; end — MRI compiles it with no line instruction and raises no :line; rbgo's line map has an entry at the def line, so it raises one. [6] in MRI, [6, 4] here. Also visible as TracePoint.new(:line).enable(target: method(:m)) succeeding here and raising can not enable any hooks in MRI.
  2. A while condition. MRI emits the condition's line trace once, above the loop; rbgo's loop jumps back to the pc its line map marks, so the condition's :line repeats per iteration: [13, 14, 14] in MRI, [13, 14, 13, 14, 13] here.

A third difference is not a defect on either side: MRI implements TracePoint#enable and #disable in Ruby (trace_point.rb), so a :call/:return TracePoint sees their frames; rbgo's are native, so it does not. A :c_call TracePoint would be the thing that sees them, and rbgo does not raise that.

One example blocked outside this change

enable_spec.rb "traces some events in nested blocks" fails on Method#source_location, which returns line 0 for every method:

// internal/vm/method_reflect2.go:190
return object.NewArray(object.NewString(is.File), object.IntValue(0))

The b_call linenos this change reports are correct ([227, 228, 229]); the spec computes its expectation from source_location and gets [1, 2, 3]. is.FirstLine in place of the literal 0 is a one-line fix worth this one example, but method_reflect2.go is outside this change's file boundary, so it is left for whoever owns it.

One thing the specs could not find

No example in the corpus exercises a :return from a frame that does not finish, and rbgo raised none. MRI does: hook_before_rewind fires RETURN as it rewinds the frames an exception is unwinding past, with #return_value nil. A probe found it; the specs never would have. The rule, measured rather than assumed: an unwinding frame reports nil, the frame that catches a non-local return reports the returned value, and a block broken out of reports the break value.

Measurement

ruby/spec at the pinned SHA, 2-way, per file. Other sessions were sweeping the same corpus on this host throughout, so the totals carry that noise; the per-file diff is what to read.

core/tracepoint/… before after
allow_reentry_spec.rb 0 2
binding_spec.rb 0 1
callee_id_spec.rb 0 1
defined_class_spec.rb 0 1
disable_spec.rb 0 5
enable_spec.rb 0 31
enabled_spec.rb 0 2
eval_script_spec.rb 0 0
event_spec.rb 0 1
inspect_spec.rb 0 6
lineno_spec.rb 0 2
method_id_spec.rb 0 1
new_spec.rb 0 7
parameters_spec.rb 0 2
path_spec.rb 0 1
raised_exception_spec.rb 0 2
return_value_spec.rb 0 1
self_spec.rb 0 2
trace_spec.rb 0 1

Whole corpus (language + core, 2206 files): 22165 → 22296, re-measured on the final tree with the same result. Two of that +131 are not this change: core/module/autoload_spec.rb contributed 0 to the baseline run (the ~1-in-4 crash, #615 — it reads 61 on the base binary when it does not crash) and core/random/bytes_spec.rb moved 8 → 9. Net attributable: +69, all in core/tracepoint, no file lost an example.

Benchmarks

Interleaved A/B on the same host, bench/*.rb run alternately by the base binary and this one, best-of-12 and — because other sessions were sweeping the corpus on this machine throughout, at load averages of 11 to 23 — the median of the per-round A/B ratios, which cancels load common to a pair. The two columns agreeing is the reason to believe either.

bench base (ms) with TracePoint (ms) best-of Δ median-ratio Δ
loop.rb (tight integer loop, one frame) 2121 2129 +0.38% +1.36%
fib.rb (recursion + dispatch) 5248 5317 +1.30% +3.32%
dispatch.rb (5M monomorphic calls) 2091 2099 +0.40% +1.59%
blocks.rb (10M tiny block calls) 904 895 −0.93% +0.75%
proc.rb 999 1016 +1.73% +1.53%
array.rb 326 333 +2.24% +1.77%
hash.rb 392 398 +1.70% +1.71%
strings.rb 106 106 +0.54% +0.55%

Roughly 1–2%, and it was measured twice because the first shape was worse. The first version paid per FRAME as well as per instruction: an unconditional defer in exec plus one more variable captured by its closures cost blocks.rb — millions of tiny block calls, this VM's worst case for anything paid per frame, and the bench an existing comment in vm.go already names for exactly that — +3.65% median / +5.22% best-of. Gating the defer on vm.traceEvents != 0 and moving the one-shot flag into the frame description took that to +0.75% / −0.93%, and a direct A/B of the two shapes on blocks.rb puts the improvement at −2.76% median. dispatch.rb came down with it (+2.60% → +1.59%).

What is left is the per-instruction gate: one load of vm.traceEvents and one not-taken branch, beside the frameCode[…].pc = pc store the loop already did. loop.rb, which is a single frame and 20M instructions, is the clean read of it: +0.4% best-of, +1.4% median.

Two things were tried and rejected on the numbers: co-locating traceEvents with frameCode in the VM struct so the pair shares a cache line (no improvement — consistent with the note already in vm.go recording that a similar layout change bought nothing there either), and leaving the defer unconditional.

The trade, stated plainly: ~1–2% on every program, including the ones that never build a TracePoint, in exchange for 69 examples and a working debugger hook. MRI pays nothing here because it rewrites instruction encodings; matching that would mean giving rbgo a trace instruction and a per-ISeq rewrite pass, which is a compiler change, not a VM one. If ~1–2% is not worth it, the honest alternative is that rewrite — not a smaller version of this.

One corner the gating costs: a frame that was already running when the TracePoint was enabled, and that then leaves by unwinding, raises no exit event (it registered no defer, because nothing was tracing when it began). Its normal exit still does — that is tested — and every frame entered after the enable behaves fully.

Gates

  • CGO_ENABLED=0 go build ./... ✅ · GOOS=wasip1 GOARCH=wasm ✅ · gofmt -l internal/ empty ✅
  • CGO_ENABLED=0 GOWORK=off go test ./... ✅ (full suite)
  • Coverage: the below-100 LIST is exactly main's. 16 functions, unchanged: object.go:repr, arith.go:binary/rubyEql/valueEqlRec, bigdecimal_bind.go:Inspect, builtins.go:bootstrap/cloneSingleton, complex.go:registerNumericGeneric, converter_codec.go:xtextRuneStep/encodeCharTo, date_bind.go:Inspect, io.go:inspectStr, nethttp.go:registerNetHTTP, object_model.go:objSingleton/classOf/ivarTable. Nothing in tracepoint.go, nothing in bytecode.go, and vm.go:exec back at 100% — it appeared at 99.7% on the first pass, and the two blocks it named were the lazy frame-description rebuilds, which turned out to be real behaviour (a TracePoint enabled from inside a frame) rather than dead code, and are now measured against MRI.

Three branches that production cannot reach were deleted rather than covered: traceEventsNamed (a mask renderer with no caller but its own test), #parameters' C-call arm, and #inspect's C-call and thread shapes. Each is noted where it was, so it comes back with its event rather than ahead of it. traceArg.hasData went too — written at two sites, read at none.

🤖 Generated with Claude Code

tannevaled and others added 6 commits September 25, 2026 10:14
There was no TracePoint code in the tree; core/tracepoint was 0 of 75.

Read before designing (ruby/ruby v3_4_0): include/ruby/internal/event.h
for the RUBY_EVENT_* bit set, vm_trace.c for tracepoint_new_s (:1490),
tracepoint_enable_m (:1375), tracepoint_disable_m (:1424),
tracepoint_inspect (:1521), rb_tracearg_* (:862-1080),
rb_tracepoint_enable_for_target (:1234), tracepoint_allow_reentry
(:1607), get_path_and_lineno (:694), hook_list_connect and
rb_exec_event_hooks (:412); iseq.c for rb_iseq_trace_set (:3981) and
rb_iseq_add_local_tracepoint_recursively (:3912); vm_insnhelper.c for
vm_trace_hook (:7054).

Events raised: line, class, end, call, return, b_call, b_return, rescue.
Left out with reasons in supportedTraceEvents: c_call/c_return,
raise, script_compiled, thread_begin/thread_end/fiber_switch — each
needs a hook in a file outside this change.

The hot path. MRI never tests a flag per instruction: it emits distinct
trace instructions and rb_iseq_trace_set rewrites their encodings, so an
untraced program executes none. rbgo has no instruction to rewrite, so
the gate is one word — vm.traceEvents, zero unless a TracePoint is
enabled — tested once per instruction beside the pc publication that was
already there. Everything past it, including the line-map search, is
behind the gate.

Order is MRI's, and it is not registration order: global hooks first,
then the ISeq's local (target:) ones, each list walked most-recently-
enabled first, because hook_list_connect prepends. enable_spec pins all
three combinations.

core/tracepoint: 0 -> 69 of 75.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Every branch of tracepoint.go, driven through Ruby where Ruby can reach
it and called directly where it cannot — the tpOf refusals, the
non-Thread and already-set target_thread: refusals, allow_reentry's
block check, the C-call inspect shape, the reentry guard, and the
frame-typing table.

frameTracePath now clamps its frame index: frameFileLabel indexes the
frame stacks unguarded, and exec can legitimately outrun them (the
bounds note at the pc publication says why), so an event raised from a
frame the stacks no longer cover reported a panic rather than the
script. scriptLabel is frameFileLabel's no-file answer, split out so the
clamped path can reach it with no frame at all.

Measured beside the specs: 15 differential probes (events, accessors,
inspect shapes, enable/disable returns, target:/target_line: including
every refusal, hook order, allow_reentry, thread filter, rescue) are
byte-identical to ruby 4.0.5. That second witness matters here because
the corpus shim defines ShouldProxy#equal but not #equal?, so a spec
written `x.should.equal?(y)` asserts nothing.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Three pieces claimed something nothing could check, so they are gone
rather than covered by a test written to reach them:

  - traceEventsNamed rendered an event mask for no caller but its own
    test;
  - #parameters carried MRI's C-call arm (rb_unnamed_parameters over the
    method arity), and rbgo raises no :c_call;
  - #inspect carried MRI's C-call and thread shapes, and rbgo raises
    none of :c_call, :c_return, :thread_begin or :thread_end.

Each is noted where it was, so it comes back WITH its event rather than
ahead of it. traceArg.hasData went too: it was written at two sites and
read at none.

Re-measured after: core/tracepoint still 69, the 15 differential probes
still byte-identical to ruby 4.0.5.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
A differential probe against ruby 4.0.5 found it: rbgo raised :return
only on normal completion, and MRI raises it for a frame an exception
unwinds past as well. `def a2; raise; end` called from a1 under a
:return TracePoint reports [:return, :a2, nil] then [:return, :a1, nil]
in MRI; rbgo reported neither. Same for a non-local return out of a
block, which MRI reports as the block's :b_return.

MRI's rule, read off hook_before_rewind and confirmed by measuring: a
frame that leaves by unwinding reports #return_value as nil, the frame
that CATCHES a non-local return reports the returned value, and a block
broken out of reports the break value.

Three sites, all gated on tracing being on:
  - a deferred fire for the exception/throw case, registered BEFORE the
    returnSignal recover so it RUNS after it and sees exitFired set;
  - the returnSignal recover itself, before it truncates this frame's
    own stack entries away;
  - OpBreak and the non-local arm of OpReturn, which know their value
    and must fire before they panic.

exitFired keeps it to exactly one event per frame.

Probes: 22 now, all byte-identical to ruby 4.0.5. core/tracepoint stays
69 — no spec exercises an unwinding return, which is why only a probe
could find this.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Two gaps the coverage list named, both real behaviour rather than dead
code.

A TracePoint enabled from INSIDE a frame must still raise that frame's
own :rescue and exit events — MRI rewrites the running iseq's trace
instructions when the hook goes on, rbgo builds the frame description on
first need — and neither lazy rebuild had a test. It does now, measured
against ruby 4.0.5 in all three shapes (top level, method, block).

enable's target_thread: default tested `target == nil` where MRI tests
NIL_P(target), so an explicit `target: nil` lost the current-thread
default that MRI keeps. Probe 23 pins both directions: `target: nil`
confines the trace to the calling thread, `target_thread: nil` does not.

internal/vm and internal/bytecode are back to the below-100 LIST main
carries, with no entry added. 24 probes, all byte-identical.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The first shape paid per FRAME as well as per instruction: exec
registered the unwind exit-event defer unconditionally and its closures
captured one more variable. bench/blocks.rb — 10M tiny block calls, this
VM's worst case for anything paid per frame, and the bench the frameCode
comment already names for exactly that — read +3.65% median / +5.22%
best-of against the base binary.

Two changes, measured: gate the defer on vm.traceEvents != 0 (an
open-coded defer inside an `if` is still open-coded, so an untraced
program does not register it), and move the one-shot flag out of exec's
locals into the frame description the four raise sites already hold.

blocks.rb: +0.75% median / -0.93% best-of. A direct A/B of the two
shapes puts the gain at -2.76% median on blocks.rb; dispatch.rb came
down with it, +2.60% -> +1.59%.

What is left is the per-instruction gate — one load and one not-taken
branch — which loop.rb, a single frame and 20M instructions, reads at
+0.4% best-of / +1.4% median.

The gating costs one corner: a frame already running when the TracePoint
was enabled raises no exit event if it then leaves by UNWINDING, because
it registered no defer. Its normal exit still does, and that is tested.

Re-verified on this tree: full suite green, below-100 coverage list
exactly main's, corpus 22296 with the same +69, 24/24 probes
byte-identical to ruby 4.0.5.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
@tannevaled
tannevaled merged commit edb3c5f into main Sep 25, 2026
7 checks passed
@tannevaled
tannevaled deleted the wave30/trace branch September 25, 2026 14:27
tannevaled added a commit that referenced this pull request Sep 25, 2026
Three units, and one of them closes the last wholly-absent subsystem.

  #654  TracePoint, 0 -> 69 of 75. core/tracepoint had been pass=0 across six
        censuses, untouched because it is hooks in the execution core rather
        than an API to complete — and because a tracepoint must report a line,
        which the VM could not do until #645. Events line/class/end/call/
        return/b_call/b_return/rescue, every accessor, enable with target:/
        target_line:/target_thread:, allow_reentry. Costs ~1-2% on every
        program; that trade is recorded and justified in issue #658, together
        with the zero-cost alternative (MRI rewrites instruction encodings
        rather than testing per instruction).
  #656  String/IO encoding conformance: gsub's result-encoding negotiation,
        IO paragraph mode's second swallow, $/ seeded to "\n", grapheme
        clusters, chomp character-wise, UTF-16/32 transcoding      (+44)
  #653  core/module: Module#dup RETURNED THE RECEIVER, Module#ruby2_keywords
        did not exist at all, visibility directives, const_source_location's
        search                                                     (+19)

Measured with scripts/conformance/rubyspec/run.sh against the pinned corpus at
87b1631, 16-way, TIMEOUT=25, three consecutive runs: 22359, 22359, 22358. The
floor is set thirteen below the lowest, the margin rule the last five bumps
used.

A caveat that belongs on this number rather than a later one: issue #655
records that the shim's `should.equal?` asserts NOTHING — it never reaches the
matcher — and it is used 765 times across 328 corpus files. An unknown share of
the total above is therefore vacuous. Fixing it will move the floor in an
unpredictable direction and the result must be re-measured, not assumed. The
number is the best we can currently measure, not a claim that every example
beneath it tests something.

Co-authored-by: Claude Opus 5 <noreply@anthropic.com>
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.

1 participant