Skip to content

Commit 5a4a18b

Browse files
richiemcilroyrichiemcilroy
committed
Add performance logging and playback optimizations
1 parent e62ccca commit 5a4a18b

File tree

15 files changed

+2046
-751
lines changed

15 files changed

+2046
-751
lines changed

‎apps/desktop/src-tauri/src/frame_ws.rs‎

Lines changed: 22 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -7,11 +7,7 @@ fn compress_frame_data(mut data: Vec<u8>, stride: u32, height: u32, width: u32)
77
data.extend_from_slice(&height.to_le_bytes());
88
data.extend_from_slice(&width.to_le_bytes());
99

10-
let data_len = data.len();
11-
let mut result = Vec::with_capacity(data_len + 4);
12-
result.extend_from_slice(&(data_len as u32).to_le_bytes());
13-
result.extend_from_slice(&data);
14-
result
10+
lz4_flex::compress_prepend_size(&data)
1511
}
1612

1713
#[derive(Clone)]
@@ -115,34 +111,43 @@ pub async fn create_watch_frame_ws(
115111

116112
let send_start = Instant::now();
117113
let original_size = frame.data.len();
118-
let compress_start = Instant::now();
119114
let packed = compress_frame_data(frame.data, frame.stride, frame.height, frame.width);
120-
let compress_time = compress_start.elapsed();
121115
let compressed_size = packed.len();
122116

123-
let ws_send_start = Instant::now();
124117
if let Err(e) = socket.send(Message::Binary(packed)).await {
125118
tracing::error!("Failed to send frame to socket: {:?}", e);
126119
break;
127120
}
128-
let ws_send_time = ws_send_start.elapsed();
129121
let send_time = send_start.elapsed();
130122

131-
// #region agent log
132-
use std::io::Write;
133-
if let Ok(mut f) = std::fs::OpenOptions::new().create(true).append(true).open("/Users/macbookuser/Documents/GitHub/cap/.cursor/debug.log") {
134-
let _ = writeln!(f, r#"{{"hypothesisId":"D","location":"frame_ws.rs:ws_send","message":"WebSocket frame sent","data":{{"frame_latency_us":{},"compress_time_us":{},"ws_send_time_us":{},"total_send_time_us":{},"original_bytes":{},"compressed_bytes":{}}},"timestamp":{}}}"#,
135-
latency_us, compress_time.as_micros(), ws_send_time.as_micros(), send_time.as_micros(), original_size, compressed_size, std::time::SystemTime::now().duration_since(std::time::UNIX_EPOCH).unwrap().as_millis());
136-
}
137-
// #endregion
138-
139123
tracing::debug!(
140124
frame_latency_us = latency_us,
141125
send_time_us = send_time.as_micros() as u64,
142126
original_size_bytes = original_size,
143127
compressed_size_bytes = compressed_size,
144128
"[PERF:WS_WATCH] frame sent (compressed)"
145129
);
130+
131+
// #region agent log
132+
use std::io::Write;
133+
if let Ok(mut file) = std::fs::OpenOptions::new().create(true).append(true).open("/Users/macbookuser/Documents/GitHub/cap/.cursor/debug.log") {
134+
let log_entry = serde_json::json!({
135+
"location": "frame_ws.rs:ws_send",
136+
"message": "websocket frame sent",
137+
"data": {
138+
"frame_latency_us": latency_us,
139+
"send_time_us": send_time.as_micros() as u64,
140+
"original_size_bytes": original_size,
141+
"compressed_size_bytes": compressed_size,
142+
"compression_ratio_pct": format!("{:.1}", (compressed_size as f64 / original_size as f64) * 100.0)
143+
},
144+
"timestamp": std::time::SystemTime::now().duration_since(std::time::UNIX_EPOCH).unwrap().as_millis() as u64,
145+
"sessionId": "debug-session",
146+
"hypothesisId": "A"
147+
});
148+
writeln!(file, "{}", log_entry).ok();
149+
}
150+
// #endregion
146151
}
147152
}
148153
}
@@ -246,27 +251,15 @@ pub async fn create_frame_ws(frame_tx: broadcast::Sender<WSFrame>) -> (u16, Canc
246251

247252
let send_start = Instant::now();
248253
let original_size = frame.data.len();
249-
let compress_start = Instant::now();
250254
let packed = compress_frame_data(frame.data, frame.stride, frame.height, frame.width);
251-
let compress_time = compress_start.elapsed();
252255
let compressed_size = packed.len();
253256

254-
let ws_send_start = Instant::now();
255257
if let Err(e) = socket.send(Message::Binary(packed)).await {
256258
tracing::error!("Failed to send frame to socket: {:?}", e);
257259
break;
258260
}
259-
let ws_send_time = ws_send_start.elapsed();
260261
let send_time = send_start.elapsed();
261262

262-
// #region agent log
263-
use std::io::Write;
264-
if let Ok(mut f) = std::fs::OpenOptions::new().create(true).append(true).open("/Users/macbookuser/Documents/GitHub/cap/.cursor/debug.log") {
265-
let _ = writeln!(f, r#"{{"hypothesisId":"WS_BROADCAST","location":"frame_ws.rs:broadcast_send","message":"WebSocket broadcast frame sent","data":{{"frame_latency_us":{},"compress_time_us":{},"ws_send_time_us":{},"total_send_time_us":{},"width":{},"height":{}}},"timestamp":{}}}"#,
266-
latency_us, compress_time.as_micros(), ws_send_time.as_micros(), send_time.as_micros(), frame.width, frame.height, std::time::SystemTime::now().duration_since(std::time::UNIX_EPOCH).unwrap().as_millis());
267-
}
268-
// #endregion
269-
270263
tracing::debug!(
271264
frame_latency_us = latency_us,
272265
send_time_us = send_time.as_micros() as u64,

‎apps/desktop/src/routes/editor/context.ts‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -47,7 +47,7 @@ export type CurrentDialog =
4747

4848
export type DialogState = { open: false } | ({ open: boolean } & CurrentDialog);
4949

50-
export const FPS = 60;
50+
export const FPS = 30;
5151

5252
export const OUTPUT_SIZE = {
5353
x: 1920,

‎apps/desktop/src/utils/socket.ts‎

Lines changed: 29 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -176,6 +176,35 @@ export function createImageDataWS(
176176
console.log(
177177
`[PERF:FRONTEND_WS] periodic - frames: ${metrics.framesReceived}, compressed: ${compressedSize} bytes (${compressionRatio}%), decompressed: ${decompressed.length} bytes, avg decompress: ${avgDecompressTime.toFixed(2)}ms, avg parse: ${avgParseTime.toFixed(2)}ms, avg imageData: ${avgImageDataTime.toFixed(2)}ms, dimensions: ${width}x${height}`,
178178
);
179+
// #region agent log
180+
fetch(
181+
"http://127.0.0.1:7242/ingest/966647b7-72f6-4ab7-b76e-6b773ac020d7",
182+
{
183+
method: "POST",
184+
headers: { "Content-Type": "application/json" },
185+
body: JSON.stringify({
186+
location: "socket.ts:ws_metrics",
187+
message: "frontend WS metrics",
188+
data: {
189+
framesReceived: metrics.framesReceived,
190+
avgDecompressMs: avgDecompressTime.toFixed(2),
191+
avgParseMs: avgParseTime.toFixed(2),
192+
avgImageDataMs: avgImageDataTime.toFixed(2),
193+
maxDecompressMs: metrics.maxDecompressTimeMs.toFixed(2),
194+
maxParseMs: metrics.maxParseTimeMs.toFixed(2),
195+
compressedBytes: compressedSize,
196+
decompressedBytes: decompressed.length,
197+
compressionRatio,
198+
width,
199+
height,
200+
},
201+
timestamp: Date.now(),
202+
sessionId: "debug-session",
203+
hypothesisId: "B",
204+
}),
205+
},
206+
).catch(() => {});
207+
// #endregion
179208
metrics.lastLogTime = now;
180209
}
181210

‎crates/editor/src/editor.rs‎

Lines changed: 25 additions & 62 deletions
Original file line numberDiff line numberDiff line change
@@ -151,6 +151,7 @@ impl Renderer {
151151
};
152152

153153
let mut dropped_in_batch = 0u32;
154+
let queue_drain_start = Instant::now();
154155
while let Ok(msg) = self.rx.try_recv() {
155156
match msg {
156157
RendererMessage::RenderFrame {
@@ -176,6 +177,9 @@ impl Renderer {
176177
return;
177178
}
178179
}
180+
if queue_drain_start.elapsed().as_millis() > 5 {
181+
break;
182+
}
179183
}
180184

181185
if dropped_in_batch > 0 {
@@ -185,48 +189,8 @@ impl Renderer {
185189
total_dropped = frames_dropped,
186190
"[PERF:EDITOR_RENDER] dropped frames to catch up"
187191
);
188-
189-
// #region agent log
190-
use std::io::Write;
191-
if let Ok(mut f) = std::fs::OpenOptions::new()
192-
.create(true)
193-
.append(true)
194-
.open("/Users/macbookuser/Documents/GitHub/cap/.cursor/debug.log")
195-
{
196-
let _ = writeln!(
197-
f,
198-
r#"{{"hypothesisId":"A","location":"editor.rs:frames_dropped","message":"Renderer dropped frames due to backpressure","data":{{"dropped_in_batch":{},"total_dropped":{},"rendering_frame":{}}},"timestamp":{}}}"#,
199-
dropped_in_batch,
200-
frames_dropped,
201-
current.frame_number,
202-
std::time::SystemTime::now()
203-
.duration_since(std::time::UNIX_EPOCH)
204-
.unwrap()
205-
.as_millis()
206-
);
207-
}
208-
// #endregion
209192
}
210193

211-
// #region agent log
212-
use std::io::Write;
213-
if let Ok(mut f) = std::fs::OpenOptions::new()
214-
.create(true)
215-
.append(true)
216-
.open("/Users/macbookuser/Documents/GitHub/cap/.cursor/debug.log")
217-
{
218-
let _ = writeln!(
219-
f,
220-
r#"{{"hypothesisId":"A","location":"editor.rs:render_start","message":"Starting GPU render","data":{{"frame_number":{}}},"timestamp":{}}}"#,
221-
current.frame_number,
222-
std::time::SystemTime::now()
223-
.duration_since(std::time::UNIX_EPOCH)
224-
.unwrap()
225-
.as_millis()
226-
);
227-
}
228-
// #endregion
229-
230194
let render_start = Instant::now();
231195
let frame = frame_renderer
232196
.render(
@@ -239,25 +203,6 @@ impl Renderer {
239203
.unwrap();
240204
let render_time = render_start.elapsed();
241205

242-
// #region agent log
243-
if let Ok(mut f) = std::fs::OpenOptions::new()
244-
.create(true)
245-
.append(true)
246-
.open("/Users/macbookuser/Documents/GitHub/cap/.cursor/debug.log")
247-
{
248-
let _ = writeln!(
249-
f,
250-
r#"{{"hypothesisId":"A","location":"editor.rs:render_complete","message":"GPU render complete","data":{{"frame_number":{},"render_time_us":{}}},"timestamp":{}}}"#,
251-
current.frame_number,
252-
render_time.as_micros(),
253-
std::time::SystemTime::now()
254-
.duration_since(std::time::UNIX_EPOCH)
255-
.unwrap()
256-
.as_millis()
257-
);
258-
}
259-
// #endregion
260-
261206
let callback_start = Instant::now();
262207
(self.frame_cb)(frame);
263208
let callback_time = callback_start.elapsed();
@@ -277,6 +222,26 @@ impl Renderer {
277222
"[PERF:EDITOR_RENDER] frame rendered"
278223
);
279224

225+
// #region agent log
226+
use std::io::Write;
227+
if let Ok(mut file) = std::fs::OpenOptions::new()
228+
.create(true)
229+
.append(true)
230+
.open("/Users/macbookuser/Documents/GitHub/cap/.cursor/debug.log")
231+
{
232+
let ts = std::time::SystemTime::now()
233+
.duration_since(std::time::UNIX_EPOCH)
234+
.unwrap()
235+
.as_millis() as u64;
236+
writeln!(
237+
file,
238+
r#"{{"location":"editor.rs:frame_rendered","message":"editor render timing","data":{{"frame_number":{},"render_time_us":{},"callback_time_us":{}}},"timestamp":{},"sessionId":"debug-session","hypothesisId":"C"}}"#,
239+
current.frame_number, render_time_us, callback_time_us, ts
240+
)
241+
.ok();
242+
}
243+
// #endregion
244+
280245
if last_metrics_log.elapsed().as_secs() >= 2 && frames_rendered > 0 {
281246
let avg_render_time = total_render_time_us / frames_rendered;
282247
let avg_callback_time = total_callback_time_us / frames_rendered;
@@ -309,7 +274,7 @@ impl RendererHandle {
309274
cursor: Arc<CursorEvents>,
310275
frame_number: u32,
311276
) {
312-
let (finished_tx, finished_rx) = oneshot::channel();
277+
let (finished_tx, _finished_rx) = oneshot::channel();
313278

314279
self.send(RendererMessage::RenderFrame {
315280
segment_frames,
@@ -319,8 +284,6 @@ impl RendererHandle {
319284
frame_number,
320285
})
321286
.await;
322-
323-
let _ = finished_rx.await;
324287
}
325288

326289
pub async fn stop(&self) {

0 commit comments

Comments
 (0)