feat(cardinal): add WatchSystemsTiming and ProfileSystems RPCs - #922
feat(cardinal): add WatchSystemsTiming and ProfileSystems RPCs#922ryanditjia wants to merge 24 commits into
Conversation
a701629 to
bc20f63
Compare
ryanditjia
changed the title
ryanditjia
changed the title
07fe4a2 to
2ce4e3c
Compare
| w.world.Tick() | ||
|
|
||
| w.debug.recordTick(w.currentTick.height, timestamp) | ||
| if w.debug != nil { |
There was a problem hiding this comment.
we dont need to check there because the nil check happens on the debug function
There was a problem hiding this comment.
Addressed in b8fe654. This avoids calling time.Since(systemPhaseStartedAt) before the nil-safe recordTick when debug == nil and systemPhaseStartedAt is zero-valued.
| // Tick ECS world. | ||
| var systemPhaseStart time.Time | ||
| if w.debug != nil { | ||
| systemPhaseStart = time.Now() |
There was a problem hiding this comment.
Can we just use timestamp?
I get that it would include the drain time but its very small amount of time and then we are not polluting so much of the tick with debug code?
Not 100% of this just leaving it for you to think about
There was a problem hiding this comment.
I thought of this too, went back and forth until I settled to keep systemPhaseStart, and later renaming it to systemPhaseStartedAt.
Reason: it might seem harmless now (only drain time as the pollutant), but it would be dishonest later if, however unlikely, we add something more other than drain. I’d rather we keep it extremely honest: purely systems.
deb8657 to
f948500
Compare
|
Claude finished @ryanditjia's task in 10m 34s —— View job Code Review —
|
❌ 10 Tests Failed:
View the full list of 10 ❄️ flaky test(s)
To view more test analytics, go to the Test Analytics Dashboard |
f948500 to
a6dc87f
Compare
a0cec02 to
cbcb34b
Compare
![claude[bot]](https://avatars.githubusercontent.com/in/1236702?s=60&v=4){kind=small}
| select { | ||
| case batch := <-ch: | ||
| response := profileBatchToProto(batch) | ||
| if len(response.GetTicks()) == 0 { |
There was a problem hiding this comment.
profileBatchToProto filters out every !Profiled tick, so a batch that mixes pre-subscribe and post-subscribe ticks silently loses the timing data for the pre-subscribe ones — and a batch made entirely of them is dropped here.
SystemsProfile.timing is populated independently of spans, so those ticks could be emitted with an empty spans list instead, giving the Editor a continuous timeline from the moment the stream opens rather than a hole of up to batchSize ticks (~1s at the default perfBatchIntervalSec).
If the hole is deliberate (client can't distinguish "profiled, no systems ran" from "not profiled"), a comment saying so would help — TestProfileBatchToProtoFiltersUnprofiledTicks already asserts that a profiled-but-empty tick stays visible, which makes the two cases ambiguous on the wire.
| for i, sub := range c.subscribers { | ||
| if sub == ch { | ||
| if sub.ch == ch { | ||
| c.subscribers = append(c.subscribers[:i], c.subscribers[i+1:]...) | ||
| c.subscriberCount.Add(-1) | ||
| if sub.requestsSystemSpans { | ||
| c.systemSpanSubscriberCount.Add(-1) | ||
| } | ||
| if len(c.subscribers) == 0 { | ||
| c.pending = c.pending[:0] | ||
| } | ||
| return | ||
| } | ||
| } |
There was a problem hiding this comment.
Two things here:
-
The new
if len(c.subscribers) == 0 { c.pending = c.pending[:0] }branch is the one piece of new state logic in this file with no test. Every collector test either usesbatchSize == 1(sopendingis empty by the timeUnsubscriberuns) or never resubscribes after unsubscribing. A test like:NewCollector(5)→ subscribe → record 3 ticks → unsubscribe → resubscribe → record 5 ticks → assert the batch starts at the post-resubscribe height, would pin the "a new subscriber never sees ticks from a previous session" invariant. -
currentSpansisn't cleared alongsidepending. After the lastProfileSystemsclient disconnects, the collector holds up tolen(systems)TickSpanvalues (including theirSystemNamestrings) until the next profiling session callsStartTick. Small, but it's free to drop here since you already hold the lock.
| @@ -68,23 +88,44 @@ func (c *Collector) RecordSpan(span TickSpan) { | |||
| c.currentSpans = append(c.currentSpans, span) | |||
| } | |||
There was a problem hiding this comment.
Optional, but worth considering given this PR adds a benchmark for exactly this path: currentSpans is touched only by StartTick, RecordSpan, RecordTick, and Reset — all four run on the tick goroutine (Reset via w.reset(), which is driven from resetChan in the run loop). Nothing outside that goroutine ever reads it; the flush copies it under the lock but from the same goroutine.
So the c.mu acquisition per system is protecting single-goroutine state. With 50 systems that's 50 lock/unlock pairs per tick on the profiled path. BenchmarkCollectorCapture/profile_50_systems on this branch reports ~5.0µs/op vs ~119ns for watch_timing, so it's a meaningful slice of the profiling overhead.
If you'd rather keep the mutex for safety, a comment on currentSpans stating the single-writer invariant would at least document why it's cheap to keep (uncontended).
| // StartTick returns whether the next tick should capture per-system spans. The | ||
| // result must be carried through RecordTick so one tick cannot be partially | ||
| // profiled when a profile subscriber connects or disconnects mid-tick. |
There was a problem hiding this comment.
Nit: "the next tick" — the caller applies this to the tick it's about to run, not the following one (cardinal.go:220 assigns it into w.currentTick and w.world.Tick() runs immediately after). "the tick that is about to run" reads truer.
| ts := world.currentTick.timestamp | ||
| startTime := ts.Add(time.Since(ts)) |
There was a problem hiding this comment.
Now that start_offset_ns is measured against SystemPhaseStartedAt (debug.go:238) instead of TickStart, anchoring span endpoints to world.currentTick.timestamp is vestigial — and it actively costs precision.
ts.Add(time.Since(ts)) evaluates to "now" either way, but it launders away the monotonic clock reading whenever the caller passes a wall-only timestamp:
time.Since(ts)on atswith no monotonic reading returns a wall-clock delta.ts.Add(d)on such atsproduces atime.Timewith no monotonic reading.span.StartTime.Sub(ts.SystemPhaseStartedAt)indebug.go:238then has monotonic on only one side, soSubsilently falls back to wall-clock subtraction — vulnerable to NTP steps, which is exactly what thestartOffset < 0clamp is papering over.
This isn't hypothetical: World.Tick is exported and called with wall-only timestamps today, with debug enabled — pkg/plugin/physics2d/test/utils_test.go:57 (time.Unix(int64(i), 0), with Debug: &debug at line 31) and bench_test.go:48.
time.Now() gives monotonic on both sides unconditionally, and drops two world.currentTick reads per system on the hot profiled path:
| ts := world.currentTick.timestamp | |
| startTime := ts.Add(time.Since(ts)) | |
| startTime := time.Now() |
(with the matching endTime := time.Now() and the now-unused ts removed).
| // WatchSystemsTiming streams the time spent executing Cardinal systems each | ||
| // tick without enabling per-system span capture. | ||
| rpc WatchSystemsTiming(WatchSystemsTimingRequest) returns (stream WatchSystemsTimingResponse); | ||
|
|
||
| // ProfileSystems captures per-system spans while the stream is open. | ||
| // Cancelling the stream stops detailed span capture. | ||
| rpc ProfileSystems(ProfileSystemsRequest) returns (stream ProfileSystemsResponse); |
There was a problem hiding this comment.
Both streams can silently drop data, and the .proto — the contract the Editor team actually reads, and the source of the generated TS/C# doc comments — doesn't say so:
- Sends are non-blocking into a
subscriberChanBuf = 4channel (collector.go:11,:146-151), so a client stalled for more than ~4 batches (~4s at the defaultperfBatchIntervalSec = 1) loses batches with no error. ProfileSystemsadditionally suppresses any batch whose ticks are all unprofiled (debug.go:205), so the first ~1s after the stream opens can be a hole.
The Go-side comment on WatchSystemsTiming (debug.go:169) does say "slow clients may miss samples", but ProfileSystems says nothing, and neither statement reaches non-Go clients. Since SystemsTiming.tick_height is monotonic, gaps are detectable — worth stating here that clients must key off tick_height and tolerate discontinuities rather than assuming a contiguous series.
…iptor-introspection-v2
af47efa to
9e0b1d1
Compare
2 participants
Summary
WatchSystemsTimingfor lightweight total system timing.ProfileSystemsfor per-system spans captured only while a profiler is connected.StreamPerfas a deprecated compatibility adapter.Stack
Built on #937.
Verification
go test ./pkg/... -count=1go test -race ./pkg/cardinal/internal/performance -count=1task lintbuf lintbuf breaking --against '.git#branch=origin/main'