fix: rework performance parsing & error handling (#75)

This PR tidies up the code around performance parsing and what we
respond with from our tools. It introduces the ability to have no
Insights from a trace (relatively rare, but can happen), and also adds
more information to the output in the event that something went wrong.

Previously we just logged errors, but if we respond with them here that
will also help users report issues and increase the chances that we can
debug them.

Author: jackfranklin

src/tools/performance.ts

@@ -11,6 +11,7 @@ import {
   getTraceSummary,
   InsightName,
   parseRawTraceBuffer,
+  traceResultIsSuccess,
 } from '../trace-processing/parse.js';
 import {logger} from '../logger.js';
 import {Page} from 'puppeteer-core';
@@ -160,22 +161,26 @@ async function stopTracingAndAppendOutput(
     const traceEventsBuffer = await page.tracing.stop();
     const result = await parseRawTraceBuffer(traceEventsBuffer);
     response.appendResponseLine('The performance trace has been stopped.');
-    if (result) {
+    if (traceResultIsSuccess(result)) {
       context.storeTraceRecording(result);
-      const insightText = getTraceSummary(result);
-      if (insightText) {
-        response.appendResponseLine('Insights with performance opportunities:');
-        response.appendResponseLine(insightText);
-      } else {
-        response.appendResponseLine(
-          'No insights have been found. The performance looks good!',
-        );
-      }
+      response.appendResponseLine(
+        'Here is a high level summary of the trace and the Insights that were found:',
+      );
+      const traceSummaryText = getTraceSummary(result);
+      response.appendResponseLine(traceSummaryText);
+    } else {
+      response.appendResponseLine(
+        'There was an unexpected error parsing the trace:',
+      );
+      response.appendResponseLine(result.error);
     }
   } catch (e) {
-    logger(
-      `Error stopping performance trace: ${e instanceof Error ? e.message : JSON.stringify(e)}`,
+    const errorText = e instanceof Error ? e.message : JSON.stringify(e);
+    logger(`Error stopping performance trace: ${errorText}`);
+    response.appendResponseLine(
+      'An error occured generating the response for this trace:',
     );
+    response.appendResponseLine(errorText);
   } finally {
     context.setIsRunningPerformanceTrace(false);
   }

src/trace-processing/parse.ts

@@ -14,19 +14,33 @@ const engine = TraceEngine.TraceModel.Model.createWithAllHandlers();
 
 export interface TraceResult {
   parsedTrace: TraceEngine.TraceModel.ParsedTrace;
-  insights: TraceEngine.Insights.Types.TraceInsightSets;
+  insights: TraceEngine.Insights.Types.TraceInsightSets | null;
+}
+
+export function traceResultIsSuccess(
+  x: TraceResult | TraceParseError,
+): x is TraceResult {
+  return 'parsedTrace' in x;
+}
+
+export interface TraceParseError {
+  error: string;
 }
 
 export async function parseRawTraceBuffer(
   buffer: Uint8Array<ArrayBufferLike> | undefined,
-): Promise<TraceResult | null> {
+): Promise<TraceResult | TraceParseError> {
   engine.resetProcessor();
   if (!buffer) {
-    return null;
+    return {
+      error: 'No buffer was provided.',
+    };
   }
   const asString = new TextDecoder().decode(buffer);
   if (!asString) {
-    return null;
+    return {
+      error: 'Decoding the trace buffer returned an empty string.',
+    };
   }
   try {
     const data = JSON.parse(asString) as
@@ -39,25 +53,23 @@ export async function parseRawTraceBuffer(
     await engine.parse(events);
     const parsedTrace = engine.parsedTrace();
     if (!parsedTrace) {
-      return null;
+      return {
+        error: 'No parsed trace was returned from the trace engine.',
+      };
     }
 
-    const insights = parsedTrace?.insights;
-    if (!insights) {
-      return null;
-    }
+    const insights = parsedTrace?.insights ?? null;
 
     return {
       parsedTrace,
       insights,
     };
   } catch (e) {
-    if (e instanceof Error) {
-      logger(`Error parsing trace: ${e.message}`);
-    } else {
-      logger(`Error parsing trace: ${JSON.stringify(e)}`);
-    }
-    return null;
+    const errorText = e instanceof Error ? e.message : JSON.stringify(e);
+    logger(`Unexpeced error parsing trace: ${errorText}`);
+    return {
+      error: errorText,
+    };
   }
 }
 
@@ -76,6 +88,12 @@ export function getInsightOutput(
   result: TraceResult,
   insightName: InsightName,
 ): InsightOutput {
+  if (!result.insights) {
+    return {
+      error: 'No Performance insights are available for this trace.',
+    };
+  }
+
   // Currently, we do not support inspecting traces with multiple navigations. We either:
   // 1. Find Insights from the first navigation (common case: user records a trace with a page reload to test load performance)
   // 2. Fall back to finding Insights not associated with a navigation (common case: user tests an interaction without a page load).

tests/tools/performance.test.js.snapshot

@@ -40,3 +40,56 @@ We can break this time down into the 4 phases that combine to make the LCP time:
 - https://web.dev/articles/lcp
 - https://web.dev/articles/optimize-lcp
 `;
+
+exports[`performance > performance_stop_trace > returns an error message if parsing the trace buffer fails 1`] = `
+The performance trace has been stopped.
+There was an unexpected error parsing the trace:
+No buffer was provided.
+`;
+
+exports[`performance > performance_stop_trace > returns the high level summary of the performance trace 1`] = `
+The performance trace has been stopped.
+Here is a high level summary of the trace and the Insights that were found:
+URL: https://web.dev/
+Bounds: {min: 122410994891, max: 122416385853}
+CPU throttling: none
+Network throttling: none
+Metrics (lab / observed):
+  - LCP: 129 ms, event: (eventKey: r-6063, ts: 122411126100)
+  - LCP breakdown:
+    - TTFB: 8 ms, bounds: {min: 122410996889, max: 122411004828}
+    - Load delay: 33 ms, bounds: {min: 122411004828, max: 122411037986}
+    - Load duration: 15 ms, bounds: {min: 122411037986, max: 122411052690}
+    - Render delay: 73 ms, bounds: {min: 122411052690, max: 122411126100}
+  - CLS: 0.00
+Metrics (field / real users): n/a – no data for this page in CrUX
+Available insights:
+  - insight name: LCPBreakdown
+    description: Each [subpart has specific improvement strategies](https://web.dev/articles/optimize-lcp#lcp-breakdown). Ideally, most of the LCP time should be spent on loading the resources, not within delays.
+    relevant trace bounds: {min: 122410996889, max: 122411126100}
+    example question: Help me optimize my LCP score
+    example question: Which LCP phase was most problematic?
+    example question: What can I do to reduce the LCP time for this page load?
+  - insight name: LCPDiscovery
+    description: Optimize LCP by making the LCP image [discoverable](https://web.dev/articles/optimize-lcp#1_eliminate_resource_load_delay) from the HTML immediately, and [avoiding lazy-loading](https://web.dev/articles/lcp-lazy-loading)
+    relevant trace bounds: {min: 122411004828, max: 122411055039}
+    example question: Suggest fixes to reduce my LCP
+    example question: What can I do to reduce my LCP discovery time?
+    example question: Why is LCP discovery time important?
+  - insight name: RenderBlocking
+    description: Requests are blocking the page's initial render, which may delay LCP. [Deferring or inlining](https://web.dev/learn/performance/understanding-the-critical-path#render-blocking_resources) can move these network requests out of the critical path.
+    relevant trace bounds: {min: 122411037528, max: 122411053852}
+    example question: Show me the most impactful render blocking requests that I should focus on
+    example question: How can I reduce the number of render blocking requests?
+  - insight name: DocumentLatency
+    description: Your first network request is the most important.  Reduce its latency by avoiding redirects, ensuring a fast server response, and enabling text compression.
+    relevant trace bounds: {min: 122410998910, max: 122411043781}
+    estimated metric savings: FCP 0 ms, LCP 0 ms
+    estimated wasted bytes: 77.1 kB
+    example question: How do I decrease the initial loading time of my page?
+    example question: Did anything slow down the request for this document?
+  - insight name: ThirdParties
+    description: 3rd party code can significantly impact load performance. [Reduce and defer loading of 3rd party code](https://web.dev/articles/optimizing-content-efficiency-loading-third-party-javascript/) to prioritize your page's content.
+    relevant trace bounds: {min: 122411037881, max: 122416229595}
+    example question: Which third parties are having the largest impact on my page performance?
+`;

tests/tools/performance.test.ts

@@ -17,6 +17,7 @@ import {loadTraceAsBuffer} from '../trace-processing/fixtures/load.js';
 import {
   parseRawTraceBuffer,
   TraceResult,
+  traceResultIsSuccess,
 } from '../../src/trace-processing/parse.js';
 
 describe('performance', () => {
@@ -141,7 +142,9 @@ describe('performance', () => {
     async function parseTrace(fileName: string): Promise<TraceResult> {
       const rawData = loadTraceAsBuffer(fileName);
       const result = await parseRawTraceBuffer(rawData);
-      assert.ok(result);
+      if (!traceResultIsSuccess(result)) {
+        assert.fail(`Unexpected trace parse error: ${result.error}`);
+      }
       return result;
     }
 
@@ -238,5 +241,30 @@ describe('performance', () => {
         sinon.assert.calledOnce(stopTracingStub);
       });
     });
+
+    it('returns an error message if parsing the trace buffer fails', async t => {
+      await withBrowser(async (response, context) => {
+        context.setIsRunningPerformanceTrace(true);
+        const selectedPage = context.getSelectedPage();
+        sinon
+          .stub(selectedPage.tracing, 'stop')
+          .returns(Promise.resolve(undefined));
+        await stopTrace.handler({params: {}}, response, context);
+        t.assert.snapshot(response.responseLines.join('\n'));
+      });
+    });
+
+    it('returns the high level summary of the performance trace', async t => {
+      const rawData = loadTraceAsBuffer('web-dev-with-commit.json.gz');
+      await withBrowser(async (response, context) => {
+        context.setIsRunningPerformanceTrace(true);
+        const selectedPage = context.getSelectedPage();
+        sinon.stub(selectedPage.tracing, 'stop').callsFake(async () => {
+          return rawData;
+        });
+        await stopTrace.handler({params: {}}, response, context);
+        t.assert.snapshot(response.responseLines.join('\n'));
+      });
+    });
   });
 });

tests/trace-processing/parse.test.ts

@@ -15,17 +15,30 @@ describe('Trace parsing', async () => {
   it('can parse a Uint8Array from Tracing.stop())', async () => {
     const rawData = loadTraceAsBuffer('basic-trace.json.gz');
     const result = await parseRawTraceBuffer(rawData);
+    if ('error' in result) {
+      assert.fail(`Unexpected parse failure: ${result.error}`);
+    }
     assert.ok(result?.parsedTrace);
     assert.ok(result?.insights);
   });
 
   it('can format results of a trace', async t => {
     const rawData = loadTraceAsBuffer('web-dev-with-commit.json.gz');
     const result = await parseRawTraceBuffer(rawData);
+    if ('error' in result) {
+      assert.fail(`Unexpected parse failure: ${result.error}`);
+    }
     assert.ok(result?.parsedTrace);
     assert.ok(result?.insights);
 
     const output = getTraceSummary(result);
     t.assert.snapshot(output);
   });
+
+  it('will return a message if there is an error', async () => {
+    const result = await parseRawTraceBuffer(undefined);
+    assert.deepEqual(result, {
+      error: 'No buffer was provided.',
+    });
+  });
 });