🔍 Add verbose timing logs to debug cloud mode slowness

Adds detailed timing breakdowns when VIZZLY_LOG_LEVEL=debug:
- Navigation: mode selection and duration for each story
- Task steps: viewport, navigate, hook, screenshot timing
- Screenshot: capture vs send timing breakdown
- Client SDK: HTTP call duration
- Server handlers: request received/returned timing

Enabled verbose logging in CI for Storybook E2E tests.

Author: Robdel12

.github/workflows/sdk-e2e.yml

@@ -175,12 +175,14 @@ jobs:
         run: ../../bin/vizzly.js tdd run "npm run test:e2e"
         env:
           CI: true
+          VIZZLY_LOG_LEVEL: debug
 
       - name: Run E2E tests (Cloud mode)
         working-directory: ./clients/storybook
         run: ../../bin/vizzly.js run "npm run test:e2e"
         env:
           CI: true
+          VIZZLY_LOG_LEVEL: debug
           VIZZLY_TOKEN: ${{ secrets.VIZZLY_STORYBOOK_CLIENT_TOKEN }}
           VIZZLY_COMMIT_MESSAGE: ${{ github.event.pull_request.head.commit.message || github.event.head_commit.message }}
           VIZZLY_COMMIT_SHA: ${{ github.event.pull_request.head.sha || github.event.head_commit.id }}

clients/storybook/src/navigation.js

