Capture-stage telemetry: per-stage timings across the screenshot pipeline - #5871
Draft
lukemelia wants to merge 5 commits into
Draft
Capture-stage telemetry: per-stage timings across the screenshot pipeline#5871lukemelia wants to merge 5 commits into
lukemelia wants to merge 5 commits into
Conversation
Contributor
Grafana previewPreview deployed for 1 dashboard in the staging Grafana.
Dashboards: Preview is torn down automatically when this PR is closed or merged. (Run: https://github.com/cardstack/boxel/actions/runs/33033723155) |
Contributor
Observability diff (vs staging)Show diffdiff --git a/tmp/committed-canon.2H03QY/dashboards/boxel-status/screenshot-captures.json b/tmp/committed-canon.2H03QY/dashboards/boxel-status/screenshot-captures.json
new file mode 100644
index 0000000..c6d5c29
--- /dev/null
+++ b/tmp/committed-canon.2H03QY/dashboards/boxel-status/screenshot-captures.json
@@ -0,0 +1,851 @@
+{
+ "apiVersion": "dashboard.grafana.app/v1beta1",
+ "kind": "Dashboard",
+ "metadata": {
+ "annotations": {
+ "grafana.app/folder": "defd2d156sav4d"
+ },
+ "name": "boxel-screenshot-perf"
+ },
+ "spec": {
+ "annotations": {
+ "list": [
+ {
+ "builtIn": 1,
+ "datasource": {
+ "type": "grafana",
+ "uid": "-- Grafana --"
+ },
+ "enable": true,
+ "hide": true,
+ "iconColor": "rgba(0, 211, 255, 1)",
+ "name": "Annotations & Alerts",
+ "type": "dashboard"
+ }
+ ]
+ },
+ "description": "Screenshot capture pipeline stage telemetry (channel boxel:screenshot-perf): request records from the serving surfaces (realm-server) and capture records from the screenshot-card worker task, joined by jobId/correlationId. The same capture breakdown is persisted on media_cache_ledger.diagnostics for SQL reads.",
+ "editable": true,
+ "fiscalYearStartMonth": 0,
+ "graphTooltip": 1,
+ "links": [],
+ "panels": [
+ {
+ "collapsed": false,
+ "gridPos": {
+ "h": 1,
+ "w": 24,
+ "x": 0,
+ "y": 0
+ },
+ "panels": [],
+ "title": "Overview",
+ "type": "row"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "Requests on the two capture surfaces that touched capture work: hits, renders, 503s, 403s. Addressing 404s/400s never emit.",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "unit": "short"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 4,
+ "w": 6,
+ "x": 0,
+ "y": 1
+ },
+ "options": {
+ "colorMode": "none",
+ "graphMode": "area",
+ "reduceOptions": {
+ "calcs": [
+ "lastNotNull"
+ ],
+ "fields": "",
+ "values": false
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "sum(count_over_time({service=\"realm-server\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"request\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" [5m])) or vector(0)",
+ "queryType": "range",
+ "refId": "A"
+ }
+ ],
+ "title": "Capture-relevant requests (5m)",
+ "type": "stat"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "screenshot-card jobs that finished (any status).",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "unit": "short"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 4,
+ "w": 6,
+ "x": 6,
+ "y": 1
+ },
+ "options": {
+ "colorMode": "none",
+ "graphMode": "area",
+ "reduceOptions": {
+ "calcs": [
+ "lastNotNull"
+ ],
+ "fields": "",
+ "values": false
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "sum(count_over_time({service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" [5m])) or vector(0)",
+ "queryType": "range",
+ "refId": "A"
+ }
+ ],
+ "title": "Captures run (5m)",
+ "type": "stat"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "hit = ledger hit with zero Chrome work; rendered = capture completed within the sync wait; timeout/congested = 503 + Retry-After; gated = 403.",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "custom": {
+ "drawStyle": "line",
+ "fillOpacity": 8,
+ "lineWidth": 1,
+ "showPoints": "never",
+ "spanNulls": true
+ },
+ "unit": "short"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 8,
+ "w": 12,
+ "x": 12,
+ "y": 1
+ },
+ "options": {
+ "legend": {
+ "displayMode": "list",
+ "placement": "bottom",
+ "showLegend": true
+ },
+ "tooltip": {
+ "mode": "multi",
+ "sort": "desc"
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "sum by (outcome) (count_over_time({service=\"realm-server\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"request\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" [$__interval]))",
+ "legendFormat": "{{outcome}}",
+ "queryType": "range",
+ "refId": "A"
+ }
+ ],
+ "title": "Requests by outcome",
+ "type": "timeseries"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "What callers experienced end-to-end on the serving surfaces, all outcomes.",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "custom": {
+ "drawStyle": "line",
+ "fillOpacity": 8,
+ "lineWidth": 1,
+ "showPoints": "never",
+ "spanNulls": true
+ },
+ "unit": "ms"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 8,
+ "w": 12,
+ "x": 0,
+ "y": 5
+ },
+ "options": {
+ "legend": {
+ "displayMode": "list",
+ "placement": "bottom",
+ "showLegend": true
+ },
+ "tooltip": {
+ "mode": "multi",
+ "sort": "desc"
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.50, {service=\"realm-server\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"request\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap totalMs [$__interval]) by ()",
+ "legendFormat": "p50",
+ "queryType": "range",
+ "refId": "A"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=\"realm-server\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"request\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap totalMs [$__interval]) by ()",
+ "legendFormat": "p95",
+ "queryType": "range",
+ "refId": "B"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.99, {service=\"realm-server\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"request\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap totalMs [$__interval]) by ()",
+ "legendFormat": "p99",
+ "queryType": "range",
+ "refId": "C"
+ }
+ ],
+ "title": "Request wall-clock (totalMs)",
+ "type": "timeseries"
+ },
+ {
+ "collapsed": false,
+ "gridPos": {
+ "h": 1,
+ "w": 24,
+ "x": 0,
+ "y": 13
+ },
+ "panels": [],
+ "title": "Capture stage breakdown",
+ "type": "row"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "Where a capture's wall-clock goes, p95 per stage. queueWaitMs is enqueue→claim; launchMs is page acquire in the pool; renderMs is the server-observed render (nav/settle/imagePaint/screenshot are its components); persistMs is the MediaCache put.",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "custom": {
+ "drawStyle": "line",
+ "fillOpacity": 8,
+ "lineWidth": 1,
+ "showPoints": "never",
+ "spanNulls": true
+ },
+ "unit": "ms"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 9,
+ "w": 24,
+ "x": 0,
+ "y": 14
+ },
+ "options": {
+ "legend": {
+ "displayMode": "list",
+ "placement": "bottom",
+ "showLegend": true
+ },
+ "tooltip": {
+ "mode": "multi",
+ "sort": "desc"
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap queueWaitMs [$__interval]) by ()",
+ "legendFormat": "queueWaitMs",
+ "queryType": "range",
+ "refId": "A"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap permissionsMs [$__interval]) by ()",
+ "legendFormat": "permissionsMs",
+ "queryType": "range",
+ "refId": "B"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap launchMs [$__interval]) by ()",
+ "legendFormat": "launchMs",
+ "queryType": "range",
+ "refId": "C"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap renderMs [$__interval]) by ()",
+ "legendFormat": "renderMs",
+ "queryType": "range",
+ "refId": "D"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap navMs [$__interval]) by ()",
+ "legendFormat": "navMs",
+ "queryType": "range",
+ "refId": "E"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap settleMs [$__interval]) by ()",
+ "legendFormat": "settleMs",
+ "queryType": "range",
+ "refId": "F"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap imagePaintMs [$__interval]) by ()",
+ "legendFormat": "imagePaintMs",
+ "queryType": "range",
+ "refId": "G"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap screenshotMs [$__interval]) by ()",
+ "legendFormat": "screenshotMs",
+ "queryType": "range",
+ "refId": "H"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap decodeMs [$__interval]) by ()",
+ "legendFormat": "decodeMs",
+ "queryType": "range",
+ "refId": "I"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap persistMs [$__interval]) by ()",
+ "legendFormat": "persistMs",
+ "queryType": "range",
+ "refId": "J"
+ }
+ ],
+ "title": "Capture latency by stage (p95)",
+ "type": "timeseries"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "A deep serialized lane shows as queue wait; a slow render shows on the render side.",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "custom": {
+ "drawStyle": "line",
+ "fillOpacity": 8,
+ "lineWidth": 1,
+ "showPoints": "never",
+ "spanNulls": true
+ },
+ "unit": "ms"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 8,
+ "w": 8,
+ "x": 0,
+ "y": 23
+ },
+ "options": {
+ "legend": {
+ "displayMode": "list",
+ "placement": "bottom",
+ "showLegend": true
+ },
+ "tooltip": {
+ "mode": "multi",
+ "sort": "desc"
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap queueWaitMs [$__interval]) by ()",
+ "legendFormat": "queueWaitMs",
+ "queryType": "range",
+ "refId": "A"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap prerenderMs [$__interval]) by ()",
+ "legendFormat": "prerenderMs (incl. transport)",
+ "queryType": "range",
+ "refId": "B"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap renderMs [$__interval]) by ()",
+ "legendFormat": "renderMs (server-observed)",
+ "queryType": "range",
+ "refId": "C"
+ }
+ ],
+ "title": "Queue wait vs render (p95)",
+ "type": "timeseries"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "tabReused=false is the cold-start tax; true with a large launch is pool contention.",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "custom": {
+ "drawStyle": "line",
+ "fillOpacity": 8,
+ "lineWidth": 1,
+ "showPoints": "never",
+ "spanNulls": true
+ },
+ "unit": "ms"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 8,
+ "w": 8,
+ "x": 8,
+ "y": 23
+ },
+ "options": {
+ "legend": {
+ "displayMode": "list",
+ "placement": "bottom",
+ "showLegend": true
+ },
+ "tooltip": {
+ "mode": "multi",
+ "sort": "desc"
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap launchMs [$__interval]) by (tabReused)",
+ "legendFormat": "tabReused={{tabReused}}",
+ "queryType": "range",
+ "refId": "A"
+ }
+ ],
+ "title": "Page acquire by warm/cold tab (p95 launchMs)",
+ "type": "timeseries"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "uploaded vs deduped (bytes already stored under the content key) vs skipped/failed.",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "custom": {
+ "drawStyle": "line",
+ "fillOpacity": 8,
+ "lineWidth": 1,
+ "showPoints": "never",
+ "spanNulls": true
+ },
+ "unit": "short"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 8,
+ "w": 8,
+ "x": 16,
+ "y": 23
+ },
+ "options": {
+ "legend": {
+ "displayMode": "list",
+ "placement": "bottom",
+ "showLegend": true
+ },
+ "tooltip": {
+ "mode": "multi",
+ "sort": "desc"
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "sum by (persistOutcome) (count_over_time({service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" [$__interval]))",
+ "legendFormat": "{{persistOutcome}}",
+ "queryType": "range",
+ "refId": "A"
+ }
+ ],
+ "title": "Persist outcome",
+ "type": "timeseries"
+ },
+ {
+ "collapsed": false,
+ "gridPos": {
+ "h": 1,
+ "w": 24,
+ "x": 0,
+ "y": 31
+ },
+ "panels": [],
+ "title": "Slices",
+ "type": "row"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "custom": {
+ "drawStyle": "line",
+ "fillOpacity": 8,
+ "lineWidth": 1,
+ "showPoints": "never",
+ "spanNulls": true
+ },
+ "unit": "ms"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 9,
+ "w": 12,
+ "x": 0,
+ "y": 32
+ },
+ "options": {
+ "legend": {
+ "displayMode": "list",
+ "placement": "bottom",
+ "showLegend": true
+ },
+ "tooltip": {
+ "mode": "multi",
+ "sort": "desc"
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap totalMs [$__interval]) by (realmURL)",
+ "legendFormat": "{{realmURL}}",
+ "queryType": "range",
+ "refId": "A"
+ }
+ ],
+ "title": "Capture wall-clock p95 by realm",
+ "type": "timeseries"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "description": "get-dsl is the GET _screenshot/ DSL route; post is POST /_screenshot-card.",
+ "fieldConfig": {
+ "defaults": {
+ "color": {
+ "mode": "palette-classic"
+ },
+ "custom": {
+ "drawStyle": "line",
+ "fillOpacity": 8,
+ "lineWidth": 1,
+ "showPoints": "never",
+ "spanNulls": true
+ },
+ "unit": "ms"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 9,
+ "w": 12,
+ "x": 12,
+ "y": 32
+ },
+ "options": {
+ "legend": {
+ "displayMode": "list",
+ "placement": "bottom",
+ "showLegend": true
+ },
+ "tooltip": {
+ "mode": "multi",
+ "sort": "desc"
+ }
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "quantile_over_time(0.95, {service=\"realm-server\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"request\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap totalMs [$__interval]) by (surface)",
+ "legendFormat": "{{surface}}",
+ "queryType": "range",
+ "refId": "A"
+ }
+ ],
+ "title": "Request wall-clock p95 by surface",
+ "type": "timeseries"
+ },
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "fieldConfig": {
+ "defaults": {
+ "unit": "ms"
+ },
+ "overrides": []
+ },
+ "gridPos": {
+ "h": 10,
+ "w": 24,
+ "x": 0,
+ "y": 41
+ },
+ "options": {
+ "showHeader": true,
+ "sortBy": [
+ {
+ "desc": true,
+ "displayName": "Value"
+ }
+ ]
+ },
+ "targets": [
+ {
+ "datasource": {
+ "type": "loki",
+ "uid": "loki"
+ },
+ "expr": "topk(20, max by (sourceURL) (max_over_time({service=~\"realm-server|worker\", env=\"$env\"} |= \"boxel:screenshot-perf\" | json | line_format \"{{ if .log }}{{ .log }}{{ else }}{{ __line__ }}{{ end }}\" | json | channel=\"boxel:screenshot-perf\" | eventType=\"capture\" | realmURL=~\".*${realm}.*\" | surface=~\"$surface\" | unwrap totalMs [$__range])))",
+ "instant": true,
+ "queryType": "instant",
+ "refId": "A"
+ }
+ ],
+ "title": "Slowest captures by card (range)",
+ "transformations": [
+ {
+ "id": "organize",
+ "options": {
+ "excludeByName": {
+ "Time": true
+ }
+ }
+ }
+ ],
+ "type": "table"
+ }
+ ],
+ "preload": false,
+ "refresh": "1m",
+ "schemaVersion": 41,
+ "tags": [
+ "screenshot",
+ "captures",
+ "media-cache"
+ ],
+ "templating": {
+ "list": [
+ {
+ "hide": 2,
+ "name": "env",
+ "query": "__ENV__",
+ "skipUrlSync": true,
+ "type": "constant"
+ },
+ {
+ "current": {
+ "text": "",
+ "value": ""
+ },
+ "description": "Substring match on the capture's realm URL; empty = all realms.",
+ "hide": 0,
+ "name": "realm",
+ "options": [
+ {
+ "selected": true,
+ "text": "",
+ "value": ""
+ }
+ ],
+ "query": "",
+ "type": "textbox"
+ },
+ {
+ "allValue": ".*",
+ "current": {
+ "selected": true,
+ "text": "All",
+ "value": "$__all"
+ },
+ "description": "Which serving surface enqueued the work.",
+ "hide": 0,
+ "includeAll": true,
+ "multi": false,
+ "name": "surface",
+ "options": [
+ {
+ "selected": true,
+ "text": "All",
+ "value": "$__all"
+ },
+ {
+ "selected": false,
+ "text": "get-dsl",
+ "value": "get-dsl"
+ },
+ {
+ "selected": false,
+ "text": "post",
+ "value": "post"
+ }
+ ],
+ "query": "get-dsl,post",
+ "type": "custom"
+ }
+ ]
+ },
+ "time": {
+ "from": "now-6h",
+ "to": "now"
+ },
+ "timepicker": {},
+ "timezone": "browser",
+ "title": "Screenshot Capture Performance"
+ }
+}
(Run: https://github.com/cardstack/boxel/actions/runs/33033723152) |
lukemelia
marked this pull request as draft
August 24, 2026 21:15
Contributor
Preview deploymentsHost Test Results 1 files ±0 1 suites ±0 2h 13m 22s ⏱️ + 3m 28s Results for commit 9e11309. ± Comparison against earlier commit cf0f802. Realm Server Test Results 1 files ±0 1 suites ±0 18m 42s ⏱️ +37s Results for commit 9e11309. ± Comparison against earlier commit cf0f802. |
lukemelia
force-pushed
the
cs-12629-capture-stage-telemetry-per-stage-timings-across-the
branch
from
August 24, 2026 22:03
06e15a2 to
0170688
Compare
One correlated per-capture timing record spanning the three processes a capture crosses: - boxel:screenshot-perf log channel (JSON-object lines, flat *Ms fields for LogQL unwrap): 'request' events from the two serving surfaces (GET _screenshot/ DSL, POST /_screenshot-card) with generation/ledger/gate/ precheck/enqueue/job-wait/serve stage clocks and an outcome (hit, rendered, congested, timeout, gated, error); 'capture' events from the screenshot-card worker task with queue wait, permissions, prerender breakdown, decode, and persist stages. - Correlation: the surface's x-boxel-logging-correlation-id rides the job args to the worker; the worker forwards jobId.reservationId to the prerender server as x-boxel-job-id; the prerender request id comes back on response.meta — the record carries all three. - JobInfo.queueWaitMs: the claim-time queue-wait the queue already computed is handed to handlers instead of only logged. - Prerender: captureScreenshot times nav/settle/imagePaint/screenshot and stamps them into meta.diagnostics (the one timing surface that survives the remote wire); prerenderScreenshot now records tabReused/priority the way runCommand does. - Persist: MediaCacheAdapter.put reports dedupe-on-write vs upload; putMedia returns it; the capture record lands on the new media_cache_ledger.diagnostics jsonb column (additive migration) so a completed capture's breakdown is readable by SQL after logs age out. - Grafana: new boxel-screenshot-perf dashboard (stage p95s, queue-wait vs render, warm/cold acquire, persist outcomes, realm/surface slices). - Tests: DSL suite covers rendered/hit/gated/congested/timeout/dedupe telemetry, the ledger diagnostics write, and pins the 503 contract the host service worker absorbs (integer Retry-After, CORS-exposed). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
lukemelia
force-pushed
the
cs-12629-capture-stage-telemetry-per-stage-timings-across-the
branch
from
August 25, 2026 20:43
0170688 to
0fc300b
Compare
lukemelia
changed the base branch from
cs-12561-post-screenshot-card-persists-captures-to-mediacache
to
main
August 25, 2026 20:43
…e-telemetry-per-stage-timings-across-the # Conflicts: # packages/realm-server/prerender/utils.ts
…ings-across-the Resolves conflicts with the envelope screenshot work (#5880): the capture telemetry's per-stage timers move into the renderFor structure, accumulating nav/settle/imagePaint across per-envelope re-renders and counting viewport switches + CDP screenshots as the capture stage so the stages stay disjoint. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
lukemelia
commented
Aug 27, 2026
lukemelia
left a comment
lukemelia
left a comment
Contributor
Author
There was a problem hiding this comment.
[Claude Code 🤖] This review went after the telemetry plumbing: the request/capture event construction on both serving surfaces, the correlation-id join across the three processes, the prerender-timing hand-off through meta.diagnostics, the dedupe-on-write reporting, the ledger persistence, and how the change lands in captureScreenshot. It did not exercise the Grafana dashboard or the remote-prerenderer wire path end-to-end (the in-process path is covered by tests).
No blocking issues — the telemetry is additive and the capture path's observable behavior is unchanged. Four non-blocking items: two inline, two artifact notes below.
totalMsvsqueueWaitMsoncaptureevents — see the thread onScreenshotPerfBase.totalMsinscreenshot-perf.ts.- The "minus the envelope fields" claim doesn't match the ledger write — see the thread on the module header comment in
screenshot-perf.ts. - Stale SQLite schema snapshot.
packages/host/config/schema/1787603632440_schema.sqlis named for this PR's migration, but itsmedia_cache_ledgertable carries nodiagnosticscolumn — jsonb regenerates asBLOB, and it's present on the other diagnostics tables, so this snapshot was dumped from a DB without the migration applied. Non-blocking: the host build only checks the snapshot's timestamp prefix, and nothing in the in-browser SQLite writes that column. Re-runningpnpm make-schemaagainst a migrated DB would make the committed snapshot truthful and spare the next person a confusing diff. screenshotCaptureMswording. TheRenderTimeoutDiagnosticscomment inindex.tscalls it "the CDP screenshot call," but for a multi-entry batch the field measures the whole capture loop (per-entry viewport switch + paint wait + screenshot), not justpage.screenshot; it's exact only for the singular case. Worth a reword. Non-blocking.
Comment on lines
+78
to
+81
| // Wall-clock of the whole event: request receipt → response for `request` | ||
| // events, job claim → job return for `capture` events. Stage fields sum to | ||
| // at most this; the remainder is unattributed overhead. | ||
| totalMs: number; |
Contributor
Author
There was a problem hiding this comment.
[Claude Code 🤖] The invariant here — "stage fields sum to at most this" — holds for request events but breaks for capture events, because of queueWaitMs. In tasks/screenshot-card.ts, taskStart is set after the job is claimed, so a capture's totalMs is claim→return; queueWaitMs measures enqueue→claim, entirely before taskStart. A capture that waited behind a backlog therefore reports a queueWaitMs larger than the whole totalMs it's presented as a slice of, and a dashboard stacking stages against totalMs mis-attributes queue wait. The request-side test checks the sum only for request events, so nothing flags it.
Pick one: fold queue wait into the capture's totalMs (queueWaitMs + (Date.now() - taskStart)), or keep totalMs as the claim→return window and carve queueWaitMs out of the "stages sum to at most totalMs" statement (it's a pre-claim clock from a different process). Non-blocking — a semantics call, not a fix.
Contributor
Author
There was a problem hiding this comment.
[Claude Code 🤖] Fixed in 9e11309 — kept totalMs as the claim→return window and carved queueWaitMs out of the invariant: the comment now states it clocks enqueue→claim, before the claim-start of totalMs, so it sits outside the sum. Chose this over folding queue wait into totalMs so the field stays the task’s own execution window and the queue clock (a different process) reads as its own field.
| // | ||
| // - `capture` — emitted by the worker's `screenshot-card` task when a job | ||
| // finishes: queue wait, the prerender stage breakdown, and the persist | ||
| // leg. The same record (minus the envelope fields) is persisted onto the |
Contributor
Author
There was a problem hiding this comment.
[Claude Code 🤖] "minus the envelope fields" doesn't match what's persisted: tasks/screenshot-card.ts passes the whole event to updateMediaCacheDiagnostics ({ ...event }), so the ledger row's diagnostics keeps eventType, surface, correlationId, jobId, reservationId, totalMs, and the rest — and the DSL test asserts diagnostics.correlationId === 'corr-dsl-1', which pins the envelope onto the row. Either drop the "(minus the envelope fields)" clause, or strip the envelope keys before the ledger write if the row is meant to hold only the breakdown. Non-blocking.
Contributor
Author
There was a problem hiding this comment.
[Claude Code 🤖] Fixed in 9e11309 — dropped the “(minus the envelope fields)” clause. The ledger row keeps the whole record, envelope included (the DSL test pins correlationId on it), so the comment now matches the write.
- screenshot-perf.ts: `totalMs`'s "stages sum to at most this" invariant excludes a capture event's `queueWaitMs`, which clocks enqueue → claim and so lands before the claim-start of `totalMs`; state the exception. - screenshot-perf.ts: the ledger `diagnostics` row keeps the whole capture record, envelope fields included (a test pins `correlationId` on the row), so drop the "minus the envelope fields" clause. - index.ts: `screenshotCaptureMs` measures the whole capture loop — the lone `page.screenshot` for a singular capture, or each entry's viewport switch + screenshot for a batch — not just the CDP screenshot call. - Add the `media_cache_ledger.diagnostics` column (jsonb → BLOB) to the generated sqlite schema snapshot, which the regen commit omitted. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_014GsYGsuCqHJz9GAti4jheG
Contributor
Author
|
[Claude Code 🤖] The two body-level notes from the review are addressed in 9e11309:
|
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What this does
Answers "why did this screenshot take N ms?" with one structured, correlated per-capture record that attributes the wall-clock across every stage of the capture pipeline — queue, prerender pool, headless-Chrome render, MediaCache persist, and serve.
Emission (both existing patterns, each where it's strongest)
Log channel `boxel:screenshot-perf` (mirrors `boxel:client-perf`): one JSON-object line per event with an explicit `channel` field and flat `*Ms` duration fields, so Grafana reads it with the standard FireLens double-parse and any stage can be `unwrap`ped directly. Two event types:
Ledger diagnostics: the same capture record is persisted onto a new `media_cache_ledger.diagnostics` JSONB column (additive migration, same pattern as `boxel_index.diagnostics`), so a completed capture's breakdown is readable by SQL after the logs age out.
Correlation (three processes, one story)
The record carries all three join keys: the surface request's `x-boxel-logging-correlation-id` rides the job args to the worker; the worker forwards `jobId.reservationId` to the prerender server as the existing `x-boxel-job-id` header (the screenshot path previously didn't send it); and the prerender HTTP request id comes back on `response.meta`. The prerender stage detail travels in `meta.diagnostics` — the one timing surface that survives the remote prerenderer's wire boundary (the `meta.timing`/`meta.pool` envelope is dropped there).
Grafana
New `boxel-screenshot-perf` dashboard ("Screenshot Capture Performance", Boxel Status folder), in the shape of the client-performance board: request rate and outcomes, request p50/p95/p99, capture latency by stage (p95 per stage), queue-wait vs render split, warm/cold page-acquire split, persist outcomes, realm/surface slices, and a slowest-captures table.
Test plan
🤖 Generated with Claude Code