From c826d2b614d8d58f70eb91a2d53059e2585fee92 Mon Sep 17 00:00:00 2001
From: ciregenz <ciregenz@berkeley.edu>
Date: Fri, 31 Jul 2026 18:43:20 -0700
Subject: [PATCH] [eric] browser: a slow command reports whether the wait was
 before its handler or inside it

---
 backend/apps/agents/browser/browser_agent.py | 15 ++++++++++++--
 frontend/src/shared/browserCommandHandler.ts | 21 +++++++++++++++++---
 2 files changed, 31 insertions(+), 5 deletions(-)

diff --git a/backend/apps/agents/browser/browser_agent.py b/backend/apps/agents/browser/browser_agent.py
index e6e01968..f95ef919 100644
--- a/backend/apps/agents/browser/browser_agent.py
+++ b/backend/apps/agents/browser/browser_agent.py
@@ -319,8 +319,10 @@ async def execute_browser_tool(
 ) -> dict:
     """Execute a browser tool via ws_manager directly (no MCP/HTTP round-trip)."""
     p_t0 = time.time()
+    p_res: dict = {}
     try:
-        return await p_execute_browser_tool(tool_name, tool_input, browser_id, tab_id)
+        p_res = await p_execute_browser_tool(tool_name, tool_input, browser_id, tab_id)
+        return p_res
     finally:
         p_ms = (time.time() - p_t0) * 1000
         try:
@@ -331,7 +333,16 @@ async def execute_browser_tool(
         # was slow. One line per genuinely slow command costs nothing on a healthy run and turns
         # "15s of tools" into a name and a duration.
         if p_ms >= P_SLOW_BROWSER_MS:
-            logger.info(f"[browser-slow] {tool_name} took {int(p_ms)}ms -> {browser_id}")
+            # The frontend reports how much of that went BEFORE its handler even started (waiting on
+            # a webview that says it is still loading). From here the two are indistinguishable, and
+            # they have completely different fixes, so make the split explicit.
+            p_split = ""
+            if isinstance(p_res, dict):
+                if p_res.get("gate_ms") is not None:
+                    p_split += f" gate={int(p_res['gate_ms'])}ms"
+                if p_res.get("stages"):
+                    p_split += f" stages=[{p_res['stages']}]"
+            logger.info(f"[browser-slow] {tool_name} took {int(p_ms)}ms{p_split} -> {browser_id}")
 
 
 async def p_execute_browser_tool(
diff --git a/frontend/src/shared/browserCommandHandler.ts b/frontend/src/shared/browserCommandHandler.ts
index 36bf5cd3..58cc95d1 100644
--- a/frontend/src/shared/browserCommandHandler.ts
+++ b/frontend/src/shared/browserCommandHandler.ts
@@ -141,21 +141,29 @@ async function removeAnnotations(wv: BrowserWebview): Promise<void> {
 }
 
 async function handleScreenshot(wv: BrowserWebview, params?: Record<string, any>): Promise<Record<string, any>> {
+  const p_t0 = Date.now();
+  const p_mark = (stage: string): void => { p_stages.push(`${stage}:${Date.now() - p_t0}`); };
+  const p_stages: string[] = [];
   if (params?.annotate !== false) {
     let drawn = 0;
     try {
       drawn = await annotateElements(wv);
+      p_mark('annotated');
       if (drawn > 0) {
         const shot = await captureRetry(wv);
+        p_mark('captured');
         if (shot.image) shot.text = `Screenshot with ${drawn} numbered boxes matching your element list (pass annotate:false for a clean shot).`;
-        return shot;
+        return { ...shot, stages: p_stages.join(' ') };
       }
     } catch { /* annotation is decoration; a plain shot always beats an error */
     } finally {
       if (drawn > 0) await removeAnnotations(wv);
+      p_mark('annotations removed');
     }
   }
-  return captureRetry(wv);
+  const p_plain = await captureRetry(wv);
+  p_mark('captured');
+  return { ...p_plain, stages: p_stages.join(' ') };
 }
 
 async function captureRetry(wv: BrowserWebview): Promise<Record<string, any>> {
@@ -2113,7 +2121,12 @@ async function runBrowserCommand(
     dashboardWs.send('browser:result', { request_id, ...result });
     return;
   }
+  const p_gateT0 = Date.now();
   const wv = await awaitWebview(browser_id, tab_id || undefined, action);
+  // A command that spends seconds before its handler even starts looks identical, from the backend,
+  // to a slow handler. Splitting the two is the whole diagnosis for the 15s screenshot wedge, so
+  // say which half ate the time. Only fires when it is genuinely slow, so a healthy run stays quiet.
+  const p_gateMs = Date.now() - p_gateT0;
   if (!wv) {
     dashboardWs.send('browser:result', {
       request_id,
@@ -2224,7 +2237,9 @@ async function runBrowserCommand(
   if (completedCommands.size > _COMPLETED_CACHE_MAX) {
     completedCommands.delete(completedCommands.keys().next().value as string);
   }
-  dashboardWs.send('browser:result', { request_id, ...result });
+  // Ride the pre-handler wait back with the result: a renderer console.log never reaches the main
+  // process, and from the backend a slow GATE and a slow HANDLER look identical.
+  dashboardWs.send('browser:result', { request_id, ...result, gate_ms: p_gateMs, total_ms: Date.now() - p_gateT0 });
 }
 
 export function initBrowserCommandHandler(): () => void {