@@ -28,11 +28,28 @@ export function generateStoryUrl(baseUrl, storyId) {
 export async function navigateToStory(tab, storyId, baseUrl, options = {}) {
   let { timeout = 30000 } = options;
   let entry = tab._poolEntry;
+  let verbose = process.env.VIZZLY_LOG_LEVEL === 'debug';
+
+  // Debug: log navigation mode
+  let navMode = !entry?.storybookInitialized
+    ? 'full-page-init'
+    : entry.currentStoryId === storyId
+      ? 'skip-same-story'
+      : 'client-side';
+
+  if (verbose) {
+    console.error(`  [nav] ${storyId}: ${navMode} (poolEntry: ${!!entry})`);
+  }
 
   // First time this tab visits Storybook: full page load
   if (!entry?.storybookInitialized) {
+    let start = Date.now();
     await fullPageNavigation(tab, storyId, baseUrl, timeout);
 
+    if (verbose) {
+      console.error(`  [nav] ${storyId}: full-page took ${Date.now() - start}ms`);
+    }
+
     if (entry) {
       entry.storybookInitialized = true;
       entry.currentStoryId = storyId;
@@ -42,20 +59,32 @@ export async function navigateToStory(tab, storyId, baseUrl, options = {}) {
 
   // Same story (maybe different viewport) - no navigation needed
   if (entry.currentStoryId === storyId) {
+    if (verbose) {
+      console.error(`  [nav] ${storyId}: skip (same story)`);
+    }
     return;
   }
 
   // Subsequent visit: use client-side navigation
   try {
+    let start = Date.now();
     await clientSideNavigation(tab, storyId, timeout);
+
+    if (verbose) {
+      console.error(`  [nav] ${storyId}: client-side took ${Date.now() - start}ms`);
+    }
     entry.currentStoryId = storyId;
   } catch (error) {
-    // Log and fallback to full navigation if client-side fails
-    console.debug?.(
-      `Client-side navigation failed for ${storyId}, falling back to full page load:`,
-      error.message
+    // Log fallback - always show since this is unexpected behavior
+    console.error(
+      `  [nav] ${storyId}: client-side failed, falling back to full-page: ${error.message}`
     );
+    let start = Date.now();
     await fullPageNavigation(tab, storyId, baseUrl, timeout);
+
+    if (verbose) {
+      console.error(`  [nav] ${storyId}: fallback full-page took ${Date.now() - start}ms`);
+    }
     entry.currentStoryId = storyId;
   }
 }

clients/storybook/src/screenshot.js

@@ -67,7 +67,19 @@ export async function captureAndSendScreenshot(
   screenshotOptions = {}
 ) {
   let name = generateScreenshotName(story, viewport);
+  let verbose = process.env.VIZZLY_LOG_LEVEL === 'debug';
+
+  let t0 = Date.now();
   let screenshot = await captureScreenshot(page, screenshotOptions);
+  let captureTime = Date.now() - t0;
 
+  let t1 = Date.now();
   await vizzlyScreenshot(name, screenshot);
+  let sendTime = Date.now() - t1;
+
+  if (verbose) {
+    console.error(
+      `    [screenshot] ${name}: capture=${captureTime}ms send=${sendTime}ms`
+    );
+  }
 }

clients/storybook/src/tasks.js

@@ -79,20 +79,39 @@ export async function processTask(tab, task, deps = {}) {
   };
 
   let { story, viewport, hook, storyId, baseUrl, screenshotOptions } = task;
+  let verbose = process.env.VIZZLY_LOG_LEVEL === 'debug';
+  let timings = {};
 
   // Set viewport (tab is reused, so always set)
+  let t0 = Date.now();
   await setViewport(tab, viewport);
+  timings.viewport = Date.now() - t0;
 
   // Navigate to the story (smart: uses client-side navigation when possible)
+  let t1 = Date.now();
   await navigateToStory(tab, storyId, baseUrl);
+  timings.navigate = Date.now() - t1;
 
   // Run interaction hook if provided
   if (hook && typeof hook === 'function') {
+    let t2 = Date.now();
     await hook(tab);
+    timings.hook = Date.now() - t2;
   }
 
   // Capture and send screenshot
+  let t3 = Date.now();
   await captureAndSendScreenshot(tab, story, viewport, screenshotOptions);
+  timings.screenshot = Date.now() - t3;
+
+  // Log timing breakdown in verbose mode
+  if (verbose) {
+    let total = timings.viewport + timings.navigate + (timings.hook || 0) + timings.screenshot;
+    let hookStr = timings.hook ? ` hook=${timings.hook}ms` : '';
+    console.error(
+      `  [timing] ${storyId}@${viewport.name}: viewport=${timings.viewport}ms nav=${timings.navigate}ms${hookStr} screenshot=${timings.screenshot}ms (total=${total}ms)`
+    );
+  }
 }
 
 /**

src/client/index.js

@@ -199,6 +199,7 @@ function createSimpleClient(serverUrl) {
         let image = isFilePath ? imageBuffer : imageBuffer.toString('base64');
         let type = isFilePath ? 'file-path' : 'base64';
 
+        let httpStart = Date.now();
         const { status, json } = await httpPost(
           `${serverUrl}/screenshot`,
           {
@@ -211,6 +212,11 @@ function createSimpleClient(serverUrl) {
           },
           DEFAULT_TIMEOUT_MS
         );
+        let httpMs = Date.now() - httpStart;
+
+        if (shouldLogClient('debug')) {
+          console.debug(`[vizzly-client] ${name} HTTP completed in ${httpMs}ms`);
+        }
 
         if (status < 200 || status >= 300) {
           // In TDD mode, if we get 422 (visual difference), don't throw

src/server/handlers/api-handler.js

@@ -56,6 +56,9 @@ export const createApiHandler = (
     properties = {},
     type
   ) => {
+    let handlerStart = Date.now();
+    output.debug('upload', `${name} received`, { buildId: buildId?.slice(0, 8) });
+
     if (vizzlyDisabled) {
       output.debug('upload', `${name} (disabled)`);
       return {
@@ -137,6 +140,7 @@ export const createApiHandler = (
       };
     }
     screenshotCount++;
+    let uploadStart = Date.now();
 
     // Fire upload in background - DON'T AWAIT!
     let uploadPromise = uploadScreenshot(
@@ -147,26 +151,34 @@ export const createApiHandler = (
       properties ?? {}
     )
       .then(result => {
+        let duration = Date.now() - uploadStart;
         if (!result.skipped) {
-          output.debug('upload', name);
+          output.debug('upload', `${name} completed`, { ms: duration });
+        } else {
+          output.debug('upload', `${name} skipped (dedup)`, { ms: duration });
         }
-        return { success: true, name, result };
+        return { success: true, name, result, duration };
       })
       .catch(uploadError => {
+        let duration = Date.now() - uploadStart;
         output.debug('upload', `${name} failed`, {
           error: uploadError.message,
+          ms: duration,
         });
         vizzlyDisabled = true;
         output.warn(
           'Vizzly disabled due to upload error - continuing tests without visual testing'
         );
-        return { success: false, name, error: uploadError };
+        return { success: false, name, error: uploadError, duration };
       });
 
     // Collect promise for later flushing
     uploadPromises.push(uploadPromise);
 
     // Return immediately - test continues without waiting!
+    let handlerMs = Date.now() - handlerStart;
+    output.debug('upload', `${name} handler returning`, { ms: handlerMs });
+
     return {
       statusCode: 200,
       body: {

src/server/handlers/tdd-handler.js

@@ -332,6 +332,9 @@ export const createTddHandler = (
     properties = {},
     type
   ) => {
+    let handlerStart = Date.now();
+    output.debug('tdd', `${name} received`);
+
     // Validate and sanitize screenshot name
     let sanitizedName;
     try {
@@ -522,6 +525,9 @@ export const createTddHandler = (
     }
 
     // Match or new baseline
+    let handlerMs = Date.now() - handlerStart;
+    output.debug('tdd', `${name} handler returning`, { ms: handlerMs, status: comparison.status });
+
     return {
       statusCode: 200,
       body: {