Skip to content

Profiling that names Rayfall code, not C #592

Description

@vbmithr

Summary

There is no way to find out which Rayfall expression is spending a running
process's CPU. perf sees only the C implementation: every Rayfall frame is
inside vm_exec or ray_eval, so a profile says which primitive is hot and
never which call site. On a script of any size that is the difference
between a diagnosis and a guess.

What it looks like today

A 30 s perf record --call-graph fp of a production service (a market-data
book owner, ~1000 lines of Rayfall, 64% CPU) gives:

33.48%  hash_row_keys
13.62%  ray_vec_is_null
 9.04%  gather_fn
 2.42%  exec_antijoin_flat
 1.67%  join_count_fn

with 72% of samples under worker_loop (the query pool) and the rest under
vm_exec ← eval_payload ← ipc_read_payload. Correct, and it does say "joins
are the problem". It does not say which of the 31 joins in the script, and the
pool frames carry no caller at all.

Recovering that took benchmarking each candidate offline against synthetic
tables sized to production — a working afternoon to establish something the
process itself knew at every instant. The answer, once found, was a single
left-join whose cost was the left table rather than its two-row right side.

Why this looks achievable

The mapping this needs already exists in the tree, for error traces:

  • ray_bc_dbg_get(ray_t* dbg, int32_t ip) in src/lang/eval.h returns the
    source span for a bytecode IP.
  • eval.h documents an error-trace frame list of [span, filename, fn_name, source], so a runtime error already prints file:line:col and the
    enclosing lambda.
  • core/profile.h already provides ray_profile_now_ns, and qstats.h
    already accumulates per-query busy_ns on profile spans.

So the VM can already answer "which Rayfall span is executing" at an arbitrary
IP. What is missing is something that asks it on a timer and aggregates.

What we are asking for

A sampling profiler inside the VM, in rough order of usefulness:

  1. .sys.profile.start / .sys.profile.stop, sampling the active Rayfall
    frame on a timer (SIGPROF or a sampling thread), returning a table of
    file, line, fn, self_ms, total_ms, samples. A table is the
    right output for a database — it can be sorted, grouped and joined against
    without leaving the language.
  2. Pool attribution. Work dispatched to the query pool should be
    attributable to the Rayfall span that dispatched it. In our profile that is
    72% of samples with no caller, which is most of the signal.
  3. A perf bridge, if it is cheap. Emitting /tmp/perf-<pid>.map does not
    apply to a bytecode VM, but if vm_exec can keep the current span in a
    thread-local that a perf probe or a USDT point can read, existing
    native-side tooling keeps working and the two profiles can be read
    together.

(1) alone would have turned our afternoon into one query.

Note

The same service's earlier hot spot was fixed by bc350ddc (the while
form, issue #588), and that one was also found by benchmarking rather than by
profiling. Two for two.


Measured on rayforce 2.6.2 (the build carrying bc350ddc, the while form).

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions