Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(studio): detect and report high listener roundtrip latency #8943

Merged
merged 4 commits into from
Mar 17, 2025

Conversation

bjoerge
Copy link
Member

@bjoerge bjoerge commented Mar 14, 2025

Description

We want to track e2e listener latency, this reports a telemetry event every time we detect >1s latency from after an edit action request has completed until we receive an event with a corresponding transaction id back from the listener.

What to review

I've tried to implement this as cleanly as possible to make it easy to delete the code path for tracking latency at some point in the future. The implementation follows the same pattern as the "document desynced" event in the document store takes a callback that will be called with latency, shard identifier and transaction id.

Testing

To see that the the Studio sends the event, start with SANITY_STUDIO_DEBUG_TELEMETRY=true pnpm dev which will log the telemetry events to the console.

This, combined with network throttling should likely cause some "High Listener Latency Detected"-events to be reported

Notes for release

n/a

@bjoerge bjoerge force-pushed the telemetry-listener-latency branch from 2a882bb to d8338e8 Compare March 14, 2025 14:24
Copy link

vercel bot commented Mar 14, 2025

The latest updates on your projects. Learn more about Vercel for Git ↗︎

Name Status Preview Comments Updated (UTC)
page-building-studio ✅ Ready (Inspect) Visit Preview 💬 Add feedback Mar 17, 2025 4:27pm
performance-studio ✅ Ready (Inspect) Visit Preview 💬 Add feedback Mar 17, 2025 4:27pm
test-studio ✅ Ready (Inspect) Visit Preview 💬 Add feedback Mar 17, 2025 4:27pm
2 Skipped Deployments
Name Status Preview Comments Updated (UTC)
studio-workshop ⬜️ Ignored (Inspect) Visit Preview Mar 17, 2025 4:27pm
test-next-studio ⬜️ Ignored (Inspect) Mar 17, 2025 4:27pm

Copy link
Contributor

No changes to documentation

Copy link
Contributor

github-actions bot commented Mar 14, 2025

Coverage Report

Status Category Percentage Covered / Total
🔵 Lines 42.16% 54661 / 129646
🔵 Statements 42.16% 54661 / 129646
🔵 Functions 47.09% 2741 / 5820
🔵 Branches 79.41% 10225 / 12876
File Coverage
File Stmts Branches Functions Lines Uncovered Lines
Changed Files
packages/sanity/src/core/store/_legacy/datastores.ts 77.95% 90.9% 70% 77.95% 151, 159-160, 166-173, 273-290, 295-313, 318-334
packages/sanity/src/core/store/_legacy/document/document-store.ts 49.6% 57.14% 33.33% 49.6% 39-40, 42-43, 45-46, 147-151, 153-160, 162-163, 169-176, 178-185, 190-194, 196-214, 216-218
packages/sanity/src/core/store/_legacy/document/getPairListener.ts 76.1% 96.66% 75% 76.1% 69-82, 96-97, 131, 146-147, 150-163, 186, 195, 202-212
packages/sanity/src/core/store/_legacy/document/document-pair/checkoutPair.ts 70.07% 92.5% 83.33% 70.07% 101-102, 113-114, 146, 208-218, 294-299, 334-398
packages/sanity/src/core/store/_legacy/document/document-pair/consistencyStatus.ts 35.71% 100% 100% 35.71% 21-38
packages/sanity/src/core/store/_legacy/document/document-pair/documentEvents.ts 47.36% 100% 100% 47.36% 16-25
packages/sanity/src/core/store/_legacy/document/document-pair/editOperations.ts 100% 100% 100% 100%
packages/sanity/src/core/store/_legacy/document/document-pair/editState.ts 21.62% 100% 100% 21.62% 56-119
packages/sanity/src/core/store/_legacy/document/document-pair/memoizedPair.ts 100% 85.71% 100% 100%
packages/sanity/src/core/store/_legacy/document/document-pair/operationArgs.ts 89.83% 85.71% 100% 89.83% 53-55, 59-61
packages/sanity/src/core/store/_legacy/document/document-pair/operationEvents.ts 53.48% 40% 0% 53.48% 50-52, 80-91, 97-103, 152-190, 201, 204
packages/sanity/src/core/store/_legacy/document/document-pair/remoteSnapshots.ts 42.85% 100% 100% 42.85% 15-26
packages/sanity/src/core/store/_legacy/document/document-pair/snapshotPair.ts 100% 83.33% 100% 100%
packages/sanity/src/core/store/_legacy/document/document-pair/validation.ts 88.57% 80% 100% 88.57% 44-49
packages/sanity/src/core/store/_legacy/grants/documentPairPermissions.ts 70.43% 52.77% 100% 70.43% 26-27, 65-75, 78-81, 90-106, 128-140, 143-158, 161-162, 213-214, 258-261
Generated in workflow #32431 for commit 51d4792 by the Vitest Coverage Report Action

Copy link
Contributor

github-actions bot commented Mar 14, 2025

⚡️ Editor Performance Report

Updated Mon, 17 Mar 2025 16:50:13 GMT

