Skip to content

fix(profiler): capture nested RPC timings and emit valid speedscope output - #949

Merged
Kingsman-99 merged 2 commits into
Stellar-split:mainfrom
maztah1:feat/849-profiler-rpc-nesting
Sep 28, 2026
Merged

Kingsman-99 merged 2 commits into
Stellar-split:mainfrom
maztah1:feat/849-profiler-rpc-nesting

Conversation

@maztah1

@maztah1 maztah1 commented Sep 26, 2026

Copy link
Copy Markdown
Contributor

What the issue was

#849 asked for a ProfilerSession capturing timings for every SDK operation, with report() producing speedscope v0.6 JSON, exportJSON(path), and "nested RPC call timings" as an explicit requirement. Validation "with ajv" was also an acceptance criterion.

Most of it existed and worked. I verified against the acceptance criteria and found two things that were not actually true.

Gap 1 — rpcCalls was never populated

report() synthesised nested flame-graph frames from entry.rpcCalls, but nothing ever pushed to that array. The RpcCallTiming plumbing, the rpc: frame naming, the nesting logic in report() — all of it operated on a field that was always undefined. So "nested RPC call timings" was dead code, and no flame graph could show where time inside an SDK call actually went.

The fix wraps each client's Soroban RPC server on start() and restores it on stop(). Instrumenting the server rather than individual SDK call sites keeps this to one place, so new SDK methods are profiled for free. Timings route through a per-invocation sink that is restored on every exit path — including thrown errors — which attributes each RPC to the call that issued it and stops concurrent SDK calls from cross-contaminating each other's timings.

RpcCallTiming also gained a timestamp, because report() was previously distributing nested RPC frames evenly across the parent window. That made flame graphs actively misleading about ordering. They're now placed at their real offsets, clamped to the parent bounds.

Gap 2 — the output wasn't actually valid speedscope

Switching the test suite from a hand-rolled validator to real ajv validation (ajv is already a declared dependency — the previous code comment said "replaces ajv without requiring the package to be installed", which was unnecessary) immediately failed:

/ must have required property 'exporter'

The speedscope v0.6 schema requires exporter, and report() never emitted it — so profiles were rejected by speedscope.app itself. The hand-rolled validator missed it because it only asserted the fields its author happened to think of. Fixed by emitting exporter: "@stellar-split/sdk".

This is the clearest argument for the ajv criterion in the issue: the approximate check passed while the real schema check failed.

How it was tested

26 tests in test/profiler.test.ts, up from 21:

  • validateSpeedscopeSchema now compiles the published v0.6 schema with ajv (kept inline so the suite stays hermetic and never fetches over the network).
  • Tests that fail against the previous implementation: an SDK method issuing an RPC call produces a populated rpcCalls entry naming the operation with a non-negative duration; nested rpc: frames appear in the report; the RPC server is restored on stop(); report() validates against the schema and carries exporter.

One subtlety worth noting: the test stubs the RPC endpoint before start(). My first attempt stubbed it inside the profiled method, which replaced the profiler's own wrapper and made capture silently fail — the RPC then made a real network call. The test now documents that ordering constraint.

Full suite: 213 passed, 1 skipped, 0 failed. tsc --noEmit diffed against base — no new errors.

Small client change

StellarSplitClient._instances (marked @internal) is a static Set of live clients, populated in the constructor, so the profiler can find each client's server. Without it the profiler has no way to reach the per-instance RPC objects. Note the prototype patching that was already there remains unchanged — a separate global-patching concern I did not touch here, since it's outside this issue's scope.

closes #849

Two real gaps against the issue's requirements:

1. rpcCalls was never populated. The report() code synthesised nested
   frames from entry.rpcCalls, but nothing ever pushed to that array, so
   'nested RPC call timings' was dead code and no flame graph could show
   where time actually went. Wrap each client's Soroban RPC server on
   start() and restore it on stop(). Instrumenting the server rather than
   individual SDK call sites keeps this to one place, so new SDK methods
   are profiled for free. A per-invocation sink (restored on every exit
   path, including thrown errors) attributes each RPC to the SDK call that
   issued it, and prevents concurrent calls from cross-contaminating.

   RpcCallTiming gains a timestamp so report() can place nested frames at
   their real offsets rather than distributing them evenly, which made
   flame graphs misleading about ordering.

2. The speedscope output was missing the 'exporter' field required by the
   v0.6 schema, so profiles were rejected by speedscope itself. Surfaced by
   switching the test suite from a hand-rolled validator to real ajv
   validation against the published schema — the hand-rolled check only
   asserted the fields it happened to think of.

Closes Stellar-split#849
@drips-wave

drips-wave Bot commented Sep 26, 2026

Copy link
Copy Markdown

@maztah1 Great news! 🎉 Based on an automated assessment of this PR, the linked Wave issue(s) no longer count against your application limits.

You can now already apply to more issues while waiting for a review of this PR. Keep up the great work! 🚀

Learn more about application limits

@Kingsman-99
Kingsman-99 merged commit f3a55f4 into Stellar-split:main Sep 28, 2026
2 checks passed
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.

Implement ProfilerSession with flame-graph-compatible timing output

2 participants