Benchmark reference
latency of sanity@latest
experiment
latency of this branch
Δ (%)
latency difference
article (title) 20.2 efps (50ms) 19.4 efps (52ms) +2ms (+4.0%)
article (body) 63.3 efps (16ms) 63.3 efps (16ms) -0ms (-/-%)
article (string inside object) 23.3 efps (43ms) 21.3 efps (47ms) +4ms (+9.3%)
article (string inside array) 21.3 efps (47ms) 19.6 efps (51ms) +4ms (+8.5%)
recipe (name) 40.0 efps (25ms) 30.3 efps (33ms) +8ms (+32.0%) 🔴
recipe (description) 62.5 efps (16ms) 32.3 efps (31ms) +15ms (+93.8%) 🔴
recipe (instructions) 99.9+ efps (5ms) 99.9+ efps (5ms) -0ms (-/-%)
synthetic (title) 18.9 efps (53ms) 16.7 efps (60ms) +7ms (+13.2%)
synthetic (string inside object) 19.0 efps (53ms) 16.9 efps (59ms) +7ms (+12.4%)

efps — editor "frames per second". The number of updates assumed to be possible within a second.

Derived from input latency. efps = 1000 / input_latency

Detailed information

🏠 Reference result

The performance result of sanity@latest

Benchmark latency p75 p90 p99 blocking time test duration
article (title) 50ms 65ms 90ms 402ms 932ms 12.3s
article (body) 16ms 18ms 24ms 103ms 217ms 6.2s
article (string inside object) 43ms 46ms 52ms 224ms 330ms 8.1s
article (string inside array) 47ms 49ms 57ms 301ms 553ms 7.8s
recipe (name) 25ms 27ms 28ms 70ms 1ms 9.1s
recipe (description) 16ms 17ms 18ms 20ms 0ms 4.0s
recipe (instructions) 5ms 6ms 8ms 11ms 0ms 3.2s
synthetic (title) 53ms 56ms 65ms 239ms 981ms 13.1s
synthetic (string inside object) 53ms 56ms 64ms 246ms 900ms 8.4s

🧪 Experiment result

The performance result of this branch

Benchmark latency p75 p90 p99 blocking time test duration
article (title) 52ms 82ms 102ms 424ms 946ms 13.3s
article (body) 16ms 18ms 30ms 229ms 298ms 6.2s
article (string inside object) 47ms 49ms 53ms 234ms 384ms 7.7s
article (string inside array) 51ms 56ms 66ms 235ms 703ms 8.2s
recipe (name) 33ms 35ms 39ms 81ms 38ms 9.1s
recipe (description) 31ms 32ms 35ms 41ms 12ms 6.3s
recipe (instructions) 5ms 7ms 8ms 23ms 0ms 3.2s
synthetic (title) 60ms 65ms 122ms 406ms 2117ms 14.9s
synthetic (string inside object) 59ms 62ms 70ms 291ms 2227ms 9.9s

📚 Glossary

column definitions

  • benchmark — the name of the test, e.g. "article", followed by the label of the field being measured, e.g. "(title)".
  • latency — the time between when a key was pressed and when it was rendered. derived from a set of samples. the median (p50) is shown to show the most common latency.
  • p75 — the 75th percentile of the input latency in the test run. 75% of the sampled inputs in this benchmark were processed faster than this value. this provides insight into the upper range of typical performance.
  • p90 — the 90th percentile of the input latency in the test run. 90% of the sampled inputs were faster than this. this metric helps identify slower interactions that occurred less frequently during the benchmark.
  • p99 — the 99th percentile of the input latency in the test run. only 1% of sampled inputs were slower than this. this represents the worst-case scenarios encountered during the benchmark, useful for identifying potential performance outliers.
  • blocking time — the total time during which the main thread was blocked, preventing user input and UI updates. this metric helps identify performance bottlenecks that may cause the interface to feel unresponsive.
  • test duration — how long the test run took to complete.

shard?: string
}
export const HighListenerLatencyOccurred = defineEvent<Samples>({
name: 'High Listener Latency Detected',
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

👍

sgulseth
sgulseth previously approved these changes Mar 14, 2025
Copy link
Member

@sgulseth sgulseth left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM from rxjs perspective, but I have limited insight into general behavior in studio paths 🙂

@@ -155,6 +156,19 @@ export function useDocumentStore(): DocumentStore {
[telemetry],
)

const handleReportLatency = useCallback(
(event: LatencyReportEvent) => {
if (event.latencyMs > 1000) {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Move into constant(Could belong with the telemetry event? 🤔) and maybe describe why and what this number is? As a reference and help for our future selves 🙃

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good call! Extracted to a const in 5f918c7

Copy link
Contributor

@juice49 juice49 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks, this looks great! I was able to see the telemetry logs client-side as expected during my testing.

@bjoerge bjoerge merged commit 224cdb5 into next Mar 17, 2025
60 checks passed
@bjoerge bjoerge deleted the telemetry-listener-latency branch March 17, 2025 16:49
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.

None yet

4 participants